logging: Reversed policy of fields - from immutable to fresh winning. (…

…#616)

* logging: Reversed policy of fields - from immutable to fresh winning.

Fixes: #613

Signed-off-by: bwplotka <[email protected]>

* Addressed comments.

Signed-off-by: bwplotka <[email protected]>

---------

Signed-off-by: bwplotka <[email protected]>

interceptors/logging/interceptors.go

@@ -141,14 +141,16 @@ func reportable(logger Logger, opts *options) interceptors.CommonReportableFunc
 			kind = KindClientFieldValue
 		}
 
-		fields := ExtractFields(ctx).WithUnique(newCommonFields(kind, c))
+		// Field dups from context override the common fields.
+		fields := newCommonFields(kind, c).WithUnique(ExtractFields(ctx))
 		if !c.IsClient {
 			if peer, ok := peer.FromContext(ctx); ok {
 				fields = append(fields, "peer.address", peer.Addr.String())
 			}
 		}
 		if opts.fieldsFromCtxFn != nil {
-			fields = fields.AppendUnique(opts.fieldsFromCtxFn(ctx))
+			// fieldsFromCtxFn dups override the existing fields.
+			fields = opts.fieldsFromCtxFn(ctx).AppendUnique(fields)
 		}
 
 		singleUseFields := Fields{"grpc.start_time", time.Now().Format(opts.timestampFormat)}

interceptors/logging/logging.go

@@ -129,8 +129,9 @@ NextAddField:
 }
 
 // ExtractFields returns logging fields from the context.
-// Logging interceptor adds fields into context when used.
-// If there are no fields in the context, returns an empty Fields value.
+// Fields can be added from the context using InjectFields. For example logging interceptor adds some (base) fields
+// into context when used.
+// If there are no fields in the context, it returns an empty Fields value.
 // Extracted fields are useful to construct your own logger that has fields from gRPC interceptors.
 func ExtractFields(ctx context.Context) Fields {
 	t, ok := ctx.Value(fieldsCtxMarkerKey).(Fields)
@@ -142,13 +143,14 @@ func ExtractFields(ctx context.Context) Fields {
 	return n
 }
 
-// InjectFields allows adding fields to any existing Fields that will be used by the logging interceptor.
-// For explicitness, in case of duplicates, first field occurrence wins (immutability of fields). This also
-// applies to all fields created by logging middleware. It uses labels from this context as a base, so fields like "grpc.service"
-// can be overridden if your you add custom middleware that injects "grpc.service" before logging middleware injects those.
-// Don't overuse overriding to avoid surprises.
+// InjectFields allows adding fields to any existing Fields that will be used by the logging interceptor or can be
+// extracted further in ExtractFields.
+// For explicitness, in case of duplicates, the newest field occurrence wins. This allows nested components to update
+// popular fields like grpc.component (e.g. server invoking gRPC client).
+//
+// Don't overuse mutation of fields to avoid surprises.
 func InjectFields(ctx context.Context, f Fields) context.Context {
-	return context.WithValue(ctx, fieldsCtxMarkerKey, ExtractFields(ctx).WithUnique(f))
+	return context.WithValue(ctx, fieldsCtxMarkerKey, f.WithUnique(ExtractFields(ctx)))
 }
 
 // InjectLogField is like InjectFields, just for one field.

interceptors/logging/logging_test.go

@@ -0,0 +1,41 @@
+// Copyright (c) The go-grpc-middleware Authors.
+// Licensed under the Apache License 2.0.
+
+package logging
+
+import (
+	"context"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+)
+
+func TestFieldsInjectExtractFromContext(t *testing.T) {
+	c := context.Background()
+	f := ExtractFields(c)
+	require.Equal(t, Fields(nil), f)
+
+	f = f.AppendUnique([]any{"a", "1", "b", "2"})
+	require.Equal(t, Fields{"a", "1", "b", "2"}, f)
+
+	c2 := InjectFields(c, f)
+
+	// First context should be untouched.
+	f = ExtractFields(c)
+	require.Equal(t, Fields(nil), f)
+	f = ExtractFields(c2)
+	require.Equal(t, Fields{"a", "1", "b", "2"}, f)
+
+	f = Fields{"a", "changed"}.WithUnique(f)
+	require.Equal(t, Fields{"a", "changed", "b", "2"}, f)
+
+	c3 := InjectFields(c, f)
+
+	// Old contexts should be untouched.
+	f = ExtractFields(c)
+	require.Equal(t, Fields(nil), f)
+	f = ExtractFields(c2)
+	require.Equal(t, Fields{"a", "1", "b", "2"}, f)
+	f = ExtractFields(c3)
+	require.Equal(t, Fields{"a", "changed", "b", "2"}, f)
+}

interceptors/logging/options.go

@@ -132,7 +132,7 @@ func DefaultClientCodeToLevel(code codes.Code) Level {
 
 type fieldsFromCtxFn func(ctx context.Context) Fields
 
-// WithFieldsFromContext allows adding extra fields to all log messages per given request.
+// WithFieldsFromContext allows overriding existing or adding extra fields to all log messages per given request.
 func WithFieldsFromContext(f fieldsFromCtxFn) Option {
 	return func(o *options) {
 		o.fieldsFromCtxFn = f