Fix logging

Author: AchoArnold

api/go.mod

@@ -4,6 +4,7 @@ go 1.18
 
 require (
 	firebase.google.com/go v3.13.0+incompatible
+	github.com/GoogleCloudPlatform/opentelemetry-operations-go/exporter/trace v1.8.3
 	github.com/alecthomas/template v0.0.0-20190718012654-fb15b899a751
 	github.com/cheggaaa/pb/v3 v3.0.8
 	github.com/cloudevents/sdk-go/v2 v2.10.0
@@ -20,8 +21,10 @@ require (
 	github.com/swaggo/swag v1.8.2
 	github.com/thedevsaddam/govalidator v1.9.10
 	go.opentelemetry.io/otel v1.7.0
+	go.opentelemetry.io/otel/exporters/jaeger v1.7.0
+	go.opentelemetry.io/otel/sdk v1.7.0
 	go.opentelemetry.io/otel/trace v1.7.0
-	google.golang.org/api v0.73.0
+	google.golang.org/api v0.74.0
 	gorm.io/datatypes v1.0.6
 	gorm.io/driver/postgres v1.3.7
 	gorm.io/gorm v1.23.5
@@ -33,19 +36,23 @@ require (
 	cloud.google.com/go/firestore v1.6.1 // indirect
 	cloud.google.com/go/iam v0.1.1 // indirect
 	cloud.google.com/go/storage v1.21.0 // indirect
+	cloud.google.com/go/trace v1.2.0 // indirect
+	github.com/GoogleCloudPlatform/opentelemetry-operations-go/internal/resourcemapping v0.32.3 // indirect
 	github.com/KyleBanks/depth v1.2.1 // indirect
 	github.com/VividCortex/ewma v1.1.1 // indirect
 	github.com/andybalholm/brotli v1.0.4 // indirect
 	github.com/fatih/color v1.10.0 // indirect
+	github.com/go-logr/logr v1.2.3 // indirect
+	github.com/go-logr/stdr v1.2.2 // indirect
 	github.com/go-openapi/jsonpointer v0.19.5 // indirect
 	github.com/go-openapi/jsonreference v0.20.0 // indirect
 	github.com/go-openapi/spec v0.20.6 // indirect
 	github.com/go-openapi/swag v0.21.1 // indirect
 	github.com/go-sql-driver/mysql v1.6.0 // indirect
-	github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e // indirect
+	github.com/golang/groupcache v0.0.0-20210331224755-41bb18bfe9da // indirect
 	github.com/golang/protobuf v1.5.2 // indirect
 	github.com/google/go-cmp v0.5.7 // indirect
-	github.com/googleapis/gax-go/v2 v2.1.1 // indirect
+	github.com/googleapis/gax-go/v2 v2.2.0 // indirect
 	github.com/jackc/chunkreader/v2 v2.0.1 // indirect
 	github.com/jackc/pgconn v1.12.1 // indirect
 	github.com/jackc/pgio v1.0.0 // indirect
@@ -71,8 +78,8 @@ require (
 	github.com/valyala/fasthttp v1.37.0 // indirect
 	github.com/valyala/tcplisten v1.0.0 // indirect
 	go.opencensus.io v0.23.0 // indirect
-	go.uber.org/atomic v1.6.0 // indirect
-	go.uber.org/multierr v1.5.0 // indirect
+	go.uber.org/atomic v1.7.0 // indirect
+	go.uber.org/multierr v1.8.0 // indirect
 	go.uber.org/zap v1.13.0 // indirect
 	golang.org/x/crypto v0.0.0-20220517005047-85d78b3ac167 // indirect
 	golang.org/x/lint v0.0.0-20210508222113-6edffad5e616 // indirect
@@ -83,9 +90,9 @@ require (
 	golang.org/x/tools v0.1.10 // indirect
 	golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 // indirect
 	google.golang.org/appengine v1.6.7 // indirect
-	google.golang.org/genproto v0.0.0-20220310185008-1973136f34c6 // indirect
+	google.golang.org/genproto v0.0.0-20220405205423-9d709892a2bf // indirect
 	google.golang.org/grpc v1.45.0 // indirect
-	google.golang.org/protobuf v1.27.1 // indirect
+	google.golang.org/protobuf v1.28.0 // indirect
 	gopkg.in/yaml.v2 v2.4.0 // indirect
 	gorm.io/driver/mysql v1.3.2 // indirect
 )

api/go.sum

@@ -7,9 +7,18 @@ import (
 	"strconv"
 	"time"
 
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/propagation"
+	"go.opentelemetry.io/otel/sdk/resource"
+	semconv "go.opentelemetry.io/otel/semconv/v1.10.0"
+
 	"firebase.google.com/go/messaging"
+	cloudtrace "github.com/GoogleCloudPlatform/opentelemetry-operations-go/exporter/trace"
 	"github.com/hirosassa/zerodriver"
 	"github.com/rs/zerolog"
+	"go.opentelemetry.io/otel/exporters/jaeger"
+	"go.opentelemetry.io/otel/sdk/trace"
 
 	firebase "firebase.google.com/go"
 	"firebase.google.com/go/auth"
@@ -51,6 +60,8 @@ func NewContainer(projectID string) (container *Container) {
 		logger:    logger(3).WithService(fmt.Sprintf("%T", container)),
 	}
 
+	container.InitializeTraceProvider("0.0.1", os.Getenv("GCP_PROJECT_ID"))
+
 	container.RegisterMessageListeners()
 	container.RegisterMessageRoutes()
 
@@ -86,6 +97,8 @@ func (container *Container) App() (app *fiber.App) {
 		app.Use(fiberLogger.New())
 	}
 
+	app.Use(middlewares.OtelTraceContext(container.Tracer(), container.Logger(), "X-Cloud-Trace-Context", os.Getenv("GCP_PROJECT_ID")))
+
 	// Default config
 	app.Use(cors.New())
 
@@ -564,11 +577,73 @@ func (container *Container) UserRepository() repositories.UserRepository {
 	)
 }
 
+// InitializeTraceProvider initializes the open telemetry trace provider
+func (container *Container) InitializeTraceProvider(version string, namespace string) func() {
+	if isLocal() {
+		return container.initializeJaegerTraceProvider(version, namespace)
+	}
+	return container.initializeGoogleTraceProvider(version, namespace)
+}
+
+func (container *Container) initializeGoogleTraceProvider(version string, namespace string) func() {
+	container.logger.Debug("initializing google trace provider")
+
+	exporter, err := cloudtrace.New(cloudtrace.WithProjectID(os.Getenv("GCP_PROJECT_ID")))
+	if err != nil {
+		container.logger.Fatal(stacktrace.Propagate(err, "cannot create cloud trace exporter"))
+	}
+
+	tp := trace.NewTracerProvider(
+		trace.WithBatcher(exporter),
+		trace.WithSampler(trace.AlwaysSample()),
+		trace.WithResource(container.InitializeOtelResources(version, namespace)),
+	)
+
+	otel.SetTracerProvider(tp)
+
+	return func() {
+		_ = exporter.Shutdown(context.Background())
+	}
+}
+
+func (container *Container) initializeJaegerTraceProvider(version string, namespace string) (flush func()) {
+	container.logger.Debug("initializing jaeger trace provider")
+	exp, err := jaeger.New(jaeger.WithCollectorEndpoint(jaeger.WithEndpoint(os.Getenv("JAEGER_COLLECTOR_ENDPOINT"))))
+	if err != nil {
+		container.logger.Error(stacktrace.Propagate(err, "could not create jaeger exporter"))
+	}
+	tp := trace.NewTracerProvider(
+		// Always be sure to batch in production.
+		trace.WithBatcher(exp),
+		trace.WithSampler(trace.AlwaysSample()),
+		// Record information about this application in a resource.
+		trace.WithResource(container.InitializeOtelResources(version, namespace)),
+	)
+
+	otel.SetTracerProvider(tp)
+	otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator(propagation.TraceContext{}, propagation.Baggage{}))
+
+	return func() {
+		_ = exp.Shutdown(context.Background())
+	}
+}
+
+// InitializeOtelResources initializes open telemetry resources
+func (container *Container) InitializeOtelResources(version string, namespace string) *resource.Resource {
+	return resource.NewWithAttributes(
+		semconv.SchemaURL,
+		semconv.ServiceNameKey.String(namespace),
+		semconv.ServiceNamespaceKey.String(namespace),
+		semconv.ServiceVersionKey.String(version),
+		semconv.ServiceInstanceIDKey.String(hostName()),
+		attribute.String("service.environment", os.Getenv("ENV")),
+	)
+}
+
 func logger(skipFrameCount int) telemetry.Logger {
-	hostname, _ := os.Hostname()
 	fields := map[string]string{
 		"pid":      strconv.Itoa(os.Getpid()),
-		"hostname": hostname,
+		"hostname": hostName(),
 	}
 
 	return telemetry.NewZerologLogger(
@@ -612,6 +687,14 @@ func jsonLogger(skipFrameCount int) *zerodriver.Logger {
 	return &zerodriver.Logger{Logger: &zl}
 }
 
+func hostName() string {
+	h, err := os.Hostname()
+	if err != nil {
+		h = strconv.Itoa(os.Getpid())
+	}
+	return h
+}
+
 func consoleLogger(skipFrameCount int) *zerodriver.Logger {
 	l := zerolog.New(
 		zerolog.ConsoleWriter{

api/pkg/di/container.go

@@ -0,0 +1,116 @@
+package middlewares
+
+import (
+	"context"
+	"fmt"
+	"strconv"
+	"strings"
+
+	"github.com/NdoleStudio/http-sms-manager/pkg/telemetry"
+	"github.com/gofiber/fiber/v2"
+	"github.com/palantir/stacktrace"
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/trace"
+)
+
+const (
+	clientVersionHeader = "X-Client-Version"
+)
+
+// OtelTraceContext adds a trace for an HTTP request
+func OtelTraceContext(tracer telemetry.Tracer, logger telemetry.Logger, header string, namespace string) fiber.Handler {
+	return func(c *fiber.Ctx) error {
+		// Get the Context from the request
+		spanContext, errors := spanContextFromHeader(c.Get(header))
+		if len(errors) != 0 {
+			logger.Error(stacktrace.NewError(strings.Join(errors, "\n")))
+		}
+
+		if !spanContext.IsValid() {
+			if c.Get(header) != "" {
+				logger.Error(stacktrace.NewError("invalid trace context %s creating new context", c.Get(header)))
+			}
+			otelTracer := otel.Tracer(namespace)
+			_, span := otelTracer.Start(context.Background(), fmt.Sprintf("%s %s", c.Method(), c.OriginalURL()))
+			defer span.End()
+			spanContext = span.SpanContext()
+		}
+
+		logger.WithSpan(spanContext).
+			WithString("http.method", c.Method()).
+			WithString("client.version", c.Get(clientVersionHeader)).
+			Trace(c.OriginalURL())
+
+		newCtx, span := otel.Tracer(namespace).Start(trace.ContextWithRemoteSpanContext(context.Background(), spanContext), "middlewares.OtelTraceContext")
+		defer span.End()
+
+		ctxLogger := tracer.CtxLogger(logger, span)
+		traceID := spanContext.TraceID().String()
+		span.SetAttributes(attribute.Key("traceID").String(traceID))
+		span.SetAttributes(attribute.Key("SpanID").String(span.SpanContext().SpanID().String()))
+		span.SetAttributes(attribute.Key("traceFlags").String(spanContext.TraceFlags().String()))
+		span.SetAttributes(attribute.Key("clientVersion").String(c.Get(clientVersionHeader)))
+
+		c.Locals(telemetry.TracerContextKey, trace.ContextWithSpan(newCtx, span))
+		ctxLogger.Trace(fmt.Sprintf("context set key [%s] url[%s] method [%s]", telemetry.TracerContextKey, c.OriginalURL(), c.Method()))
+
+		// Go to next middleware:
+		response := c.Next()
+
+		statusCode := c.Response().StatusCode()
+		span.AddEvent(fmt.Sprintf("finished handling request with traceID: %s, statusCode = %d", traceID, statusCode))
+
+		if statusCode >= 300 && len(c.Request().Body()) > 0 {
+			ctxLogger.Warn(stacktrace.NewError(fmt.Sprintf("http.status [%b], body [%s]", statusCode, string(c.Request().Body()))))
+		}
+
+		return response
+	}
+}
+
+func spanContextFromHeader(parentContext string) (trace.SpanContext, []string) {
+	result := trace.NewSpanContext(trace.SpanContextConfig{
+		TraceID:    trace.TraceID{},
+		SpanID:     trace.SpanID{},
+		TraceState: trace.TraceState{},
+		Remote:     true,
+	})
+
+	parts := strings.Split(parentContext, "/")
+	var errors []string
+	if len(parts) == 2 {
+		traceID, err := trace.TraceIDFromHex(parts[0])
+		if err != nil {
+			errors = append(errors, fmt.Sprintf("could not get trace id %v", err))
+			return result, errors
+		}
+		result = result.WithTraceID(traceID)
+
+		spanParts := strings.Split(parts[1], ";")
+		if len(spanParts) == 1 {
+			spanParts = append(spanParts, "")
+		}
+
+		if len(spanParts) == 2 {
+			val, err := strconv.ParseUint(spanParts[0], 10, 64)
+			if err != nil {
+				errors = append(errors, fmt.Sprintf("could not get trace id %v", err))
+				return result, errors
+			}
+
+			spanID, err := trace.SpanIDFromHex(fmt.Sprintf("%016x", val))
+			if err != nil {
+				errors = append(errors, fmt.Sprintf("could not get span trace id %v", err))
+				return result, errors
+			}
+			result = result.WithSpanID(spanID)
+
+			if spanParts[1] == "o=1" {
+				result = result.WithTraceFlags(trace.FlagsSampled)
+			}
+		}
+	}
+
+	return result, errors
+}

api/pkg/middlewares/otel_context_middleware.go

@@ -2,9 +2,12 @@ package telemetry
 
 import (
 	"context"
+	"fmt"
 	"runtime"
 	"strings"
 
+	"github.com/palantir/stacktrace"
+
 	"github.com/gofiber/fiber/v2"
 	"go.opentelemetry.io/otel/attribute"
 	"go.opentelemetry.io/otel/codes"
@@ -24,10 +27,15 @@ func NewOtelLogger(projectID string, logger Logger) Tracer {
 	}
 }
 
-func (tracer *otelTracer) StartFromFiberCtx(_ *fiber.Ctx, name ...string) (context.Context, trace.Span) {
-	ctx, span := trace.NewNoopTracerProvider().Tracer(tracer.projectID).Start(context.Background(), getName(name...))
-	defer span.End()
-	return tracer.Start(ctx, getName(name...))
+func (tracer *otelTracer) StartFromFiberCtx(c *fiber.Ctx, name ...string) (context.Context, trace.Span) {
+	parentCtx, ok := c.Locals(TracerContextKey).(context.Context)
+	if !ok {
+		tracer.logger.Error(stacktrace.NewError(fmt.Sprintf("could not get trace from context with key [%s] url[%s] method [%s]", TracerContextKey, c.OriginalURL(), c.Method())))
+		ctx, span := trace.NewNoopTracerProvider().Tracer("").Start(context.Background(), "")
+		defer span.End()
+		parentCtx = ctx
+	}
+	return tracer.Start(parentCtx, getName(name...))
 }
 
 func (tracer *otelTracer) CtxLogger(logger Logger, span trace.Span) Logger {

api/pkg/telemetry/otel_tracer.go

@@ -7,6 +7,11 @@ import (
 	"go.opentelemetry.io/otel/trace"
 )
 
+const (
+	// TracerContextKey stores the fiber trace context
+	TracerContextKey = "tracer.context.key"
+)
+
 // Tracer is used for tracing
 type Tracer interface {
 	// StartFromFiberCtx creates a spanContext and a context.Context containing the newly-created spanContext.

api/pkg/telemetry/tracer.go

@@ -75,7 +75,7 @@ func (logger *zerologLogger) Fatal(err error) {
 
 // Error logs an error
 func (logger *zerologLogger) Error(err error) {
-	logger.decorateEvent(logger.zerolog.Fatal()).Err(err).Send()
+	logger.decorateEvent(logger.zerolog.Error()).Err(err).Send()
 }
 
 // WithSpan adds a spanContext to a logger