Improved observability (#869)

- Added jaeger trace fields in all logs - Moved few request log parameters from response to all logs - method - pathname - remoteAddr - host
uber · May 18, 2023 · f2aa266 · f2aa266
1 parent 81403d8
commit f2aa266
Show file tree

Hide file tree

Showing 4 changed files with 37 additions and 20 deletions.
diff --git a/runtime/context.go b/runtime/context.go
@@ -53,7 +53,11 @@ const (
 const (
 	// thrift service::method of endpoint thrift spec
 	logFieldRequestMethod       = "endpointThriftMethod"
+	logFieldRequestHTTPMethod   = "method"
 	logFieldRequestURL          = "url"
+	logFieldRequestPathname     = "pathname"
+	logFieldRequestRemoteAddr   = "remoteAddr"
+	logFieldRequestHost         = "host"
 	logFieldRequestStartTime    = "timestamp-started"
 	logFieldRequestFinishedTime = "timestamp-finished"
 	logFieldResponseStatusCode  = "statusCode"

diff --git a/runtime/server_http_request.go b/runtime/server_http_request.go
@@ -34,6 +34,7 @@ import (
 	"github.com/opentracing/opentracing-go"
 	"github.com/opentracing/opentracing-go/ext"
 	"github.com/uber-go/tally"
+	"github.com/uber/jaeger-client-go"
 	"github.com/uber/zanzibar/runtime/jsonwrapper"
 	"go.uber.org/zap"
 )
@@ -78,6 +79,10 @@ func NewServerHTTPRequest(
 		zap.String(logFieldEndpointID, endpoint.EndpointName),
 		zap.String(logFieldEndpointHandler, endpoint.HandlerName),
 		zap.String(logFieldRequestURL, r.URL.Path),
+		zap.String(logFieldRequestHTTPMethod, r.Method),
+		zap.String(logFieldRequestRemoteAddr, r.RemoteAddr),
+		zap.String(logFieldRequestPathname, r.URL.RequestURI()),
+		zap.String(logFieldRequestHost, r.Host),
 	}
 
 	// put request scope tags on context
@@ -204,6 +209,25 @@ func (req *ServerHTTPRequest) start() {
 		}
 		req.span = span
 	}
+	req.setupLogFields()
+}
+
+func (req *ServerHTTPRequest) setupLogFields() {
+	fields := GetLogFieldsFromCtx(req.Context())
+	fields = append(fields, zap.Time(logFieldRequestStartTime, req.startTime))
+	if span := req.GetSpan(); span != nil {
+		jc, ok := span.Context().(jaeger.SpanContext)
+		if ok {
+			fields = append(fields,
+				zap.String(TraceSpanKey, jc.SpanID().String()),
+				zap.String(TraceIDKey, jc.TraceID().String()),
+				zap.Bool(TraceSampledKey, jc.IsSampled()),
+			)
+		}
+	}
+
+	ctx := WithLogFields(req.Context(), fields...)
+	req.httpRequest = req.httpRequest.WithContext(ctx)
 }
 
 // CheckHeaders verifies that request contains required headers.

diff --git a/runtime/server_http_response.go b/runtime/server_http_response.go
@@ -28,8 +28,6 @@ import (
 	"strings"
 	"time"
 
-	"github.com/uber/jaeger-client-go"
-
 	"github.com/buger/jsonparser"
 	"github.com/pkg/errors"
 	"github.com/uber-go/tally"
@@ -142,24 +140,8 @@ func (res *ServerHTTPResponse) finish(ctx context.Context) {
 
 func serverHTTPLogFields(req *ServerHTTPRequest, res *ServerHTTPResponse) []zapcore.Field {
 	fields := []zapcore.Field{
-		zap.String("method", req.httpRequest.Method),
-		zap.String("remoteAddr", req.httpRequest.RemoteAddr),
-		zap.String("pathname", req.httpRequest.URL.RequestURI()),
-		zap.String("host", req.httpRequest.Host),
-		zap.Time("timestamp-started", req.startTime),
-		zap.Time("timestamp-finished", res.finishTime),
-		zap.Int("statusCode", res.StatusCode),
-	}
-
-	if span := req.GetSpan(); span != nil {
-		jc, ok := span.Context().(jaeger.SpanContext)
-		if ok {
-			fields = append(fields,
-				zap.String(TraceSpanKey, jc.SpanID().String()),
-				zap.String(TraceIDKey, jc.TraceID().String()),
-				zap.Bool(TraceSampledKey, jc.IsSampled()),
-			)
-		}
+		zap.Time(logFieldRequestFinishedTime, res.finishTime),
+		zap.Int(logFieldResponseStatusCode, res.StatusCode),
 	}
 
 	for k, v := range res.Headers() {

diff --git a/test/endpoints/bar/bar_metrics_test.go b/test/endpoints/bar/bar_metrics_test.go
@@ -211,6 +211,11 @@ func TestCallMetrics(t *testing.T) {
 		"hostname",
 		"pid",
 		"requestUUID",
+		"host",
+		"remoteAddr",
+		"trace.traceId",
+		"trace.span",
+		"trace.sampled",
 	}
 	for _, dynamicValue := range dynamicHeaders {
 		assert.Contains(t, logMsg, dynamicValue)
@@ -221,6 +226,8 @@ func TestCallMetrics(t *testing.T) {
 		"level":      "debug",
 		"msg":        "Finished an outgoing client HTTP request",
 		"statusCode": float64(200),
+		"method":     "POST",
+		"pathname":   "/bar/bar-path",
 		//"clientID":                       "bar",
 		//"clientMethod":                   "Normal",
 		//"clientThriftMethod":             "Bar::normal",