grpc logging and tracing

cmd/grpcserver/grpc.go

@@ -3,14 +3,21 @@
 package main
 
 import (
+	"context"
 	"fmt"
 	"github.com/anytypeio/go-anytype-middleware/metrics"
+	grpc_middleware "github.com/grpc-ecosystem/go-grpc-middleware"
+	grpc_zap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap"
 	grpc_prometheus "github.com/grpc-ecosystem/go-grpc-prometheus"
+	"github.com/grpc-ecosystem/grpc-opentracing/go/otgrpc"
+	"github.com/opentracing/opentracing-go"
+	"github.com/uber/jaeger-client-go"
 	"net"
 	"net/http"
 	_ "net/http/pprof"
 	"os"
 	"os/signal"
+	"strconv"
 	"syscall"
 
 	"github.com/anytypeio/go-anytype-middleware/core/event"
@@ -21,6 +28,8 @@ import (
 
 	"github.com/anytypeio/go-anytype-middleware/core"
 	"github.com/anytypeio/go-anytype-middleware/pb/service"
+
+	jaegercfg "github.com/uber/jaeger-client-go/config"
 )
 
 const defaultAddr = "127.0.0.1:31007"
@@ -82,13 +91,74 @@ func main() {
 		log.Fatalf("failed to listen: %v", err)
 	}
 	webaddr = webLis.Addr().String()
+	var (
+		unaryInterceptors  []grpc.UnaryServerInterceptor
+		streamInterceptors []grpc.StreamServerInterceptor
+	)
 
-	var unaryServerInterceptor grpc.UnaryServerInterceptor
 	if metrics.Enabled {
-		unaryServerInterceptor = grpc_prometheus.UnaryServerInterceptor
+		unaryInterceptors = append(unaryInterceptors, grpc_prometheus.UnaryServerInterceptor)
 	}
 
-	server := grpc.NewServer(grpc.MaxRecvMsgSize(20*1024*1024), grpc.UnaryInterceptor(unaryServerInterceptor))
+	grpcDebug, _ := strconv.Atoi(os.Getenv("ANYTYPE_GRPC_LOG"))
+	if grpcDebug > 0 {
+		decider := func(_ context.Context, _ string, _ interface{}) bool {
+			return true
+		}
+
+		grpcLogger := logging.Logger("grpc")
+
+		unaryInterceptors = append(unaryInterceptors, grpc_zap.UnaryServerInterceptor(grpcLogger.Desugar()))
+		streamInterceptors = append(streamInterceptors, grpc_zap.StreamServerInterceptor(grpcLogger.Desugar()))
+		if grpcDebug > 1 {
+			unaryInterceptors = append(unaryInterceptors, grpc_zap.PayloadUnaryServerInterceptor(grpcLogger.Desugar(), decider))
+		}
+		if grpcDebug > 2 {
+			streamInterceptors = append(streamInterceptors, grpc_zap.PayloadStreamServerInterceptor(grpcLogger.Desugar(), decider))
+		}
+	}
+
+	grpcTrace, _ := strconv.Atoi(os.Getenv("ANYTYPE_GRPC_TRACE"))
+	if grpcTrace > 0 {
+		jLogger := jaeger.StdLogger
+
+		cfg, err := jaegercfg.FromEnv()
+		if err != nil {
+			log.Fatal(err.Error())
+		}
+		if cfg.ServiceName == "" {
+			cfg.ServiceName = "mw"
+		}
+		// Initialize tracer with a logger and a metrics factory
+		tracer, closer, err := cfg.NewTracer(jaegercfg.Logger(jLogger))
+		if err != nil {
+			log.Fatal(err.Error())
+		}
+		defer closer.Close()
+
+		var (
+			unaryOptions  []otgrpc.Option
+			streamOptions []otgrpc.Option
+		)
+
+		// Set the singleton opentracing.Tracer with the Jaeger tracer.
+		opentracing.SetGlobalTracer(tracer)
+		if grpcTrace > 1 {
+			unaryOptions = append(unaryOptions, otgrpc.LogPayloads())
+		}
+		if grpcTrace > 2 {
+			streamOptions = append(streamOptions, otgrpc.LogPayloads())
+		}
+
+		unaryInterceptors = append(unaryInterceptors, otgrpc.OpenTracingServerInterceptor(tracer, unaryOptions...))
+		streamInterceptors = append(streamInterceptors, otgrpc.OpenTracingStreamServerInterceptor(tracer, streamOptions...))
+	}
+
+	server := grpc.NewServer(grpc.MaxRecvMsgSize(20*1024*1024),
+		grpc.UnaryInterceptor(grpc_middleware.ChainUnaryServer(unaryInterceptors...)),
+		grpc.StreamInterceptor(grpc_middleware.ChainStreamServer(streamInterceptors...)),
+	)
+
 	service.RegisterClientCommandsServer(server, mw)
 	if metrics.Enabled {
 		grpc_prometheus.EnableHandlingTimeHistogram()

docker-compose.yml

@@ -24,8 +24,13 @@ services:
     image: docker.pkg.github.com/anytypeio/go-anytype-middleware/server:${TAG}
     environment:
       ANYTYPE_GRPC_ADDR: "0.0.0.0:31007"
-      ANYTYPE_GATEWAY_ADDR: "0.0.0.0:32007"
-      ANYTYPE_LOG_LEVEL: "*=DEBUG"
+      ANYTYPE_LOG_LEVEL: "anytype-mw-app=DEBUG;grpc=DEBUG;anytype-gateway=DEBUG"
+      ANYTYPE_LOG_NOGELF: 1
+      ANYTYPE_GRPC_LOG: 3
+      # local tracing
+      #ANYTYPE_GRPC_TRACE: 3
+      #JAEGER_AGENT_HOST: "docker.for.mac.localhost"
+      #JAEGER_SERVICE_NAME: "mw-a"
 
   middleware-node-b:
     stop_grace_period: 1s
@@ -34,4 +39,11 @@ services:
     environment:
       ANYTYPE_GRPC_ADDR: "0.0.0.0:41007"
       ANYTYPE_GATEWAY_ADDR: "0.0.0.0:42007"
-      ANYTYPE_LOG_LEVEL: "*=DEBUG"
+      ANYTYPE_LOG_LEVEL: "anytype-mw-app=DEBUG;grpc=DEBUG;anytype-gateway=DEBUG"
+      ANYTYPE_LOG_NOGELF: 1
+      ANYTYPE_GRPC_LOG: 3
+      # local tracing
+      #ANYTYPE_GRPC_TRACE: 3
+      #JAEGER_AGENT_HOST: "docker.for.mac.localhost"
+      #JAEGER_SERVICE_NAME: "mw-b"
+      #JAEGER_SERVICE_NAME: "mw-b"

go.mod

@@ -3,6 +3,7 @@ module github.com/anytypeio/go-anytype-middleware
 go 1.14
 
 require (
+	github.com/HdrHistogram/hdrhistogram-go v1.1.0 // indirect
 	github.com/JohannesKaufmann/html-to-markdown v0.0.0-00010101000000-000000000000
 	github.com/PuerkitoBio/goquery v1.6.1
 	github.com/anytypeio/go-slip10 v0.0.0-20200330112030-a352ca8495e4
@@ -19,7 +20,9 @@ require (
 	github.com/gogo/status v1.1.0
 	github.com/golang/mock v1.4.4
 	github.com/google/uuid v1.2.0
+	github.com/grpc-ecosystem/go-grpc-middleware v1.2.1
 	github.com/grpc-ecosystem/go-grpc-prometheus v1.2.0
+	github.com/grpc-ecosystem/grpc-opentracing v0.0.0-20180507213350-8e809c8a8645
 	github.com/h2non/filetype v1.1.1
 	github.com/hashicorp/golang-lru v0.5.4
 	github.com/hsanjuan/ipfs-lite v1.1.18
@@ -56,6 +59,7 @@ require (
 	github.com/multiformats/go-multiaddr v0.3.1
 	github.com/multiformats/go-multibase v0.0.3
 	github.com/multiformats/go-multihash v0.0.14
+	github.com/opentracing/opentracing-go v1.2.0
 	github.com/otiai10/opengraph v1.1.3
 	github.com/prometheus/client_golang v1.9.0
 	github.com/rwcarlsen/goexif v0.0.0-20190401172101-9e8deecbddbd
@@ -63,6 +67,8 @@ require (
 	github.com/stretchr/testify v1.7.0
 	github.com/textileio/go-threads v1.0.2-0.20210304072541-d0f91da84404
 	github.com/tyler-smith/go-bip39 v1.0.1-0.20190808214741-c55f737395bc
+	github.com/uber/jaeger-client-go v2.25.0+incompatible
+	github.com/uber/jaeger-lib v2.4.0+incompatible // indirect
 	github.com/yuin/goldmark v1.3.1
 	go.uber.org/zap v1.16.0
 	golang.org/x/text v0.3.5