Add context logger; use context logger for HTTP client request log #444

jacobgreenleaf · 2018-08-23T21:54:37Z

Adds a new logger to DefaultDeps that has an API like:

// 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)
	Fatal(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)
}

Cases for log fields:

static defined by zanzibar (server) i.e. "production" env var. The logger passed to NewContextLogger() should have this field already populated in zap fields.
static defined by zanzibar (endpoint) i.e. endpointID="foo.bar". Today we happen to call NewContextLogger with endpoint's zap logger preallocated to have endpointID field client.loggers[methodName]. In the future we will need to inject endpointID into context like other request fields to support logs emitted by user code, which makes clients.loggers redundant.
Request parameter (HTTP header, etc.). Zanzibar uses zanzibar/runtime.WithLogFields(ctx, ...) to mutate context.Context.
request value defined by zanzibar (e.g. request UUID). Same as (3).
request value defined by platform using zanzibar (e.g. task ID, or maybe edge gateway middlewares). Platform code to use zanzibar/runtime.WithLogFields(ctx, ...) to mutate context.Context similar to (3).
request value put in context by third party lib (e.g. jaeger trace ID). Will need to use third party API to extract value from context (since it's usually unexported type), then use WithLogFields(ctx) API similar to (3).
static defined by platform using zanzibar (e.g. UDEPLOY_DEPLOYMENT_NAME). There will need to be a startup hook to register custom log fields (in a later diff).

This diff leverages previously written tests (#441).

cl1337 · 2018-08-23T21:58:39Z

runtime/client_http_response_test.go

 	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()


I like this, as long as ctx inside req is not mutated

will the behavior for deadline change?

I don't see that there is a difference for deadline propagation. It was redundant before since there were no mutations done to the context, but now WriteJSON modifies the context so it's actually confusing / misleading to pass context into Do().

cl1337 · 2018-08-23T21:59:28Z

runtime/context.go

@@ -23,7 +23,10 @@ package zanzibar
 import (
 	"context"

+	"github.com/uber/zanzibar/internal/runtime"
+
 	"github.com/pborman/uuid"


I heard https://github.com/satori/go.uuid is more popular now

cl1337 · 2018-08-23T21:59:51Z

runtime/context.go

@@ -34,6 +37,13 @@ const (
 	routingDelegateKey = contextFieldKey("rd")
 )

+const (


not open to extension in this PR? 😿

cl1337 · 2018-08-23T22:00:28Z

runtime/context.go

+
+// WithLogFields is a helper function to add the log field to the context
+func WithLogFields(ctx context.Context, fields ...zap.Field) context.Context {
+	lg := Logger(ctx)


nit: just use log :)

cl1337 · 2018-08-23T22:01:28Z

runtime/context.go

+	logFieldRequestMethod       = "method"
+	logFieldRequestURL          = "url"
+	logFieldRequestStartTime    = "timestamp-started"
+	logFieldRequestHeaderPrefix = "Request-Header"


nit: seems like you're implicating case sensitive, is this intended ?

ChuntaoLu

It seems like this change is quite different from what I thought it is supposed to be. Don't we want something like logger.Info(ctx, msg, fields...)?

It is also noticeable that this changes creates 2 child logger per client request, which, @cl1337 have shown in #425, is not a good idea performance wise.

ChuntaoLu · 2018-08-23T23:22:34Z

runtime/client_http_request.go

-func (req *ClientHTTPRequest) Do(
-	ctx context.Context,
-) (*ClientHTTPResponse, error) {
+func (req *ClientHTTPRequest) Do() (*ClientHTTPResponse, error) {


Since now the Do method no longer takes the context parameter and ctx is a private field on ClientHTTPRequest, we should update the comments here and here to explicitly call out that the context given during the constructor call is attached to the ClientHTTPRequest and all its methods behave according to that context.

I've updated the comments, but it was sort of implied before (since started and startTime make this class not reusable).

ChuntaoLu · 2018-08-23T23:28:01Z

runtime/context.go

@@ -81,3 +91,27 @@ func GetRoutingDelegateFromCtx(ctx context.Context) string {
 	}
 	return ""
 }
+
+// Logger returns a request-scoped logger, a logger with request headers added as log fields.
+func Logger(ctx context.Context) *zap.Logger {


Just looking at the function signature, I had the false impression that a new logger is created. Maybe something like GetLoggerFrom is more descriptive.

ChuntaoLu · 2018-08-23T23:37:03Z

runtime/context.go

+	return logger
+}
+
+// WithLogFields is a helper function to add the log field to the context


This comment is misleading, the function actually adds log fields to the logger on the context (also involves a child logger creation) instead of "add the log field to the context". The function name WithLogFields with its signature does create an conventional impression that is consistent with what the comment says, but that is not what really happens here.

ChuntaoLu · 2018-08-23T23:46:35Z

runtime/client_http_response.go

@@ -156,27 +156,18 @@ func (res *ClientHTTPResponse) finish() {
 	}

 	// write logs
-	res.req.Logger.Info(
+	Logger(res.req.ctx).Info(


This is quite different from what we discussed, I thought what we want is logger.Info(ctx, msg, fields...).

ChuntaoLu · 2018-08-23T23:53:37Z

runtime/client_http_request.go

@@ -149,24 +149,40 @@ func (req *ClientHTTPRequest) WriteJSON(
 	httpReq.Header.Set("Content-Type", "application/json")

 	req.httpReq = httpReq
+	req.ctx = WithLogFields(req.ctx,


WithLogFields creates a child logger and this is inside the WriteJSON call, which means we are creating a child logger per client request here.

+1. The context child logger should be created once for the client and we register all the context fields that we need to fetch from context.

Lu's comment refers to an earlier diff where we were creating a new *zap.Logger each time. Now instead we are just mutating the []zap.Fields each time.

ChuntaoLu · 2018-08-23T23:56:05Z

runtime/client_http_request.go

+
+		logFields = append(logFields, zap.String(fmt.Sprintf("%s-%s", logFieldRequestHeaderPrefix, k), v[0]))
+	}
+	ctx = WithLogFields(ctx, logFields...)


Here is another callsite of WithLogFields, plus the one in WriteJSON, we are creating 2 child loggers per client request.

ChuntaoLu

Do you plan to have the context logger in http endpoint in a separate PR?

ChuntaoLu · 2018-08-24T18:50:41Z

runtime/context.go

+}
+
+// ContextLogger is a logger that extracts some log fields from the context before passing through to underlying zap logger.
+type ContextLogger interface {


I like it. We should write some tests for the ContextLogger, it will be great to have some benchmark tests to compare with vanilla zap.Logger so that we don't have any surprises.

ChuntaoLu · 2018-08-24T18:54:05Z

runtime/context.go

+	log *zap.Logger
+}
+
+func (c *contextLogger) joinFields(ctx context.Context, userFields []zap.Field) []zap.Field {


nit: this function almost identical to WithLogFields, maybe reuse.

ChuntaoLu · 2018-08-24T18:54:57Z

runtime/context.go

+	return fields
+}
+
+func (c *contextLogger) Debug(ctx context.Context, msg string, userFields ...zap.Field) {


Doesn't the linter complain missing comments for public methods?

ChuntaoLu · 2018-08-24T19:02:12Z

runtime/client_http_request.go

@@ -61,6 +61,7 @@ func NewClientHTTPRequest(
 		MethodName:     methodName,
 		client:         client,
 		Logger:         client.loggers[methodName],
+		ContextLogger:  NewContextLogger(client.loggers[methodName]),


Now that we have a proper context logger, we will no longer need to create a child logger per method as in https://github.com/uber/zanzibar/blob/master/runtime/http_client.go#L62-L68, we only need to include the method name in the context log fields. That could be in different PR tho (please create an issue to remind us if you decide to have that done separately).

Yes, it'll be done in a separate diff.

ChuntaoLu · 2018-08-24T19:12:28Z

runtime/context.go

+)
+
+const (
+	logFieldRequestMethod       = "method"


How should we differentiate the field between client and endpoint?

I'm preserving these log fields as they were before, open to better names. endpoint-http-method, endpoint-url, etc. seem better to me. Thoughts?

That works, we should also think about how these can be customizable so that user can define log fields.

coveralls · 2018-08-25T00:01:13Z

Coverage increased (+0.1%) to 62.63% when pulling 7ffd245 on jg-client-logger into 0f16a51 on master.

jacobgreenleaf requested review from ChuntaoLu and cl1337 August 23, 2018 21:54

cl1337 approved these changes Aug 23, 2018

View reviewed changes

ChuntaoLu suggested changes Aug 24, 2018

View reviewed changes

jacobgreenleaf changed the title ~~Switch to Logger(ctx) for success HTTP client log~~ Add context logger Aug 24, 2018

jacobgreenleaf force-pushed the jg-client-logger branch from 4d1c19b to 8ab384d Compare August 24, 2018 01:54

jacobgreenleaf requested a review from srivastavankit August 24, 2018 01:57

jacobgreenleaf changed the title ~~Add context logger~~ Add context logger; use context logger for HTTP client request log Aug 24, 2018

ChuntaoLu reviewed Aug 24, 2018

View reviewed changes

Add context logger

7ffd245

jacobgreenleaf force-pushed the jg-client-logger branch from 8ab384d to 7ffd245 Compare August 24, 2018 23:41

ChuntaoLu approved these changes Aug 25, 2018

View reviewed changes

jacobgreenleaf merged commit 359e6d0 into master Aug 25, 2018

jacobgreenleaf deleted the jg-client-logger branch August 25, 2018 00:20

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add context logger; use context logger for HTTP client request log #444

Add context logger; use context logger for HTTP client request log #444

jacobgreenleaf commented Aug 23, 2018 •

edited

cl1337 Aug 23, 2018

jacobgreenleaf Aug 24, 2018

cl1337 Aug 23, 2018

cl1337 Aug 23, 2018

cl1337 Aug 23, 2018

cl1337 Aug 23, 2018

ChuntaoLu left a comment •

edited

ChuntaoLu Aug 23, 2018

jacobgreenleaf Aug 24, 2018

ChuntaoLu Aug 23, 2018

ChuntaoLu Aug 23, 2018

ChuntaoLu Aug 23, 2018

ChuntaoLu Aug 23, 2018

srivastavankit Aug 24, 2018

jacobgreenleaf Aug 24, 2018

ChuntaoLu Aug 23, 2018

ChuntaoLu left a comment

ChuntaoLu Aug 24, 2018

ChuntaoLu Aug 24, 2018

ChuntaoLu Aug 24, 2018

ChuntaoLu Aug 24, 2018

jacobgreenleaf Aug 24, 2018

ChuntaoLu Aug 24, 2018

jacobgreenleaf Aug 24, 2018

ChuntaoLu Aug 25, 2018

coveralls commented Aug 25, 2018

Add context logger; use context logger for HTTP client request log #444

Add context logger; use context logger for HTTP client request log #444

Conversation

jacobgreenleaf commented Aug 23, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ChuntaoLu left a comment • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ChuntaoLu left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Aug 25, 2018

jacobgreenleaf commented Aug 23, 2018 •

edited

ChuntaoLu left a comment •

edited