gcp/observability: Link logs and traces by logging Trace and Span IDs (…

…#6056)
grpc · Mar 9, 2023 · 55d8783 · 55d8783
1 parent ad4057f
commit 55d8783
Show file tree

Hide file tree

Showing 15 changed files with 673 additions and 54 deletions.
diff --git a/gcp/observability/go.mod b/gcp/observability/go.mod
@@ -39,3 +39,5 @@ require (
 )
 
 replace google.golang.org/grpc => ../../
+
+replace google.golang.org/grpc/stats/opencensus => ../../stats/opencensus
diff --git a/gcp/observability/go.sum b/gcp/observability/go.sum
@@ -1056,8 +1056,6 @@ google.golang.org/genproto v0.0.0-20221202195650-67e5cbc046fd/go.mod h1:cTsE614G
 google.golang.org/genproto v0.0.0-20230110181048-76db0878b65f h1:BWUVssLB0HVOSY78gIdvk1dTVYtT1y8SBWtPYuTJ/6w=
 google.golang.org/genproto v0.0.0-20230110181048-76db0878b65f/go.mod h1:RGgjbofJ8xD9Sq1VVhDM1Vok1vRONV+rg+CjzG4SZKM=
 google.golang.org/grpc/cmd/protoc-gen-go-grpc v1.1.0/go.mod h1:6Kw0yEErY5E/yWrBtf03jp27GLLJujG4z/JK95pnjjw=
-google.golang.org/grpc/stats/opencensus v0.0.0-20230221205128-8702a2ebf4b0 h1:v7h+HONu0plE0b3y9fBiOWlsqTdQQ5A9l9Ag2LXbEoE=
-google.golang.org/grpc/stats/opencensus v0.0.0-20230221205128-8702a2ebf4b0/go.mod h1:l7+BYcyrDJFQo8nh4v8h5TJ6VfQ9QGBfFqVO7xoqQzI=
 google.golang.org/protobuf v0.0.0-20200109180630-ec00e32a8dfd/go.mod h1:DFci5gLYBciE7Vtevhsrf46CRTquxDuWsQurQQe4oz8=
 google.golang.org/protobuf v0.0.0-20200221191635-4d8936d0db64/go.mod h1:kwYJMbMJ01Woi6D6+Kah6886xMZcty6N08ah7+eCXa0=
 google.golang.org/protobuf v0.0.0-20200228230310-ab0ca4ff8a60/go.mod h1:cfTl7dwQJ+fmap5saPgwCLgHXTUD7jkjRqWcaiX5VyM=

diff --git a/gcp/observability/logging.go b/gcp/observability/logging.go
@@ -29,13 +29,15 @@ import (
 
 	gcplogging "cloud.google.com/go/logging"
 	"github.com/google/uuid"
+	"go.opencensus.io/trace"
 
 	"google.golang.org/grpc"
 	binlogpb "google.golang.org/grpc/binarylog/grpc_binarylog_v1"
 	"google.golang.org/grpc/internal"
 	"google.golang.org/grpc/internal/binarylog"
 	iblog "google.golang.org/grpc/internal/binarylog"
 	"google.golang.org/grpc/internal/grpcutil"
+	"google.golang.org/grpc/stats/opencensus"
 )
 
 var lExporter loggingExporter
@@ -237,13 +239,16 @@ type methodLoggerBuilder interface {
 }
 
 type binaryMethodLogger struct {
-	callID, serviceName, methodName, authority string
+	callID, serviceName, methodName, authority, projectID string
 
-	mlb      methodLoggerBuilder
-	exporter loggingExporter
+	mlb        methodLoggerBuilder
+	exporter   loggingExporter
+	clientSide bool
 }
 
-func (bml *binaryMethodLogger) Log(c iblog.LogEntryConfig) {
+// buildGCPLoggingEntry converts the binary log log entry into a gcp logging
+// entry.
+func (bml *binaryMethodLogger) buildGCPLoggingEntry(ctx context.Context, c iblog.LogEntryConfig) gcplogging.Entry {
 	binLogEntry := bml.mlb.Build(c)
 
 	grpcLogEntry := &grpcLogEntry{
@@ -305,9 +310,6 @@ func (bml *binaryMethodLogger) Log(c iblog.LogEntryConfig) {
 		setPeerIfPresent(binLogEntry, grpcLogEntry)
 	case binlogpb.GrpcLogEntry_EVENT_TYPE_CANCEL:
 		grpcLogEntry.Type = eventTypeCancel
-	default:
-		logger.Infof("Unknown event type: %v", binLogEntry.Type)
-		return
 	}
 	grpcLogEntry.ServiceName = bml.serviceName
 	grpcLogEntry.MethodName = bml.methodName
@@ -318,8 +320,25 @@ func (bml *binaryMethodLogger) Log(c iblog.LogEntryConfig) {
 		Severity:  100,
 		Payload:   grpcLogEntry,
 	}
+	if bml.clientSide {
+		// client side span, populated through opencensus trace package.
+		if span := trace.FromContext(ctx); span != nil {
+			sc := span.SpanContext()
+			gcploggingEntry.Trace = "projects/" + bml.projectID + "/traces/" + fmt.Sprintf("%x", sc.TraceID)
+			gcploggingEntry.SpanID = fmt.Sprintf("%x", sc.SpanID)
+		}
+	} else {
+		// server side span, populated through stats/opencensus package.
+		if tID, sID, ok := opencensus.GetTraceAndSpanID(ctx); ok {
+			gcploggingEntry.Trace = "projects/" + bml.projectID + "/traces/" + fmt.Sprintf("%x", tID)
+			gcploggingEntry.SpanID = fmt.Sprintf("%x", sID)
+		}
+	}
+	return gcploggingEntry
+}
 
-	bml.exporter.EmitGcpLoggingEntry(gcploggingEntry)
+func (bml *binaryMethodLogger) Log(ctx context.Context, c iblog.LogEntryConfig) {
+	bml.exporter.EmitGcpLoggingEntry(bml.buildGCPLoggingEntry(ctx, c))
 }
 
 type eventConfig struct {
@@ -336,7 +355,9 @@ type eventConfig struct {
 
 type binaryLogger struct {
 	EventConfigs []eventConfig
+	projectID    string
 	exporter     loggingExporter
+	clientSide   bool
 }
 
 func (bl *binaryLogger) GetMethodLogger(methodName string) iblog.MethodLogger {
@@ -352,9 +373,11 @@ func (bl *binaryLogger) GetMethodLogger(methodName string) iblog.MethodLogger {
 			}
 
 			return &binaryMethodLogger{
-				exporter: bl.exporter,
-				mlb:      iblog.NewTruncatingMethodLogger(eventConfig.HeaderBytes, eventConfig.MessageBytes),
-				callID:   uuid.NewString(),
+				exporter:   bl.exporter,
+				mlb:        iblog.NewTruncatingMethodLogger(eventConfig.HeaderBytes, eventConfig.MessageBytes),
+				callID:     uuid.NewString(),
+				projectID:  bl.projectID,
+				clientSide: bl.clientSide,
 			}
 		}
 	}
@@ -372,7 +395,8 @@ func parseMethod(method string) (string, string, error) {
 	return method[:pos], method[pos+1:], nil
 }
 
-func registerClientRPCEvents(clientRPCEvents []clientRPCEvents, exporter loggingExporter) {
+func registerClientRPCEvents(config *config, exporter loggingExporter) {
+	clientRPCEvents := config.CloudLogging.ClientRPCEvents
 	if len(clientRPCEvents) == 0 {
 		return
 	}
@@ -405,11 +429,14 @@ func registerClientRPCEvents(clientRPCEvents []clientRPCEvents, exporter logging
 	clientSideLogger := &binaryLogger{
 		EventConfigs: eventConfigs,
 		exporter:     exporter,
+		projectID:    config.ProjectID,
+		clientSide:   true,
 	}
 	internal.AddGlobalDialOptions.(func(opt ...grpc.DialOption))(internal.WithBinaryLogger.(func(bl binarylog.Logger) grpc.DialOption)(clientSideLogger))
 }
 
-func registerServerRPCEvents(serverRPCEvents []serverRPCEvents, exporter loggingExporter) {
+func registerServerRPCEvents(config *config, exporter loggingExporter) {
+	serverRPCEvents := config.CloudLogging.ServerRPCEvents
 	if len(serverRPCEvents) == 0 {
 		return
 	}
@@ -442,6 +469,8 @@ func registerServerRPCEvents(serverRPCEvents []serverRPCEvents, exporter logging
 	serverSideLogger := &binaryLogger{
 		EventConfigs: eventConfigs,
 		exporter:     exporter,
+		projectID:    config.ProjectID,
+		clientSide:   false,
 	}
 	internal.AddGlobalServerOptions.(func(opt ...grpc.ServerOption))(internal.BinaryLogger.(func(bl binarylog.Logger) grpc.ServerOption)(serverSideLogger))
 }
@@ -456,9 +485,8 @@ func startLogging(ctx context.Context, config *config) error {
 		return fmt.Errorf("unable to create CloudLogging exporter: %v", err)
 	}
 
-	cl := config.CloudLogging
-	registerClientRPCEvents(cl.ClientRPCEvents, lExporter)
-	registerServerRPCEvents(cl.ServerRPCEvents, lExporter)
+	registerClientRPCEvents(config, lExporter)
+	registerServerRPCEvents(config, lExporter)
 	return nil
 }
 

diff --git a/gcp/observability/logging_test.go b/gcp/observability/logging_test.go
@@ -68,6 +68,8 @@ type fakeLoggingExporter struct {
 
 	mu      sync.Mutex
 	entries []*grpcLogEntry
+
+	idsSeen []*traceAndSpanIDString
 }
 
 func (fle *fakeLoggingExporter) EmitGcpLoggingEntry(entry gcplogging.Entry) {
@@ -76,6 +78,13 @@ func (fle *fakeLoggingExporter) EmitGcpLoggingEntry(entry gcplogging.Entry) {
 	if entry.Severity != 100 {
 		fle.t.Errorf("entry.Severity is not 100, this should be hardcoded")
 	}
+
+	ids := &traceAndSpanIDString{
+		traceID: entry.Trace,
+		spanID:  entry.SpanID,
+	}
+	fle.idsSeen = append(fle.idsSeen, ids)
+
 	grpcLogEntry, ok := entry.Payload.(*grpcLogEntry)
 	if !ok {
 		fle.t.Errorf("payload passed in isn't grpcLogEntry")
Original file line number	Diff line number	Diff line change
Expand Up		@@ -39,3 +39,5 @@ require (
		)

		replace google.golang.org/grpc => ../../

		replace google.golang.org/grpc/stats/opencensus => ../../stats/opencensus