RA-7777: Implement logging of timing events in the trillian ctfe

go.mod

@@ -11,6 +11,7 @@ require (
 	github.com/golang/mock v1.7.0-rc.1
 	github.com/google/go-cmp v0.7.0
 	github.com/google/trillian v1.7.2
+	github.com/google/uuid v1.6.0
 	github.com/gorilla/mux v1.8.1
 	github.com/hashicorp/golang-lru/v2 v2.0.7
 	github.com/jackc/pgx/v5 v5.7.5
@@ -19,6 +20,7 @@ require (
 	github.com/prometheus/client_golang v1.22.0
 	github.com/rs/cors v1.11.1
 	github.com/sergi/go-diff v1.4.0
+	github.com/sirupsen/logrus v1.9.3
 	github.com/spf13/cobra v1.9.1
 	github.com/spf13/pflag v1.0.6
 	github.com/tomasen/realip v0.0.0-20180522021738-f0c99a92ddce
@@ -71,7 +73,6 @@ require (
 	github.com/golang/protobuf v1.5.4 // indirect
 	github.com/google/btree v1.1.3 // indirect
 	github.com/google/s2a-go v0.1.9 // indirect
-	github.com/google/uuid v1.6.0 // indirect
 	github.com/googleapis/enterprise-certificate-proxy v0.3.5 // indirect
 	github.com/googleapis/gax-go/v2 v2.14.1 // indirect
 	github.com/gorilla/websocket v1.5.1 // indirect
@@ -101,7 +102,6 @@ require (
 	github.com/prometheus/procfs v0.15.1 // indirect
 	github.com/prometheus/prometheus v0.51.0 // indirect
 	github.com/rivo/uniseg v0.4.7 // indirect
-	github.com/sirupsen/logrus v1.9.3 // indirect
 	github.com/soheilhy/cmux v0.1.5 // indirect
 	github.com/spiffe/go-spiffe/v2 v2.5.0 // indirect
 	github.com/stretchr/testify v1.10.0 // indirect

trillian/ctfe/ct_server/main.go

@@ -33,6 +33,8 @@ import (
 	"syscall"
 	"time"
 
+	"github.com/google/certificate-transparency-go/trillian/ctfe/logging"
+
 	"github.com/google/certificate-transparency-go/trillian/ctfe"
 	"github.com/google/certificate-transparency-go/trillian/ctfe/cache"
 	"github.com/google/certificate-transparency-go/trillian/ctfe/configpb"
@@ -136,6 +138,7 @@ func main() {
 	}
 
 	klog.CopyStandardLogTo("WARNING")
+
 	klog.Info("**** CT HTTP Server Starting ****")
 
 	metricsAt := *metricsEndpoint
@@ -448,7 +451,7 @@ func setupAndRegister(ctx context.Context, client trillian.TrillianLogClient, de
 		return nil, err
 	}
 	for path, handler := range inst.Handlers {
-		mux.Handle(lhp+path, handler)
+		mux.Handle(lhp+path, logging.Middleware(handler))
 	}
 	return inst, nil
 }

trillian/ctfe/handlers.go

@@ -32,13 +32,15 @@ import (
 
 	"github.com/google/certificate-transparency-go/asn1"
 	"github.com/google/certificate-transparency-go/tls"
+	"github.com/google/certificate-transparency-go/trillian/ctfe/logging"
 	"github.com/google/certificate-transparency-go/trillian/util"
 	"github.com/google/certificate-transparency-go/x509"
 	"github.com/google/certificate-transparency-go/x509util"
 	"github.com/google/trillian"
 	"github.com/google/trillian/monitoring"
 	"github.com/google/trillian/types"
 	"google.golang.org/grpc/codes"
+	"google.golang.org/grpc/metadata"
 	"google.golang.org/grpc/status"
 	"google.golang.org/protobuf/encoding/prototext"
 	"k8s.io/klog/v2"
@@ -198,6 +200,18 @@ func (a AppHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	// Many/most of the handlers forward the request on to the Log RPC server; impose a deadline
 	// on this onward request.
 	ctx, cancel := context.WithDeadline(logCtx, getRPCDeadlineTime(a.Info))
+	txID, ok := logCtx.Value(logging.CtxKeyTxID).(string)
+	if !ok || txID == "" {
+		klog.Warning("Missing transaction_id in context")
+		txID = "unknown"
+	}
+	spanID, ok := logCtx.Value(logging.CtxKeySpanID).(string)
+	if !ok || spanID == "" {
+		klog.Warning("Missing span_id in context")
+		spanID = "unknown"
+	}
+	md := metadata.Pairs("X-Transaction-ID", txID, "X-Span-ID", spanID)
+	ctx = metadata.NewOutgoingContext(ctx, md)
 	defer cancel()
 
 	var err error

trillian/ctfe/logging/logger.go

@@ -0,0 +1,155 @@
+package logging
+
+import (
+	"context"
+	"fmt"
+	"net/http"
+	"time"
+
+	"github.com/google/uuid"
+	"github.com/sirupsen/logrus"
+	"google.golang.org/grpc"
+	"google.golang.org/grpc/metadata"
+)
+
+type contextKey string
+
+const (
+	CtxKeyTxID   contextKey = "transaction_id"
+	CtxKeySpanID contextKey = "span_id"
+)
+
+var log = logrus.New()
+
+func init() {
+	log.Formatter = &logrus.JSONFormatter{
+		TimestampFormat: "2006-01-02T15:04:05.000Z07:00",
+	}
+}
+
+func generateUUID() string {
+	return uuid.New().String()
+}
+
+func WithContext(r *http.Request) context.Context {
+	txID := r.Header.Get("X-Transaction-ID")
+	if txID == "" {
+		txID = generateUUID()
+	}
+
+	spanID := generateUUID()
+	ctx := context.WithValue(r.Context(), CtxKeyTxID, txID)
+	ctx = context.WithValue(ctx, CtxKeySpanID, spanID)
+	return ctx
+}
+
+func WithGRPCContext(ctx context.Context) context.Context {
+	// First check if there's already a transaction_id in the context (from HTTP)
+	txID, ok := ctx.Value(CtxKeyTxID).(string)
+	if !ok || txID == "" {
+		// If not, try to get it from gRPC metadata
+		txID = getFromMetadata(ctx, "X-Transaction-ID")
+		if txID == "" {
+			txID = generateUUID()
+		}
+	}
+
+	// Check for span_id in context first
+	spanID, ok := ctx.Value(CtxKeySpanID).(string)
+	if !ok || spanID == "" {
+		// Always generate a new span_id for this service
+		// No longer checking metadata since span_id is not propagated
+		spanID = generateUUID()
+	}
+
+	ctx = context.WithValue(ctx, CtxKeyTxID, txID)
+	ctx = context.WithValue(ctx, CtxKeySpanID, spanID)
+	return ctx
+}
+
+func getFromMetadata(ctx context.Context, key string) string {
+	md, ok := metadata.FromIncomingContext(ctx)
+	if !ok {
+		return ""
+	}
+	values := md.Get(key)
+	if len(values) > 0 {
+		return values[0]
+	}
+	return ""
+}
+
+// PropagateToGRPC adds the transaction_id from the context to gRPC metadata
+// This ensures transaction correlation across service boundaries
+// Note: span_id is NOT propagated - each service generates its own span_id
+func PropagateToGRPC(ctx context.Context) context.Context {
+	txID := ctx.Value(CtxKeyTxID)
+
+	if txID == nil {
+		return ctx
+	}
+
+	mdMap := map[string]string{
+		"X-Transaction-ID": txID.(string),
+	}
+	// Deliberately NOT propagating span_id - each service gets its own
+
+	md := metadata.New(mdMap)
+	return metadata.NewOutgoingContext(ctx, md)
+}
+
+func LogWithContext(ctx context.Context, eventID string, msg string, fields map[string]interface{}) {
+	lf := logrus.Fields{
+		"event_id": eventID,
+	}
+
+	// Safely extract transaction_id and span_id
+	if txID := ctx.Value(CtxKeyTxID); txID != nil {
+		lf["transaction_id"] = txID
+	}
+	if spanID := ctx.Value(CtxKeySpanID); spanID != nil {
+		lf["span_id"] = spanID
+	}
+
+	for k, v := range fields {
+		lf[k] = v
+	}
+	log.WithFields(lf).Info(msg)
+}
+
+func LogTiming(ctx context.Context, r *http.Request, status int, elapsed time.Duration) {
+	elapsedInMsStr := fmt.Sprintf("%dms", elapsed.Milliseconds())
+	LogWithContext(ctx, "timing", "request completed", map[string]interface{}{
+		"path":    r.URL.Path,
+		"method":  r.Method,
+		"status":  status,
+		"elapsed": elapsedInMsStr,
+	})
+}
+
+func UnaryServerInterceptor() grpc.UnaryServerInterceptor {
+	return func(
+		ctx context.Context,
+		req interface{},
+		info *grpc.UnaryServerInfo,
+		handler grpc.UnaryHandler,
+	) (interface{}, error) {
+		ctx = WithGRPCContext(ctx)
+		start := time.Now()
+		resp, err := handler(ctx, req)
+		elapsed := time.Since(start)
+		LogWithContext(ctx, "timing", "gRPC call completed", map[string]interface{}{
+			"method":  info.FullMethod,
+			"status":  statusCodeFromError(err),
+			"elapsed": elapsed.Milliseconds(),
+		})
+		return resp, err
+	}
+}
+
+func statusCodeFromError(err error) string {
+	if err == nil {
+		return "OK"
+	}
+	return err.Error()
+}