diff --git a/targeting/contextagent/handler.go b/targeting/contextagent/handler.go index 688fda21..cdf0bd77 100644 --- a/targeting/contextagent/handler.go +++ b/targeting/contextagent/handler.go @@ -93,7 +93,8 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } if err := tmproto.ValidateContextRequest(&req); err != nil { - writeError(w, tmproto.SafeRequestIDForEcho(req.RequestID), tmproto.ErrorCodeInvalidRequest, err.Error(), http.StatusBadRequest) + h.logValidationFailure(r, req.RequestID, err) + writeError(w, tmproto.SafeRequestIDForEcho(req.RequestID), tmproto.ErrorCodeInvalidRequest, "invalid request", http.StatusBadRequest) return } @@ -154,6 +155,26 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } } +// logValidationFailure logs a rejected request's validation error +// server-side with request context, mirroring identityagent's +// logValidationFailure. The HTTP response only ever gets the generic +// "invalid request" message (see ServeHTTP) — validator error text +// (which can include request-shaped detail like field names and +// lengths) must not cross the response boundary per AGENTS.md's +// generic-error-message invariant. request_id is only logged when it +// passes SafeRequestIDForEcho; an id that fails that check is elided +// and request_id_valid=false is logged instead, so a control-byte or +// oversized request_id doesn't get written verbatim into logs either. +func (h *handler) logValidationFailure(r *http.Request, requestID string, err error) { + attrs := []any{"method", r.Method, "path", r.URL.Path, "error", err} + if safeID := tmproto.SafeRequestIDForEcho(requestID); safeID != "" { + attrs = append(attrs, "request_id", safeID) + } else if requestID != "" { + attrs = append(attrs, "request_id_valid", false) + } + h.logger.Warn("invalid context-match request", attrs...) +} + // writeError writes a TMP error response. Headers must be set before // WriteHeader because anything after WriteHeader is silently dropped // by net/http. diff --git a/targeting/contextagent/handler_test.go b/targeting/contextagent/handler_test.go new file mode 100644 index 00000000..c00ec482 --- /dev/null +++ b/targeting/contextagent/handler_test.go @@ -0,0 +1,105 @@ +package contextagent + +import ( + "bytes" + "encoding/json" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "github.com/adcontextprotocol/adcp-go/tmproto" +) + +// TestContextHandlerValidationErrorIsGenericAndLogged pins the +// generic-error-message invariant from AGENTS.md ("Never echo err.Error() +// in HTTP responses") for the context-match validation path. The same +// pattern was fixed for router.HandleContextMatch and identityagent's +// ServeHTTP in the validator-error sweep (adcontextprotocol/adcp-go#190, +// #201; landed in PR #210) but that sweep did not touch this handler, +// which kept echoing tmproto.ValidateContextRequest's err.Error() text — +// e.g. "property_id contains invalid characters" — straight into the HTTP +// response body. +func TestContextHandlerValidationErrorIsGenericAndLogged(t *testing.T) { + var logs bytes.Buffer + h := NewHandler(HandlerConfig{ + RequestTimeout: time.Second, + RequestBodyLimit: 64 * 1024, + ResponseTTL: time.Minute, + SupportedADCPMajorVersions: []int{3}, + Logger: slog.New(slog.NewJSONHandler(&logs, nil)), + }) + + body := `{ + "type": "context_match_request", + "request_id": "ctx-invalid", + "property_rid": "rid-1", + "property_id": "bad:property", + "property_type": "website", + "placement_id": "sidebar", + "seller_agent_url": "https://seller.example.com/agent" + }` + req := httptest.NewRequest(http.MethodPost, "/context", strings.NewReader(body)) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + + require.Equal(t, http.StatusBadRequest, w.Code, w.Body.String()) + var resp tmproto.ErrorResponse + require.NoError(t, json.NewDecoder(w.Body).Decode(&resp)) + assert.Equal(t, tmproto.ErrorCodeInvalidRequest, resp.Code) + assert.Equal(t, "ctx-invalid", resp.RequestID) + assert.Equal(t, "invalid request", resp.Message) + assert.NotContains(t, w.Body.String(), "property_id") + + logText := logs.String() + assert.Contains(t, logText, "invalid context-match request") + assert.Contains(t, logText, `"method":"POST"`) + assert.Contains(t, logText, `"path":"/context"`) + assert.Contains(t, logText, "ctx-invalid") + assert.Contains(t, logText, "property_id contains invalid characters") +} + +// TestContextHandlerInvalidRequestIDIsNotEchoed pins the companion +// invariant: a request_id that itself fails validateSafeID (so it is +// unsafe to echo — see tmproto.SafeRequestIDForEcho) must not appear in +// the HTTP response body, and is elided from the structured log too. +func TestContextHandlerInvalidRequestIDIsNotEchoed(t *testing.T) { + var logs bytes.Buffer + h := NewHandler(HandlerConfig{ + RequestTimeout: time.Second, + RequestBodyLimit: 64 * 1024, + ResponseTTL: time.Minute, + SupportedADCPMajorVersions: []int{3}, + Logger: slog.New(slog.NewJSONHandler(&logs, nil)), + }) + + body := `{ + "type": "context_match_request", + "request_id": "bad/id", + "property_rid": "rid-1", + "property_id": "pub-1", + "property_type": "website", + "placement_id": "sidebar", + "seller_agent_url": "https://seller.example.com/agent" + }` + req := httptest.NewRequest(http.MethodPost, "/context", strings.NewReader(body)) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + + require.Equal(t, http.StatusBadRequest, w.Code, w.Body.String()) + var resp tmproto.ErrorResponse + require.NoError(t, json.NewDecoder(w.Body).Decode(&resp)) + assert.Empty(t, resp.RequestID) + assert.Equal(t, "invalid request", resp.Message) + assert.NotContains(t, w.Body.String(), "bad/id") + + logText := logs.String() + assert.Contains(t, logText, "invalid context-match request") + assert.Contains(t, logText, `"request_id_valid":false`) + assert.NotContains(t, logText, "bad/id") +}