Merge pull request #105 from evanofslack/trace

Improve tracing

backend/cmd/analogdb/main.go

@@ -39,20 +39,25 @@ func main() {
 	}
 
 	// create logger instance
-	logger, err := logger.New(cfg.Log.Level, cfg.App.Env)
+	logger, err := logger.New(cfg.Log.Level, cfg.App.Env, cfg.App.Name)
 	if err != nil {
 		err = fmt.Errorf("Failed to create logger: %w", err)
 		fatal(nil, err)
 	}
-	logger.Info().Str("app", cfg.App.Name).Str("version", cfg.App.Version).Str("env", cfg.App.Env).Str("loglevel", cfg.Log.Level).Msg("Initializing application")
+	logger.Info().Str("version", cfg.App.Version).Str("env", cfg.App.Env).Str("loglevel", cfg.Log.Level).Msg("Initializing application")
 
 	// add slack webhook to logger to notify on error
 	if webhookURL := cfg.Log.WebhookURL; webhookURL != "" && cfg.App.Env != "debug" {
 		logger = logger.WithSlackNotifier(webhookURL)
 	}
 
+	// add otel tracing to logger if enabled
+	if cfg.Tracing.Enabled {
+		logger = logger.WithTracer(cfg.App.Name)
+	}
+
 	// initialize otlp tracing
-	tracingLogger := logger.WithService("tracer")
+	tracingLogger := logger.WithSubsystem("tracer")
 	tracer, err := tracer.New(tracingLogger, cfg)
 	if err != nil {
 		err = fmt.Errorf("Failed to initialize otlp tracing: %w", err)
@@ -64,7 +69,7 @@ func main() {
 	}
 
 	// initialize prometheus metrics
-	metricsLogger := logger.WithService("metrics")
+	metricsLogger := logger.WithSubsystem("metrics")
 	metrics, err := metrics.New(metricsLogger)
 	if err != nil {
 		err = fmt.Errorf("Failed to initialize prometheus metrics: %w", err)
@@ -76,15 +81,15 @@ func main() {
 	}
 
 	// open connection to postgres
-	dbLogger := logger.WithService("database")
+	dbLogger := logger.WithSubsystem("database")
 	db := postgres.NewDB(cfg.DB.URL, dbLogger, cfg.Tracing.Enabled)
 	if err := db.Open(); err != nil {
 		err = fmt.Errorf("Failed to startup database: %w", err)
 		fatal(logger, err)
 	}
 
 	// open connection to weaviate
-	dbVecLogger := logger.WithService("vector-database")
+	dbVecLogger := logger.WithSubsystem("vector-database")
 	dbVec := weaviate.NewDB(cfg.VectorDB.Host, cfg.VectorDB.Scheme, dbVecLogger, tracer)
 	if err := dbVec.Open(); err != nil {
 		err = fmt.Errorf("Failed to startup vector database: %w", err)
@@ -99,7 +104,7 @@ func main() {
 	// open connection to redis if cache enabled
 	var rdb *redis.RDB
 	if cfg.App.CacheEnabled {
-		redisLogger := logger.WithService("redis")
+		redisLogger := logger.WithSubsystem("redis")
 		rdb, err = redis.NewRDB(cfg.Redis.URL, redisLogger, metrics, cfg.Tracing.Enabled)
 		if err != nil {
 			err = fmt.Errorf("Failed to startup redis: %w", err)
@@ -112,7 +117,7 @@ func main() {
 	}
 
 	// initialize http server
-	httpLogger := logger.WithService("http")
+	httpLogger := logger.WithSubsystem("http")
 	server := server.New(cfg.HTTP.Port, httpLogger, metrics, cfg)
 
 	// need to clean up this dependency injection

backend/docker-compose.yaml

@@ -76,14 +76,15 @@ services:
     # - redis:/bitnami/redis/data
 
   weaviate:
+    image: semitechnologies/weaviate:1.18.3
+    container_name: weaviate
     command:
       - --host
       - 0.0.0.0
       - --port
       - "8080"
       - --scheme
       - http
-    image: semitechnologies/weaviate:1.18.3
     ports:
       - 8081:8080
       - 9092:2112
@@ -109,6 +110,7 @@ services:
 
   i2v-neural:
     image: semitechnologies/img2vec-pytorch:resnet50
+    container_name: weaviate-i2v
     ports:
       - 8082:8080
     restart: unless-stopped

backend/go.mod

@@ -18,7 +18,7 @@ require (
 	github.com/redis/go-redis/extra/redisprometheus/v9 v9.0.5
 	github.com/redis/go-redis/v9 v9.0.5
 	github.com/riandyrn/otelchi v0.5.1
-	github.com/rs/zerolog v1.29.1
+	github.com/rs/zerolog v1.30.0
 	github.com/weaviate/weaviate v1.18.3
 	github.com/weaviate/weaviate-go-client/v4 v4.7.0
 	go.nhat.io/otelsql v0.11.0
@@ -79,7 +79,7 @@ require (
 	golang.org/x/net v0.7.0 // indirect
 	golang.org/x/oauth2 v0.5.0 // indirect
 	golang.org/x/sync v0.2.0 // indirect
-	golang.org/x/sys v0.8.0 // indirect
+	golang.org/x/sys v0.10.0 // indirect
 	golang.org/x/text v0.7.0 // indirect
 	google.golang.org/appengine v1.6.7 // indirect
 	google.golang.org/genproto v0.0.0-20220617124728-180714bec0ad // indirect

backend/go.sum

@@ -1013,8 +1013,11 @@ github.com/rogpeppe/go-internal v1.8.1/go.mod h1:JeRgkft04UBgHMgCIwADu4Pn6Mtm5d4
 github.com/rs/cors v1.5.0/go.mod h1:gFx+x8UowdsKA9AchylcLynDq+nNFfI8FkUZdN/jGCU=
 github.com/rs/xid v1.2.1/go.mod h1:+uKXf+4Djp6Md1KODXJxgGQPKngRmWyn10oCKFzNHOQ=
 github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
 github.com/rs/zerolog v1.29.1 h1:cO+d60CHkknCbvzEWxP0S9K6KqyTjrCNUy1LdQLCGPc=
 github.com/rs/zerolog v1.29.1/go.mod h1:Le6ESbR7hc+DP6Lt1THiV8CQSdkkNrd3R0XbEgp3ZBU=
+github.com/rs/zerolog v1.30.0 h1:SymVODrcRsaRaSInD9yQtKbtWqwsfoPcRff/oRXLj4c=
+github.com/rs/zerolog v1.30.0/go.mod h1:/tk+P47gFdPXq4QYjvCmT5/Gsug2nagsFWBWhAiSi1w=
 github.com/russross/blackfriday v1.6.0/go.mod h1:ti0ldHuxg49ri4ksnFxlkCfN+hvslNlmVHqNRXXJNAY=
 github.com/russross/blackfriday/v2 v2.0.1/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
 github.com/ruudk/golang-pdf417 v0.0.0-20181029194003-1af4ab5afa58/go.mod h1:6lfFZQK844Gfx8o5WFuvpxWRwnSoipWe/p622j1v06w=
@@ -1564,6 +1567,8 @@ golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.8.0 h1:EBmGv8NaZBZTWvrbjNoL6HVt+IVy3QDQpJs7VRIw3tU=
 golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.10.0 h1:SqMFp9UcQJZa+pmYuAKjd9xq1f0j5rLcDIk0mj4qAsA=
+golang.org/x/sys v0.10.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20201117132131-f5c789dd3221/go.mod h1:Nr5EML6q2oocZ2LXRh80K7BxOlk5/8JxuGnuhpl+muw=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/term v0.0.0-20210220032956-6a3ed077a48d/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=

backend/logger/logger.go

@@ -15,7 +15,7 @@ type Logger struct {
 	zerolog.Logger
 }
 
-func New(level string, env string) (*Logger, error) {
+func New(level , env , app string) (*Logger, error) {
 
 	switch level {
 	case "debug":
@@ -57,16 +57,18 @@ func New(level string, env string) (*Logger, error) {
 		With().
 		Caller().
 		Timestamp().
+		Str("app", app).
 		Logger()
 
+
 	logger := Logger{zerologger}
 	logger.Debug().Msg("Created new base logger")
 	return &logger, nil
 }
 
-func (l Logger) WithService(name string) *Logger {
-	serviceLogger := l.Logger.With().Str("service", name).Logger()
-	serviceLogger.Debug().Msg("Created new service logger")
+func (l Logger) WithSubsystem(name string) *Logger {
+	serviceLogger := l.Logger.With().Str("subsystem", name).Logger()
+	serviceLogger.Debug().Msg("Created new subsystem logger")
 	return &Logger{
 		serviceLogger,
 	}
@@ -75,8 +77,18 @@ func (l Logger) WithService(name string) *Logger {
 func (l Logger) WithSlackNotifier(url string) *Logger {
 	notifier := newSlackNotifier(url)
 	slackLogger := l.Hook(notifier)
-	slackLogger.Debug().Msg("Added slack notifier to logger")
+	slackLogger.Info().Msg("Added slack notifier to logger")
 	return &Logger{
 		slackLogger,
 	}
 }
+
+func (l Logger) WithTracer(serviceName string) *Logger {
+
+	tracer := newTracerHook(serviceName)
+	tracerLogger := l.Hook(tracer)
+	tracerLogger.Info().Msg("Added tracer to logger")
+	return &Logger{
+		tracerLogger,
+	}
+}

backend/logger/middleware.go

@@ -15,21 +15,24 @@ func Middleware(logger *Logger) func(next http.Handler) http.Handler {
 			start := time.Now()
 			log := logger.With().Logger()
 			ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
+			ctx := r.Context()
 
 			defer func() {
 				// Recover and record stack traces in case of a panic
 				if rec := recover(); rec != nil {
 					log.Error().
+						Ctx(ctx).
 						Str("type", "error").
 						Timestamp().
 						Interface("recover_info", rec).
 						Bytes("debug_stack", debug.Stack()).
-						Msg("log system error")
+						Msg("Log system error")
 					http.Error(ww, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
 				}
 
 				// log end request
 				log.Info().
+					Ctx(ctx).
 					Str("type", "access").
 					Timestamp().
 					Fields(map[string]interface{}{
@@ -43,7 +46,7 @@ func Middleware(logger *Logger) func(next http.Handler) http.Handler {
 						"bytes_in":   r.Header.Get("Content-Length"),
 						"bytes_out":  ww.BytesWritten(),
 					}).
-					Msg("incoming_request")
+					Msg("Incoming request")
 			}()
 
 			next.ServeHTTP(ww, r)

backend/logger/slack.go

@@ -66,11 +66,8 @@ func (slackhook *SlackHook) shouldNotify(message string) bool {
 	return false
 }
 
-func (slackhook *SlackHook) Run(
-	e *zerolog.Event,
-	level zerolog.Level,
-	message string,
-) {
+func (slackhook *SlackHook) Run(e *zerolog.Event, level zerolog.Level, message string) {
+
 	// if the level is less than our notify threshold, don't notify
 	if level <= zerolog.WarnLevel {
 		return

backend/logger/tracer.go

@@ -0,0 +1,31 @@
+package logger
+
+import (
+	"github.com/rs/zerolog"
+	"go.opentelemetry.io/otel/trace"
+)
+
+type tracingHook struct {
+	serviceName string
+}
+
+func newTracerHook(serviceName string) *tracingHook {
+	return &tracingHook{
+		serviceName: serviceName,
+	}
+}
+
+func (t tracingHook) Run(e *zerolog.Event, level zerolog.Level, message string) {
+
+	// grab the context from the logger.
+	// the logger caller pass in its current context.
+	ctx := e.GetCtx()
+
+	// grab the span and trace id from the context
+	spanCtx := trace.SpanContextFromContext(ctx)
+	if spanCtx.IsValid() {
+		e.Str("span_id", spanCtx.SpanID().String())
+		e.Str("trace_id", spanCtx.TraceID().String())
+		e.Str("service.name", t.serviceName)
+	}
+}

backend/postgres/author.go

@@ -20,7 +20,9 @@ func NewAuthorService(db *DB) *AuthorService {
 
 func (s *AuthorService) FindAuthors(ctx context.Context) ([]string, error) {
 
-	s.db.logger.Debug().Msg("Starting find authors")
+	s.db.logger.Debug().Ctx(ctx).Msg("Starting find authors")
+	defer s.db.logger.Debug().Ctx(ctx).Msg("Finished find authors")
+
 	tx, err := s.db.db.BeginTx(ctx, nil)
 	if err != nil {
 		return nil, err
@@ -32,8 +34,6 @@ func (s *AuthorService) FindAuthors(ctx context.Context) ([]string, error) {
 		return nil, err
 	}
 
-	s.db.logger.Debug().Msg("Finished find authors")
-
 	return authors, nil
 }