From 7ffd245bba2a60a3de96bb8c61aa3c59edb8a09b Mon Sep 17 00:00:00 2001 From: Jacob Greenleaf Date: Thu, 23 Aug 2018 18:53:27 -0700 Subject: [PATCH] Add context logger --- codegen/template_bundle/template_files.go | 17 +++-- codegen/templates/http_client.tmpl | 2 +- codegen/templates/module_initializer.tmpl | 11 +-- codegen/test_data/clients/bar.gogen | 58 +++++++------- .../example-gateway/build/clients/bar/bar.go | 58 +++++++------- .../build/clients/contacts/contacts.go | 4 +- .../build/clients/corge-http/corge-http.go | 2 +- .../build/clients/google-now/google-now.go | 4 +- .../build/clients/multi/multi.go | 4 +- .../services/example-gateway/module/init.go | 11 +-- runtime/client_http_request.go | 27 +++++-- runtime/client_http_request_test.go | 2 +- runtime/client_http_response.go | 16 +--- runtime/client_http_response_test.go | 9 ++- runtime/context.go | 75 +++++++++++++++++++ runtime/context_test.go | 50 +++++++++++++ runtime/gateway.go | 12 ++- 17 files changed, 253 insertions(+), 109 deletions(-) diff --git a/codegen/template_bundle/template_files.go b/codegen/template_bundle/template_files.go index 2649dd580..ec564e711 100644 --- a/codegen/template_bundle/template_files.go +++ b/codegen/template_bundle/template_files.go @@ -1074,7 +1074,7 @@ func (c *{{$clientName}}) {{$methodName}}( } {{- end}} - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return {{if eq .ResponseType ""}}nil, err{{else}}defaultRes, nil, err{{end}} } @@ -1203,7 +1203,7 @@ func http_clientTmpl() (*asset, error) { return nil, err } - info := bindataFileInfo{name: "http_client.tmpl", size: 8008, mode: os.FileMode(420), modTime: time.Unix(1, 0)} + info := bindataFileInfo{name: "http_client.tmpl", size: 8005, mode: os.FileMode(420), modTime: time.Unix(1, 0)} a := &asset{bytes: bytes, info: info} return a, nil } @@ -1588,11 +1588,12 @@ func InitializeDependencies( tree := &DependenciesTree{} initializedDefaultDependencies := &zanzibar.DefaultDependencies{ - Logger: g.Logger, - Scope: g.AllHostScope, - Tracer: g.Tracer, - Config: g.Config, - Channel: g.Channel, + Logger: g.Logger, + ContextLogger: g.ContextLogger, + Scope: g.AllHostScope, + Tracer: g.Tracer, + Config: g.Config, + Channel: g.Channel, } {{range $idx, $className := $instance.DependencyOrder}} @@ -1624,7 +1625,7 @@ func module_initializerTmpl() (*asset, error) { return nil, err } - info := bindataFileInfo{name: "module_initializer.tmpl", size: 2237, mode: os.FileMode(420), modTime: time.Unix(1, 0)} + info := bindataFileInfo{name: "module_initializer.tmpl", size: 2307, mode: os.FileMode(420), modTime: time.Unix(1, 0)} a := &asset{bytes: bytes, info: info} return a, nil } diff --git a/codegen/templates/http_client.tmpl b/codegen/templates/http_client.tmpl index 701f53f8e..9b26d4120 100644 --- a/codegen/templates/http_client.tmpl +++ b/codegen/templates/http_client.tmpl @@ -168,7 +168,7 @@ func (c *{{$clientName}}) {{$methodName}}( } {{- end}} - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return {{if eq .ResponseType ""}}nil, err{{else}}defaultRes, nil, err{{end}} } diff --git a/codegen/templates/module_initializer.tmpl b/codegen/templates/module_initializer.tmpl index 7e5757e3f..dabd2f024 100644 --- a/codegen/templates/module_initializer.tmpl +++ b/codegen/templates/module_initializer.tmpl @@ -38,11 +38,12 @@ func InitializeDependencies( tree := &DependenciesTree{} initializedDefaultDependencies := &zanzibar.DefaultDependencies{ - Logger: g.Logger, - Scope: g.AllHostScope, - Tracer: g.Tracer, - Config: g.Config, - Channel: g.Channel, + Logger: g.Logger, + ContextLogger: g.ContextLogger, + Scope: g.AllHostScope, + Tracer: g.Tracer, + Config: g.Config, + Channel: g.Channel, } {{range $idx, $className := $instance.DependencyOrder}} diff --git a/codegen/test_data/clients/bar.gogen b/codegen/test_data/clients/bar.gogen index ca79a0219..4dd4ab42a 100644 --- a/codegen/test_data/clients/bar.gogen +++ b/codegen/test_data/clients/bar.gogen @@ -268,7 +268,7 @@ func (c *barClient) ArgNotStruct( return nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return nil, err } @@ -335,7 +335,7 @@ func (c *barClient) ArgWithHeaders( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -468,7 +468,7 @@ func (c *barClient) ArgWithManyQueryParams( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -561,7 +561,7 @@ func (c *barClient) ArgWithNestedQueryParams( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -616,7 +616,7 @@ func (c *barClient) ArgWithParams( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -668,7 +668,7 @@ func (c *barClient) ArgWithQueryHeader( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -737,7 +737,7 @@ func (c *barClient) ArgWithQueryParams( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -788,7 +788,7 @@ func (c *barClient) Hello( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -847,7 +847,7 @@ func (c *barClient) MissingArg( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -907,7 +907,7 @@ func (c *barClient) NoRequest( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -968,7 +968,7 @@ func (c *barClient) Normal( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1029,7 +1029,7 @@ func (c *barClient) NormalRecur( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1089,7 +1089,7 @@ func (c *barClient) TooManyArgs( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1163,7 +1163,7 @@ func (c *barClient) EchoBinary( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1219,7 +1219,7 @@ func (c *barClient) EchoBool( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1275,7 +1275,7 @@ func (c *barClient) EchoDouble( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1331,7 +1331,7 @@ func (c *barClient) EchoEnum( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1387,7 +1387,7 @@ func (c *barClient) EchoI16( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1443,7 +1443,7 @@ func (c *barClient) EchoI32( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1499,7 +1499,7 @@ func (c *barClient) EchoI32Map( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1555,7 +1555,7 @@ func (c *barClient) EchoI64( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1611,7 +1611,7 @@ func (c *barClient) EchoI8( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1667,7 +1667,7 @@ func (c *barClient) EchoString( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1723,7 +1723,7 @@ func (c *barClient) EchoStringList( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1779,7 +1779,7 @@ func (c *barClient) EchoStringMap( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1835,7 +1835,7 @@ func (c *barClient) EchoStringSet( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1891,7 +1891,7 @@ func (c *barClient) EchoStructList( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1947,7 +1947,7 @@ func (c *barClient) EchoStructSet( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -2003,7 +2003,7 @@ func (c *barClient) EchoTypedef( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } diff --git a/examples/example-gateway/build/clients/bar/bar.go b/examples/example-gateway/build/clients/bar/bar.go index 3a2c35c6c..aba78514a 100644 --- a/examples/example-gateway/build/clients/bar/bar.go +++ b/examples/example-gateway/build/clients/bar/bar.go @@ -268,7 +268,7 @@ func (c *barClient) ArgNotStruct( return nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return nil, err } @@ -335,7 +335,7 @@ func (c *barClient) ArgWithHeaders( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -468,7 +468,7 @@ func (c *barClient) ArgWithManyQueryParams( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -561,7 +561,7 @@ func (c *barClient) ArgWithNestedQueryParams( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -616,7 +616,7 @@ func (c *barClient) ArgWithParams( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -668,7 +668,7 @@ func (c *barClient) ArgWithQueryHeader( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -737,7 +737,7 @@ func (c *barClient) ArgWithQueryParams( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -788,7 +788,7 @@ func (c *barClient) Hello( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -847,7 +847,7 @@ func (c *barClient) MissingArg( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -907,7 +907,7 @@ func (c *barClient) NoRequest( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -968,7 +968,7 @@ func (c *barClient) Normal( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1029,7 +1029,7 @@ func (c *barClient) NormalRecur( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1089,7 +1089,7 @@ func (c *barClient) TooManyArgs( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1163,7 +1163,7 @@ func (c *barClient) EchoBinary( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1219,7 +1219,7 @@ func (c *barClient) EchoBool( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1275,7 +1275,7 @@ func (c *barClient) EchoDouble( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1331,7 +1331,7 @@ func (c *barClient) EchoEnum( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1387,7 +1387,7 @@ func (c *barClient) EchoI16( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1443,7 +1443,7 @@ func (c *barClient) EchoI32( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1499,7 +1499,7 @@ func (c *barClient) EchoI32Map( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1555,7 +1555,7 @@ func (c *barClient) EchoI64( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1611,7 +1611,7 @@ func (c *barClient) EchoI8( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1667,7 +1667,7 @@ func (c *barClient) EchoString( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1723,7 +1723,7 @@ func (c *barClient) EchoStringList( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1779,7 +1779,7 @@ func (c *barClient) EchoStringMap( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1835,7 +1835,7 @@ func (c *barClient) EchoStringSet( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1891,7 +1891,7 @@ func (c *barClient) EchoStructList( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -1947,7 +1947,7 @@ func (c *barClient) EchoStructSet( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -2003,7 +2003,7 @@ func (c *barClient) EchoTypedef( return defaultRes, nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } diff --git a/examples/example-gateway/build/clients/contacts/contacts.go b/examples/example-gateway/build/clients/contacts/contacts.go index 837d80a8d..063955bbd 100644 --- a/examples/example-gateway/build/clients/contacts/contacts.go +++ b/examples/example-gateway/build/clients/contacts/contacts.go @@ -104,7 +104,7 @@ func (c *contactsClient) SaveContacts( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -154,7 +154,7 @@ func (c *contactsClient) TestURLURL( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } diff --git a/examples/example-gateway/build/clients/corge-http/corge-http.go b/examples/example-gateway/build/clients/corge-http/corge-http.go index 859130c47..10cd370aa 100644 --- a/examples/example-gateway/build/clients/corge-http/corge-http.go +++ b/examples/example-gateway/build/clients/corge-http/corge-http.go @@ -116,7 +116,7 @@ func (c *corgeHTTPClient) EchoString( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } diff --git a/examples/example-gateway/build/clients/google-now/google-now.go b/examples/example-gateway/build/clients/google-now/google-now.go index 21fe1d1ea..eb96028d4 100644 --- a/examples/example-gateway/build/clients/google-now/google-now.go +++ b/examples/example-gateway/build/clients/google-now/google-now.go @@ -108,7 +108,7 @@ func (c *googleNowClient) AddCredentials( return nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return nil, err } @@ -161,7 +161,7 @@ func (c *googleNowClient) CheckCredentials( return nil, headerErr } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return nil, err } diff --git a/examples/example-gateway/build/clients/multi/multi.go b/examples/example-gateway/build/clients/multi/multi.go index 3189a842f..e32090e0e 100644 --- a/examples/example-gateway/build/clients/multi/multi.go +++ b/examples/example-gateway/build/clients/multi/multi.go @@ -101,7 +101,7 @@ func (c *multiClient) HelloA( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } @@ -151,7 +151,7 @@ func (c *multiClient) HelloB( return defaultRes, nil, err } - res, err := req.Do(ctx) + res, err := req.Do() if err != nil { return defaultRes, nil, err } diff --git a/examples/example-gateway/build/services/example-gateway/module/init.go b/examples/example-gateway/build/services/example-gateway/module/init.go index ef4a23493..dee5f0f0f 100644 --- a/examples/example-gateway/build/services/example-gateway/module/init.go +++ b/examples/example-gateway/build/services/example-gateway/module/init.go @@ -97,11 +97,12 @@ func InitializeDependencies( tree := &DependenciesTree{} initializedDefaultDependencies := &zanzibar.DefaultDependencies{ - Logger: g.Logger, - Scope: g.AllHostScope, - Tracer: g.Tracer, - Config: g.Config, - Channel: g.Channel, + Logger: g.Logger, + ContextLogger: g.ContextLogger, + Scope: g.AllHostScope, + Tracer: g.Tracer, + Config: g.Config, + Channel: g.Channel, } initializedClientDependencies := &ClientDependenciesNodes{} diff --git a/runtime/client_http_request.go b/runtime/client_http_request.go index 58f4173a6..a0c66ce44 100644 --- a/runtime/client_http_request.go +++ b/runtime/client_http_request.go @@ -33,8 +33,7 @@ import ( "go.uber.org/zap" ) -// ClientHTTPRequest is the struct for making client -// requests using an outbound http client. +// ClientHTTPRequest is the struct for making a single client request using an outbound http client. type ClientHTTPRequest struct { ClientID string MethodName string @@ -44,13 +43,14 @@ type ClientHTTPRequest struct { started bool startTime time.Time Logger *zap.Logger + ContextLogger ContextLogger metrics *OutboundHTTPMetrics rawBody []byte defaultHeaders map[string]string ctx context.Context } -// NewClientHTTPRequest allocates a ClientHTTPRequest +// NewClientHTTPRequest allocates a ClientHTTPRequest. The ctx parameter is the context associated with the outbound requests. func NewClientHTTPRequest( ctx context.Context, clientID, methodName string, @@ -61,6 +61,7 @@ func NewClientHTTPRequest( MethodName: methodName, client: client, Logger: client.loggers[methodName], + ContextLogger: NewContextLogger(client.loggers[methodName]), metrics: client.metrics[methodName], defaultHeaders: client.DefaultHeaders, ctx: ctx, @@ -149,17 +150,21 @@ func (req *ClientHTTPRequest) WriteJSON( httpReq.Header.Set("Content-Type", "application/json") req.httpReq = httpReq + req.ctx = WithLogFields(req.ctx, + zap.String(logFieldRequestMethod, method), + zap.String(logFieldRequestURL, url), + zap.Time(logFieldRequestStartTime, req.startTime), + ) + return nil } // Do will send the request out. -func (req *ClientHTTPRequest) Do( - ctx context.Context, -) (*ClientHTTPResponse, error) { +func (req *ClientHTTPRequest) Do() (*ClientHTTPResponse, error) { opName := fmt.Sprintf("%s.%s", req.ClientID, req.MethodName) urlTag := opentracing.Tag{Key: "URL", Value: req.httpReq.URL} methodTag := opentracing.Tag{Key: "Method", Value: req.httpReq.Method} - span, ctx := opentracing.StartSpanFromContext(ctx, opName, urlTag, methodTag) + span, ctx := opentracing.StartSpanFromContext(req.ctx, opName, urlTag, methodTag) err := req.InjectSpanToHeader(span, opentracing.HTTPHeaders) if err != nil { /* coverage ignore next line */ @@ -167,6 +172,14 @@ func (req *ClientHTTPRequest) Do( /* coverage ignore next line */ return nil, err } + + logFields := make([]zap.Field, 0, len(req.httpReq.Header)) + for k, v := range req.httpReq.Header { + logFields = append(logFields, zap.String(fmt.Sprintf("%s-%s", logFieldRequestHeaderPrefix, k), v[0])) + } + ctx = WithLogFields(ctx, logFields...) + req.ctx = ctx + res, err := req.client.Client.Do(req.httpReq.WithContext(ctx)) span.Finish() if err != nil { diff --git a/runtime/client_http_request_test.go b/runtime/client_http_request_test.go index 55a7559b0..e423a34df 100644 --- a/runtime/client_http_request_test.go +++ b/runtime/client_http_request_test.go @@ -155,7 +155,7 @@ func TestMakingClientCallWithHeaders(t *testing.T) { ) assert.NoError(t, err) - res, err := req.Do(context.Background()) + res, err := req.Do() assert.NoError(t, err) assert.Equal(t, 200, res.StatusCode) diff --git a/runtime/client_http_response.go b/runtime/client_http_response.go index faef5a0cd..ee1d71859 100644 --- a/runtime/client_http_response.go +++ b/runtime/client_http_response.go @@ -156,27 +156,19 @@ func (res *ClientHTTPResponse) finish() { } // write logs - res.req.Logger.Info( + res.req.ContextLogger.Info( + res.req.ctx, "Finished an outgoing client HTTP request", clientHTTPLogFields(res.req, res)..., ) - } func clientHTTPLogFields(req *ClientHTTPRequest, res *ClientHTTPResponse) []zapcore.Field { fields := []zapcore.Field{ - zap.String("method", req.httpReq.Method), - zap.String("url", req.httpReq.URL.String()), - zap.Time("timestamp-started", req.startTime), - zap.Time("timestamp-finished", res.finishTime), - zap.Int("statusCode", res.StatusCode), + zap.Time(logFieldRequestFinishedTime, res.finishTime), + zap.Int(logFieldResponseStatusCode, res.StatusCode), } - for k, v := range req.httpReq.Header { - if len(v) > 0 { - fields = append(fields, zap.String("Request-Header-"+k, v[0])) - } - } for k, v := range req.res.Header { if len(v) > 0 { fields = append(fields, zap.String("Response-Header-"+k, v[0])) diff --git a/runtime/client_http_response_test.go b/runtime/client_http_response_test.go index e259e9dd3..fbeb1401f 100644 --- a/runtime/client_http_response_test.go +++ b/runtime/client_http_response_test.go @@ -76,11 +76,12 @@ func TestReadAndUnmarshalNonStructBody(t *testing.T) { time.Second, ) ctx := context.Background() + req := zanzibar.NewClientHTTPRequest(ctx, "bar", "echo", client) err = req.WriteJSON("POST", baseURL+"/bar/echo", nil, myJson{}) assert.NoError(t, err) - res, err := req.Do(context.Background()) + res, err := req.Do() assert.NoError(t, err) var resp string @@ -133,11 +134,12 @@ func TestReadAndUnmarshalNonStructBodyUnmarshalError(t *testing.T) { time.Second, ) ctx := context.Background() + req := zanzibar.NewClientHTTPRequest(ctx, "bar", "echo", client) err = req.WriteJSON("POST", baseURL+"/bar/echo", nil, myJson{}) assert.NoError(t, err) - res, err := req.Do(context.Background()) + res, err := req.Do() assert.NoError(t, err) var resp string @@ -190,12 +192,13 @@ func TestUnknownStatusCode(t *testing.T) { ) ctx := context.Background() + req := zanzibar.NewClientHTTPRequest(ctx, "bar", "echo", client) err = req.WriteJSON("POST", baseURL+"/bar/echo", nil, myJson{}) assert.NoError(t, err) - res, err := req.Do(context.Background()) + res, err := req.Do() assert.NoError(t, err) var resp string diff --git a/runtime/context.go b/runtime/context.go index 455518418..b24e52a36 100644 --- a/runtime/context.go +++ b/runtime/context.go @@ -24,6 +24,7 @@ import ( "context" "github.com/pborman/uuid" + "go.uber.org/zap" ) type contextFieldKey string @@ -32,6 +33,16 @@ const ( endpointKey = contextFieldKey("endpoint") requestUUIDKey = contextFieldKey("requestUUID") routingDelegateKey = contextFieldKey("rd") + requestLogFields = contextFieldKey("requestLogFields") +) + +const ( + logFieldRequestMethod = "method" + logFieldRequestURL = "url" + logFieldRequestStartTime = "timestamp-started" + logFieldRequestFinishedTime = "timestamp-finished" + logFieldRequestHeaderPrefix = "Request-Header" + logFieldResponseStatusCode = "statusCode" ) // WithEndpointField adds the endpoint information in the @@ -81,3 +92,67 @@ func GetRoutingDelegateFromCtx(ctx context.Context) string { } return "" } + +// WithLogFields returns a new context with the given log fields attached to context.Context +func WithLogFields(ctx context.Context, newFields ...zap.Field) context.Context { + return context.WithValue(ctx, requestLogFields, accumulateLogFields(ctx, newFields)) +} + +func accumulateLogFields(ctx context.Context, newFields []zap.Field) []zap.Field { + previousFieldsUntyped := ctx.Value(requestLogFields) + if previousFieldsUntyped == nil { + previousFieldsUntyped = []zap.Field{} + } + previousFields := previousFieldsUntyped.([]zap.Field) + + fields := make([]zap.Field, 0, len(previousFields)+len(newFields)) + + for _, field := range previousFields { + fields = append(fields, field) + } + for _, field := range newFields { + fields = append(fields, field) + } + + return fields +} + +// ContextLogger is a logger that extracts some log fields from the context before passing through to underlying zap logger. +type ContextLogger interface { + Debug(ctx context.Context, msg string, fields ...zap.Field) + Error(ctx context.Context, msg string, fields ...zap.Field) + Info(ctx context.Context, msg string, fields ...zap.Field) + Panic(ctx context.Context, msg string, fields ...zap.Field) + Warn(ctx context.Context, msg string, fields ...zap.Field) +} + +// NewContextLogger returns a logger that extracts log fields a context before passing through to underlying zap logger. +func NewContextLogger(log *zap.Logger) ContextLogger { + return &contextLogger{ + log: log, + } +} + +type contextLogger struct { + log *zap.Logger +} + +func (c *contextLogger) Debug(ctx context.Context, msg string, userFields ...zap.Field) { + c.log.Debug(msg, accumulateLogFields(ctx, userFields)...) +} + +func (c *contextLogger) Error(ctx context.Context, msg string, userFields ...zap.Field) { + c.log.Error(msg, accumulateLogFields(ctx, userFields)...) +} + +func (c *contextLogger) Info(ctx context.Context, msg string, userFields ...zap.Field) { + c.log.Info(msg, accumulateLogFields(ctx, userFields)...) +} + +func (c *contextLogger) Panic(ctx context.Context, msg string, userFields ...zap.Field) { + c.log.Panic(msg, accumulateLogFields(ctx, userFields)...) +} + +func (c *contextLogger) Warn(ctx context.Context, msg string, userFields ...zap.Field) { + c.log.Warn(msg, accumulateLogFields(ctx, userFields)...) +} diff --git a/runtime/context_test.go b/runtime/context_test.go index 5e76cad37..3d697dcd7 100644 --- a/runtime/context_test.go +++ b/runtime/context_test.go @@ -26,6 +26,8 @@ import ( "github.com/pborman/uuid" "github.com/stretchr/testify/assert" + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" ) func TestWithEndpointField(t *testing.T) { @@ -93,3 +95,51 @@ func TestGetRoutingDelegateFromCtx(t *testing.T) { assert.Equal(t, expected, rd) } + +func TestContextLogger(t *testing.T) { + zapLoggerCore, logs := observer.New(zap.DebugLevel) + zapLogger := zap.New(zapLoggerCore) + contextLogger := NewContextLogger(zapLogger) + ctx := context.Background() + ctxWithField := WithLogFields(ctx, zap.String("ctxField", "ctxValue")) + + var logMessages []observer.LoggedEntry + + contextLogger.Debug(ctxWithField, "msg", zap.String("argField", "argValue")) + logMessages = logs.TakeAll() + assert.Len(t, logMessages, 1) + assert.Equal(t, zap.DebugLevel, logMessages[0].Level) + assert.Equal(t, logMessages[0].Context[0].Key, "ctxField") + assert.Equal(t, logMessages[0].Context[0].String, "ctxValue") + assert.Equal(t, logMessages[0].Context[1].Key, "argField") + assert.Equal(t, logMessages[0].Context[1].String, "argValue") + + contextLogger.Info(ctxWithField, "msg", zap.String("argField", "argValue")) + logMessages = logs.TakeAll() + assert.Len(t, logMessages, 1) + assert.Equal(t, zap.InfoLevel, logMessages[0].Level) + + contextLogger.Warn(ctxWithField, "msg", zap.String("argField", "argValue")) + logMessages = logs.TakeAll() + assert.Len(t, logMessages, 1) + assert.Equal(t, zap.WarnLevel, logMessages[0].Level) + + contextLogger.Error(ctxWithField, "msg", zap.String("argField", "argValue")) + logMessages = logs.TakeAll() + assert.Len(t, logMessages, 1) + assert.Equal(t, zap.ErrorLevel, logMessages[0].Level) +} + +func TestContextLoggerPanic(t *testing.T) { + defer func() { + err := recover() + assert.NotNil(t, err) + }() + + zapNop := zap.NewNop() + + contextLogger := NewContextLogger(zapNop) + ctx := context.Background() + + contextLogger.Panic(ctx, "msg", zap.String("argField", "argValue")) +} diff --git a/runtime/gateway.go b/runtime/gateway.go index 5b6aeb194..5004ddec7 100644 --- a/runtime/gateway.go +++ b/runtime/gateway.go @@ -76,6 +76,7 @@ type Gateway struct { WaitGroup *sync.WaitGroup Channel *tchannel.Channel Logger *zap.Logger + ContextLogger ContextLogger RootScope tally.Scope AllHostScope tally.Scope PerHostScope tally.Scope @@ -101,9 +102,14 @@ type Gateway struct { // - process reporter ? } -// DefaultDependencies type +// DefaultDependencies are the common dependencies for all modules type DefaultDependencies struct { - Logger *zap.Logger + // Logger is a server-scoped logger + Logger *zap.Logger + + // ContextLogger is a logger with request-scoped log fields + ContextLogger ContextLogger + Scope tally.Scope Tracer opentracing.Tracer Config *StaticConfig @@ -545,6 +551,8 @@ func (gateway *Gateway) setupLogger(config *StaticConfig) error { zap.String("service", gateway.Config.MustGetString("serviceName")), zap.Int("pid", os.Getpid()), ) + + gateway.ContextLogger = NewContextLogger(gateway.Logger) return nil }