diff --git a/runtime/client_http_request_test.go b/runtime/client_http_request_test.go index ae7be70ab..a074d7ba8 100644 --- a/runtime/client_http_request_test.go +++ b/runtime/client_http_request_test.go @@ -240,7 +240,44 @@ func TestMakingClientCallWithRespHeaders(t *testing.T) { assert.Equal(t, "Example-Value", headers["Example-Header"]) logs := bgateway.AllLogs() - assert.Len(t, logs["Finished an outgoing client HTTP request"], 1) + logMsgs := logs["Finished an outgoing client HTTP request"] + assert.Len(t, logMsgs, 1) + logMsg := logMsgs[0] + + dynamicHeaders := []string{ + "url", + "timestamp-finished", + "Request-Header-Uber-Trace-Id", + "Response-Header-Content-Length", + "timestamp-started", + "Response-Header-Date", + "ts", + "hostname", + "pid", + } + for _, dynamicValue := range dynamicHeaders { + assert.Contains(t, logMsg, dynamicValue) + delete(logMsg, dynamicValue) + } + + expectedValues := map[string]interface{}{ + "msg": "Finished an outgoing client HTTP request", + "env": "production", + "clientID": "bar", + "Response-Header-Example-Header": "Example-Value", + "statusCode": float64(200), + "Request-Header-Content-Type": "application/json", + "Response-Header-Content-Type": "text/plain; charset=utf-8", + "level": "info", + "methodName": "Normal", + "method": "POST", + "Request-Header-X-Client-Id": "bar", + "zone": "unknown", + "service": "example-gateway", + } + for actualKey, actualValue := range logMsg { + assert.Equal(t, expectedValues[actualKey], actualValue, "unexpected header %q", actualKey) + } } func TestMakingClientCallWithThriftException(t *testing.T) { diff --git a/runtime/server_http_request_test.go b/runtime/server_http_request_test.go index c33352d00..c140ad42c 100644 --- a/runtime/server_http_request_test.go +++ b/runtime/server_http_request_test.go @@ -1370,3 +1370,81 @@ func TestSpanCreated(t *testing.T) { } assert.Equal(t, "200 OK", resp.Status) } + +func TestIncomingHTTPRequestServerLog(t *testing.T) { + gateway, err := benchGateway.CreateGateway( + defaultTestConfig, + defaultTestOptions, + exampleGateway.CreateGateway, + ) + + if !assert.NoError(t, err) { + return + } + defer gateway.Close() + + bgateway := gateway.(*benchGateway.BenchGateway) + bgateway.ActualGateway.HTTPRouter.Register( + "GET", "/foo", zanzibar.NewRouterEndpoint( + bgateway.ActualGateway.Logger, + bgateway.ActualGateway.AllHostScope, + bgateway.ActualGateway.Tracer, + "foo", "foo", + func( + ctx context.Context, + req *zanzibar.ServerHTTPRequest, + res *zanzibar.ServerHTTPResponse, + ) { + res.WriteJSONBytes(200, nil, []byte(`{"ok":true}`)) + }, + ), + ) + + _, err = gateway.MakeRequest("GET", "/foo?bar=bar", nil, nil) + assert.NoError(t, err) + + allLogs := bgateway.AllLogs() + assert.Equal(t, 1, len(allLogs["Finished an incoming server HTTP request"])) + + tags := allLogs["Finished an incoming server HTTP request"][0] + dynamicHeaders := []string{ + "remoteAddr", + "timestamp-started", + "ts", + "hostname", + "host", + "pid", + "timestamp-finished", + } + for _, dynamicValue := range dynamicHeaders { + assert.Contains(t, tags, dynamicValue) + delete(tags, dynamicValue) + } + + expectedValues := map[string]interface{}{ + "msg": "Finished an incoming server HTTP request", + "env": "production", + "clientID": "baz", + "level": "info", + "serviceName": "bazService", + "serviceMethod": "SimpleService::call", + "methodName": "Call", + "zone": "unknown", + "service": "example-gateway", + "Request-Header-Foo-Bar": "Baz", + "Request-Header-x-uuid": "uuid", + "Request-Header-x-token": "token", + "Response-Header-some-res-header": "something", + "method": "GET", + "pathname": "/foo?bar=bar", + "statusCode": float64(200), + "Response-Header-Content-Type": "application/json", + "Request-Header-Accept-Encoding": "gzip", + "Request-Header-User-Agent": "Go-http-client/1.1", + "handlerID": "foo", + "endpointID": "foo", + } + for actualKey, actualValue := range tags { + assert.Equal(t, expectedValues[actualKey], actualValue, "unexpected header %q", actualKey) + } +} diff --git a/test/endpoints/tchannel/baz/baz_simpleservice_method_call_test.go b/test/endpoints/tchannel/baz/baz_simpleservice_method_call_test.go index 6ba438dc5..65673b9b3 100644 --- a/test/endpoints/tchannel/baz/baz_simpleservice_method_call_test.go +++ b/test/endpoints/tchannel/baz/baz_simpleservice_method_call_test.go @@ -105,32 +105,70 @@ func TestCallTChannelSuccessfulRequestOKResponse(t *testing.T) { assert.Equal(t, 1, len(allLogs["Finished an incoming server TChannel request"])) tags := allLogs["Finished an incoming server TChannel request"][0] - assert.Equal(t, "info", tags["level"]) - assert.Equal(t, "Finished an incoming server TChannel request", tags["msg"]) - assert.Equal(t, "bazTChannel", tags["endpointID"]) - assert.Equal(t, "call", tags["handlerID"]) - assert.Equal(t, "SimpleService::Call", tags["method"]) - assert.Equal(t, "token", tags["Request-Header-x-token"]) - assert.Equal(t, "uuid", tags["Request-Header-x-uuid"]) - assert.Equal(t, "something", tags["Response-Header-some-res-header"]) - assert.Equal(t, "test-gateway", tags["calling-service"]) - assert.Contains(t, tags["remoteAddr"], getLocalAddr(t)) - assert.NotNil(t, tags["timestamp-started"]) - assert.NotNil(t, tags["timestamp-finished"]) + dynamicHeaders := []string{ + "timestamp-started", + "timestamp-finished", + "remoteAddr", + "ts", + "hostname", + "pid", + } + for _, dynamicValue := range dynamicHeaders { + assert.Contains(t, tags, dynamicValue) + delete(tags, dynamicValue) + } + + expectedValues := map[string]interface{}{ + "level": "info", + "env": "test", + "service": "example-gateway", + "msg": "Finished an incoming server TChannel request", + "endpointID": "bazTChannel", + "handlerID": "call", + "method": "SimpleService::Call", + "Request-Header-x-token": "token", + "Request-Header-x-uuid": "uuid", + "Response-Header-some-res-header": "something", + "calling-service": "test-gateway", + "zone": "unknown", + } + for actualKey, actualValue := range tags { + assert.Equal(t, expectedValues[actualKey], actualValue, "unexpected header %q", actualKey) + } tags = allLogs["Finished an outgoing client TChannel request"][0] - assert.Equal(t, "info", tags["level"]) - assert.Equal(t, "Finished an outgoing client TChannel request", tags["msg"]) - assert.Equal(t, "baz", tags["clientID"]) - assert.Equal(t, "bazService", tags["serviceName"]) - assert.Equal(t, "Call", tags["methodName"]) - assert.Equal(t, "SimpleService::call", tags["serviceMethod"]) - assert.Equal(t, "token", tags["Request-Header-x-token"]) - assert.Equal(t, "uuid", tags["Request-Header-x-uuid"]) - assert.Equal(t, "something", tags["Response-Header-some-res-header"]) - assert.Contains(t, tags["remoteAddr"], "127.0.0.1") - assert.NotNil(t, tags["timestamp-started"]) - assert.NotNil(t, tags["timestamp-finished"]) + dynamicHeaders = []string{ + "remoteAddr", + "timestamp-started", + "ts", + "hostname", + "pid", + "timestamp-finished", + "Request-Header-$tracing$uber-trace-id", + } + for _, dynamicValue := range dynamicHeaders { + assert.Contains(t, tags, dynamicValue) + delete(tags, dynamicValue) + } + + expectedValues = map[string]interface{}{ + "msg": "Finished an outgoing client TChannel request", + "env": "test", + "clientID": "baz", + "level": "info", + "serviceName": "bazService", + "serviceMethod": "SimpleService::call", + "methodName": "Call", + "zone": "unknown", + "service": "example-gateway", + "Request-Header-Foo-Bar": "Baz", + "Request-Header-x-uuid": "uuid", + "Request-Header-x-token": "token", + "Response-Header-some-res-header": "something", + } + for actualKey, actualValue := range tags { + assert.Equal(t, expectedValues[actualKey], actualValue, "unexpected header %q", actualKey) + } } func getLocalAddr(t *testing.T) string {