Skip to content

Commit

Permalink
feat(logger): add trace context hook (#134)
Browse files Browse the repository at this point in the history
* feat(logger): add trace context hook

* test(logger): add context tests

* fix(middleware): update example tests

* chore(probes): remove coverage out

* chore(logger): update version to v0.6.4

* chore(otel): uodate version to v0.1.3

* chore(camunda): uodate version to v2.0.3

* chore(middleware): uodate version to v0.3.3
  • Loading branch information
jcyamacho committed Jul 8, 2022
1 parent f1eca08 commit f852a45
Show file tree
Hide file tree
Showing 12 changed files with 164 additions and 52 deletions.
2 changes: 1 addition & 1 deletion camunda/v2/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,7 @@ replace (
)

require (
github.com/blacklane/go-libs/logger v0.6.3
github.com/blacklane/go-libs/logger v0.6.4
github.com/google/uuid v1.3.0
github.com/stretchr/testify v1.7.1
)
4 changes: 4 additions & 0 deletions camunda/v2/go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -90,6 +90,7 @@ github.com/google/go-cmp v0.4.1/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/
github.com/google/go-cmp v0.5.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
github.com/google/go-cmp v0.5.1/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
github.com/google/go-cmp v0.5.7 h1:81/ik6ipDQS2aGcBfIN5dHDB36BwrStyeAQquSYCV4o=
github.com/google/go-cmp v0.5.7/go.mod h1:n+brtR0CgQNWTVd5ZUFpTBC8YFBDLK/h/bpaJ8/DtOE=
github.com/google/martian v2.1.0+incompatible/go.mod h1:9I4somxYTbIHy5NJKHRl3wXiIaQGbYVAs8BPL6v8lEs=
github.com/google/martian/v3 v3.0.0/go.mod h1:y5Zk1BBys9G+gd6Jrk0W3cC1+ELVxBWuIGO+w/tUAp0=
Expand Down Expand Up @@ -138,7 +139,9 @@ go.opencensus.io v0.22.0/go.mod h1:+kGneAE2xo2IficOXnaByMWTGM9T73dGwxeWcUqIpI8=
go.opencensus.io v0.22.2/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
go.opencensus.io v0.22.3/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
go.opencensus.io v0.22.4/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
go.opentelemetry.io/otel v1.7.0 h1:Z2lA3Tdch0iDcrhJXDIlC94XE+bxok1F9B+4Lz/lGsM=
go.opentelemetry.io/otel v1.7.0/go.mod h1:5BdUoMIz5WEs0vt0CUEMtSSaTSHBBVwrhnz7+nrD5xk=
go.opentelemetry.io/otel/trace v1.7.0 h1:O37Iogk1lEkMRXewVtZ1BBTVn5JEp8GrJvP92bJqC6o=
go.opentelemetry.io/otel/trace v1.7.0/go.mod h1:fzLSB9nqR2eXzxPXb2JW9IKE+ScyXA48yyE4TNvoHqU=
golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
golang.org/x/crypto v0.0.0-20190510104115-cbcb75029529/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
Expand Down Expand Up @@ -301,6 +304,7 @@ golang.org/x/tools v0.1.7/go.mod h1:LGqMHiF4EqQNHR1JncWGqT5BVaXmza+X+BDGol+dOxo=
golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 h1:go1bK/D/BFZV2I8cIQd1NKEZ+0owSTG1fDTci4IqFcE=
golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
google.golang.org/api v0.4.0/go.mod h1:8k5glujaEP+g9n7WNsDg8QP6cUVNI86fCNMcbazEtwE=
google.golang.org/api v0.7.0/go.mod h1:WtwebWUNSVBH/HAw79HIFXZNqEvBhG+Ra+ax0hx3E3M=
Expand Down
10 changes: 9 additions & 1 deletion logger/context.go
Original file line number Diff line number Diff line change
Expand Up @@ -3,11 +3,19 @@ package logger
import (
"context"

"github.com/blacklane/go-libs/logger/hooks"
"github.com/rs/zerolog"
)

const (
ddTraceIDKey = "dd.trace_id"
ddSpanIDKey = "dd.span_id"
)

// FromContext delegates to zerolog.Ctx. It'll return the logger in the context
// or a disabled logger if none is found. For details check the docs for zerolog.Ctx.
func FromContext(ctx context.Context) *Logger {
return zerolog.Ctx(ctx)
logger := zerolog.Ctx(ctx)
newLogger := logger.Hook(hooks.TraceContext(ctx))
return &newLogger
}
91 changes: 91 additions & 0 deletions logger/context_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,91 @@
package logger

import (
"bytes"
"context"
"encoding/json"
"testing"

"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/codes"
"go.opentelemetry.io/otel/trace"
)

func TestFromContext(t *testing.T) {
const (
message = "Hello!"
appName = "test"
)
var buf bytes.Buffer
logger := New(&buf, appName)
ctx := logger.WithContext(context.Background())
log := FromContext(ctx)

log.Info().Msg(message)
var data map[string]interface{}
if err := json.Unmarshal(buf.Bytes(), &data); err != nil {
t.Fatal(err)
}
if data["message"] != message {
t.Errorf("expected message to be '%s', got %q", message, data["message"])
}
if data["application"] != appName {
t.Errorf("expected application to be '%s', got %q", appName, data["application"])
}
}

func TestFromContext_TraceContext(t *testing.T) {
traceID := [16]byte{1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16}
spanID := [8]byte{1, 2, 3, 4, 5, 6, 7, 8}

ddTraceID := "651345242494996240"
ddSpanID := "72623859790382856"

var buf bytes.Buffer
logger := New(&buf, "test")
ctx := logger.WithContext(context.Background())

span := newFakeSpan(traceID, spanID)

ctx = trace.ContextWithSpan(ctx, span)

log := FromContext(ctx)

log.Info().Msg("message")
var data map[string]interface{}
if err := json.Unmarshal(buf.Bytes(), &data); err != nil {
t.Fatal(err)
}
if data["dd.trace_id"] != ddTraceID {
t.Errorf("expected dd.trace_id to be '%s', got %q", ddTraceID, data["dd.trace_id"])
}
if data["dd.span_id"] != ddSpanID {
t.Errorf("expected dd.span_id to be '%s', got %q", ddSpanID, data["dd.span_id"])
}
}

type fakeSpan struct {
Context trace.SpanContext
}

func newFakeSpan(traceID [16]byte, spanID [8]byte) trace.Span {
ctx := trace.NewSpanContext(trace.SpanContextConfig{
TraceID: traceID,
SpanID: spanID,
})

return fakeSpan{
Context: ctx,
}
}

func (f fakeSpan) SpanContext() trace.SpanContext { return f.Context }
func (fakeSpan) IsRecording() bool { return true }
func (fakeSpan) SetStatus(codes.Code, string) {}
func (fakeSpan) SetError(bool) {}
func (fakeSpan) SetAttributes(...attribute.KeyValue) {}
func (fakeSpan) End(...trace.SpanEndOption) {}
func (fakeSpan) RecordError(error, ...trace.EventOption) {}
func (fakeSpan) AddEvent(string, ...trace.EventOption) {}
func (fakeSpan) SetName(string) {}
func (fakeSpan) TracerProvider() trace.TracerProvider { return nil }
4 changes: 2 additions & 2 deletions logger/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,8 @@ require (
github.com/google/go-cmp v0.5.7
github.com/rs/zerolog v1.26.0
github.com/stretchr/testify v1.7.1
go.opentelemetry.io/otel v1.7.0
go.opentelemetry.io/otel/trace v1.7.0
)

require (
Expand All @@ -23,8 +25,6 @@ require (
github.com/golang/protobuf v1.5.2 // indirect
github.com/google/uuid v1.3.0 // indirect
github.com/pmezard/go-difflib v1.0.0 // indirect
go.opentelemetry.io/otel v1.7.0 // indirect
go.opentelemetry.io/otel/trace v1.7.0 // indirect
golang.org/x/net v0.0.0-20211109214657-ef0fda0de508 // indirect
golang.org/x/oauth2 v0.0.0-20211104180415-d3ed0bb246c8 // indirect
google.golang.org/appengine v1.6.7 // indirect
Expand Down
48 changes: 48 additions & 0 deletions logger/hooks/trace.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,48 @@
package hooks

import (
"context"
"strconv"

"github.com/rs/zerolog"
"go.opentelemetry.io/otel/trace"
)

const (
ddTraceIDKey = "dd.trace_id"
ddSpanIDKey = "dd.span_id"
)

func TraceContext(ctx context.Context) zerolog.Hook {
return &traceContextHook{ctx: ctx}
}

type traceContextHook struct {
ctx context.Context
}

func (ot *traceContextHook) Run(e *zerolog.Event, level zerolog.Level, msg string) {
span := trace.SpanFromContext(ot.ctx)
if span.IsRecording() {
spanCtx := span.SpanContext()
traceID := spanCtx.TraceID().String()
spanID := spanCtx.SpanID().String()

e.Str(ddTraceIDKey, convertTraceID(traceID)).
Str(ddSpanIDKey, convertTraceID(spanID))
}
}

func convertTraceID(id string) string {
if len(id) < 16 {
return ""
}
if len(id) > 16 {
id = id[16:]
}
intValue, err := strconv.ParseUint(id, 16, 64)
if err != nil {
return ""
}
return strconv.FormatUint(intValue, 10)
}
7 changes: 0 additions & 7 deletions middleware/events_example_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -50,7 +50,6 @@ func ExampleEvents() {
// "message": "always logged",
// "request_id": "the_tracking_id",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "the_tracking_id"
// }
// {
Expand All @@ -61,7 +60,6 @@ func ExampleEvents() {
// "message": "event_to_be_logged succeeded",
// "request_id": "the_tracking_id",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "the_tracking_id"
// }
// {
Expand All @@ -71,7 +69,6 @@ func ExampleEvents() {
// "message": "always logged",
// "request_id": "the_tracking_id",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "the_tracking_id"
// }
}
Expand Down Expand Up @@ -110,7 +107,6 @@ func ExampleEvents_onlyRequestIDHeader() {
// "message": "always logged",
// "request_id": "ExampleEvents_onlyRequestIDHeader",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "ExampleEvents_onlyRequestIDHeader"
// }
// {
Expand All @@ -121,7 +117,6 @@ func ExampleEvents_onlyRequestIDHeader() {
// "message": "event_to_be_logged succeeded",
// "request_id": "ExampleEvents_onlyRequestIDHeader",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "ExampleEvents_onlyRequestIDHeader"
// }
}
Expand Down Expand Up @@ -160,7 +155,6 @@ func ExampleEvents_trackingIDAndRequestIDHeaders() {
// "message": "always logged",
// "request_id": "ExampleEvents_trackingIDAndRequestIDHeaders",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "ExampleEvents_trackingIDAndRequestIDHeaders"
// }
// {
Expand All @@ -171,7 +165,6 @@ func ExampleEvents_trackingIDAndRequestIDHeaders() {
// "message": "event_to_be_logged succeeded",
// "request_id": "ExampleEvents_trackingIDAndRequestIDHeaders",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "ExampleEvents_trackingIDAndRequestIDHeaders"
// }
}
6 changes: 3 additions & 3 deletions middleware/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -11,9 +11,9 @@ replace (
)

require (
github.com/blacklane/go-libs/camunda/v2 v2.0.2
github.com/blacklane/go-libs/logger v0.6.3
github.com/blacklane/go-libs/otel v0.1.2
github.com/blacklane/go-libs/camunda/v2 v2.0.3
github.com/blacklane/go-libs/logger v0.6.4
github.com/blacklane/go-libs/otel v0.1.3
github.com/blacklane/go-libs/tracking v0.3.1
github.com/blacklane/go-libs/x/events v0.2.1
github.com/google/go-cmp v0.5.7
Expand Down
8 changes: 1 addition & 7 deletions middleware/http_example_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,6 @@ func ExampleHTTP() {
// "path": "/foo",
// "request_id": "tracking_id_ExampleHTTP",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "tracking_id_ExampleHTTP",
// "user_agent": "",
// "verb": "GET"
Expand All @@ -71,7 +70,6 @@ func ExampleHTTP() {
// "path": "/foo",
// "request_id": "tracking_id_ExampleHTTP",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "tracking_id_ExampleHTTP",
// "user_agent": "",
// "verb": "GET"
Expand Down Expand Up @@ -117,7 +115,6 @@ func ExampleHTTP_onlyRequestIDHeader() {
// "path": "/foo",
// "request_id": "ExampleHTTP_onlyRequestIDHeader",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "ExampleHTTP_onlyRequestIDHeader",
// "user_agent": "",
// "verb": "GET"
Expand All @@ -135,7 +132,6 @@ func ExampleHTTP_onlyRequestIDHeader() {
// "path": "/foo",
// "request_id": "ExampleHTTP_onlyRequestIDHeader",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "ExampleHTTP_onlyRequestIDHeader",
// "user_agent": "",
// "verb": "GET"
Expand Down Expand Up @@ -182,7 +178,6 @@ func ExampleHTTP_trackingIDAndRequestIDHeaders() {
// "path": "/foo",
// "request_id": "ExampleHTTP_trackingIDAndRequestIDHeaders",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "ExampleHTTP_trackingIDAndRequestIDHeaders",
// "user_agent": "",
// "verb": "GET"
Expand All @@ -200,7 +195,6 @@ func ExampleHTTP_trackingIDAndRequestIDHeaders() {
// "path": "/foo",
// "request_id": "ExampleHTTP_trackingIDAndRequestIDHeaders",
// "timestamp": "2009-11-10T23:00:00.000Z",
// "trace_id": "00000000000000000000000000000000",
// "tracking_id": "ExampleHTTP_trackingIDAndRequestIDHeaders",
// "user_agent": "",
// "verb": "GET"
Expand Down Expand Up @@ -234,7 +228,7 @@ func TestHTTPWithBodyFilter(t *testing.T) {
filterKeys: []string{},
log: logger.Logger{},
},
want: `{"level":"info","application":"TestHTTPRequestLogger","host":"example.com","ip":"192.0.2.1","params":"","path":"/with_body","request_id":"tracking_id_ExampleHTTP","tracking_id":"tracking_id_ExampleHTTP","user_agent":"","verb":"POST","trace_id":"00000000000000000000000000000000","http_status":200,"duration_ms":0,"body":{"hello":"world"},"timestamp":"2009-11-10T23:00:00.000Z","message":"POST /with_body"}` + "\n",
want: `{"level":"info","application":"TestHTTPRequestLogger","host":"example.com","ip":"192.0.2.1","params":"","path":"/with_body","request_id":"tracking_id_ExampleHTTP","tracking_id":"tracking_id_ExampleHTTP","user_agent":"","verb":"POST","http_status":200,"duration_ms":0,"body":{"hello":"world"},"timestamp":"2009-11-10T23:00:00.000Z","message":"POST /with_body"}` + "\n",
},
}
for _, tt := range tests {
Expand Down
2 changes: 1 addition & 1 deletion otel/go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ replace (
)

require (
github.com/blacklane/go-libs/logger v0.6.3
github.com/blacklane/go-libs/logger v0.6.4
github.com/blacklane/go-libs/tracking v0.3.1
github.com/blacklane/go-libs/x/events v0.2.1
github.com/rs/zerolog v1.26.0
Expand Down
26 changes: 0 additions & 26 deletions probes/coverage.out

This file was deleted.

8 changes: 4 additions & 4 deletions versions.yaml
Original file line number Diff line number Diff line change
@@ -1,18 +1,18 @@
module-sets:
camunda:
version: v2.0.2
version: v2.0.3
modules:
- github.com/blacklane/go-libs/camunda/v2
logger:
version: v0.6.3
version: v0.6.4
modules:
- github.com/blacklane/go-libs/logger
middleware:
version: v0.3.2
version: v0.3.3
modules:
- github.com/blacklane/go-libs/middleware
otel:
version: v0.1.2
version: v0.1.3
modules:
- github.com/blacklane/go-libs/otel
probes:
Expand Down

0 comments on commit f852a45

Please sign in to comment.