Merge pull request #13 from bstasyszyn/log-correlation-id

feat: Log the correlation ID

.github/workflows/build.yml

@@ -7,7 +7,7 @@
 name: "logutil ci"
 
 env:
-  GO_VERSION: 1.19
+  GO_VERSION: 1.23
 
 on:
   push:

.golangci.yml

@@ -12,7 +12,7 @@ run:
   # Define the Go version limit.
   # Mainly related to generics support in go1.18.
   # Default: use Go version from the go.mod file, fallback on the env var `GOVERSION`, fallback on 1.19
-  go: "1.19"
+  go: "1.23"
 
 
 # All possible options can be found here: https://github.com/golangci/golangci-lint/blob/master/.golangci.reference.yml

pkg/log/fields.go

@@ -18,21 +18,22 @@ import (
 
 // Log Fields.
 const (
-	FieldAddress      = "address"
-	FieldDuration     = "duration"
-	FieldHTTPStatus   = "httpStatus"
-	FieldID           = "id"
-	FieldName         = "name"
-	FieldPath         = "path"
-	FieldResponse     = "response"
-	FieldState        = "state"
-	FieldToken        = "token"
-	FieldTopic        = "topic"
-	FieldTxID         = "txID"
-	FieldURL          = "url"
-	FieldTraceID      = "trace_id"
-	FieldSpanID       = "span_id"
-	FieldParentSpanID = "parent_span_id"
+	FieldAddress       = "address"
+	FieldDuration      = "duration"
+	FieldHTTPStatus    = "httpStatus"
+	FieldID            = "id"
+	FieldName          = "name"
+	FieldPath          = "path"
+	FieldResponse      = "response"
+	FieldState         = "state"
+	FieldToken         = "token"
+	FieldTopic         = "topic"
+	FieldTxID          = "txID"
+	FieldURL           = "url"
+	FieldTraceID       = "trace_id"
+	FieldSpanID        = "span_id"
+	FieldParentSpanID  = "parent_span_id"
+	FieldCorrelationID = "correlation_id"
 )
 
 // WithError sets the error field.
@@ -106,6 +107,11 @@ func WithTracing(ctx context.Context) zap.Field {
 	return zap.Inline(&otelMarshaller{ctx: ctx})
 }
 
+// WithCorrelationID sets the correlation_id field.
+func WithCorrelationID(value string) zap.Field {
+	return zap.String(FieldCorrelationID, value)
+}
+
 // otelMarshaller is an OpenTelemetry marshaller which adds Open-Telemetry
 // trace and span IDs (as well as parent span ID if exists) to the log message.
 type otelMarshaller struct {

pkg/log/fields_test.go

@@ -92,7 +92,6 @@ func TestStandardFields(t *testing.T) {
 		span2.End()
 		span.End()
 
-		t.Logf(stdOut.String())
 		l := unmarshalLogData(t, stdOut.Bytes())
 
 		require.Equal(t, span2.SpanContext().TraceID().String(), l.TraceID)

pkg/otel/api/api.go

@@ -8,7 +8,7 @@ package api
 
 const (
 	// CorrelationIDHeader is the HTTP header key for the correlation ID.
-	CorrelationIDHeader = "X-Correlation-ID"
+	CorrelationIDHeader = "X-Correlation-Id"
 
 	// CorrelationIDAttribute is the Open Telemetry span attribute key for the correlation ID.
 	CorrelationIDAttribute = "dts.correlation_id"

pkg/otel/correlationid/correlationid.go

@@ -17,6 +17,7 @@ import (
 
 	"go.opentelemetry.io/otel/trace"
 
+	"github.com/trustbloc/logutil-go/pkg/log"
 	"github.com/trustbloc/logutil-go/pkg/otel/api"
 )
 
@@ -25,6 +26,8 @@ const (
 	correlationIDLength = 8
 )
 
+var logger = log.New("correlationid")
+
 type contextKey struct{}
 
 // Set derives the correlation ID from the OpenTelemetry trace ID and sets it on the returned context.
@@ -35,12 +38,16 @@ func Set(ctx context.Context) (context.Context, string, error) {
 	traceID := trace.SpanFromContext(ctx).SpanContext().TraceID().String()
 	if traceID != "" && traceID != nilTraceID {
 		correlationID = deriveID(traceID)
+
+		logger.Debugc(ctx, "Derived correlation ID from trace ID", log.WithCorrelationID(correlationID))
 	} else {
 		var err error
 		correlationID, err = generateID()
 		if err != nil {
 			return nil, "", fmt.Errorf("generate correlation ID: %w", err)
 		}
+
+		logger.Debug("Generated correlation ID", log.WithCorrelationID(correlationID))
 	}
 
 	return context.WithValue(ctx, contextKey{}, correlationID), correlationID, nil

pkg/otel/correlationidecho/correlationecho.go

@@ -8,20 +8,27 @@ package correlationidecho
 
 import (
 	"github.com/labstack/echo/v4"
-	"github.com/trustbloc/logutil-go/pkg/otel/api"
 	"go.opentelemetry.io/otel/attribute"
 	"go.opentelemetry.io/otel/trace"
+
+	"github.com/trustbloc/logutil-go/pkg/log"
+	"github.com/trustbloc/logutil-go/pkg/otel/api"
 )
 
+var logger = log.New("correlationid-echo")
+
 // Middleware reads the X-Correlation-Id header and, if found, sets the
 // dts.correlation_id attribute on the current span.
 func Middleware() echo.MiddlewareFunc {
 	return func(next echo.HandlerFunc) echo.HandlerFunc {
 		return func(c echo.Context) error {
-			correlationID := c.Request().Header.Get(api.CorrelationIDHeader)
-			if correlationID != "" {
-				span := trace.SpanFromContext(c.Request().Context())
+			if correlationID := c.Request().Header.Get(api.CorrelationIDHeader); correlationID != "" {
+				ctx := c.Request().Context()
+
+				span := trace.SpanFromContext(ctx)
 				span.SetAttributes(attribute.String(api.CorrelationIDAttribute, correlationID))
+
+				logger.Infoc(ctx, "Received HTTP request", log.WithCorrelationID(correlationID))
 			}
 
 			return next(c)

pkg/otel/correlationidecho/correlationecho_test.go

@@ -7,32 +7,38 @@ SPDX-License-Identifier: Apache-2.0
 package correlationidecho
 
 import (
+	"context"
 	"net/http"
 	"net/http/httptest"
 	"testing"
 
 	"github.com/labstack/echo/v4"
 	"github.com/stretchr/testify/require"
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/sdk/trace"
 )
 
 func TestMiddleware(t *testing.T) {
 	const correlationID1 = "correlationID1"
 
 	m := Middleware()
 
-	handler := m(func(c echo.Context) error {
+	handler := m(func(echo.Context) error {
 		return nil
 	})
 	require.NotNil(t, handler)
 
-	e := echo.New()
-	req := httptest.NewRequest(http.MethodGet, "/", nil)
+	otel.SetTracerProvider(trace.NewTracerProvider())
+
+	ctx, span := otel.GetTracerProvider().Tracer("test").Start(context.Background(), "test")
+	defer span.End()
+
+	req := httptest.NewRequestWithContext(ctx, http.MethodGet, "/", nil)
 	req.Header.Set("X-Correlation-Id", correlationID1)
 
 	rec := httptest.NewRecorder()
 
-	ctx := e.NewContext(req, rec)
+	ectx := echo.New().NewContext(req, rec)
 
-	err := handler(ctx)
-	require.NoError(t, err)
+	require.NoError(t, handler(ectx))
 }

scripts/check_lint.sh

@@ -10,7 +10,7 @@ set -e
 echo "Running $0"
 
 DOCKER_CMD=${DOCKER_CMD:-docker}
-GOLANGCI_LINT_IMAGE="golangci/golangci-lint:v1.50.1"
+GOLANGCI_LINT_IMAGE="golangci/golangci-lint:v1.61.0"
 
 if [ ! $(command -v ${DOCKER_CMD}) ]; then
     exit 0