Skip to content

Commit

Permalink
fix: logger enhancement
Browse files Browse the repository at this point in the history
  • Loading branch information
morlay committed Mar 4, 2024
1 parent 9f36a4c commit 48eaf27
Show file tree
Hide file tree
Showing 11 changed files with 100 additions and 45 deletions.
8 changes: 4 additions & 4 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -31,12 +31,12 @@ require (
)

require (
github.com/Azure/azure-sdk-for-go/sdk/azcore v1.9.2 // indirect
github.com/Azure/azure-sdk-for-go/sdk/azcore v1.10.0 // indirect
github.com/Azure/azure-sdk-for-go/sdk/azidentity v1.5.1 // indirect
github.com/Azure/azure-sdk-for-go/sdk/internal v1.5.2 // indirect
github.com/AzureAD/microsoft-authentication-library-for-go v1.2.2 // indirect
github.com/alecthomas/units v0.0.0-20231202071711-9a357b53e9c9 // indirect
github.com/aws/aws-sdk-go v1.50.28 // indirect
github.com/aws/aws-sdk-go v1.50.30 // indirect
github.com/bboreham/go-loser v0.0.0-20230920113527-fcc2c21820a3 // indirect
github.com/beorn7/perks v1.0.1 // indirect
github.com/cenkalti/backoff/v4 v4.2.1 // indirect
Expand Down Expand Up @@ -74,10 +74,10 @@ require (
github.com/pkg/browser v0.0.0-20240102092130-5ac0b6a4141c // indirect
github.com/pmezard/go-difflib v1.0.1-0.20181226105442-5d4384ee4fb2 // indirect
github.com/prometheus/client_model v0.6.0 // indirect
github.com/prometheus/common v0.48.0 // indirect
github.com/prometheus/common v0.49.0 // indirect
github.com/prometheus/common/sigv4 v0.1.0 // indirect
github.com/prometheus/procfs v0.12.0 // indirect
github.com/stretchr/testify v1.8.4 // indirect
github.com/stretchr/testify v1.9.0 // indirect
go.opentelemetry.io/proto/otlp v1.1.0 // indirect
go.uber.org/atomic v1.11.0 // indirect
go.uber.org/goleak v1.3.0 // indirect
Expand Down
11 changes: 11 additions & 0 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,8 @@ cuelang.org/go v0.7.1/go.mod h1:ix+3dM/bSpdG9xg6qpCgnJnpeLtciZu+O/rDbywoMII=
dmitri.shuralyov.com/gpu/mtl v0.0.0-20190408044501-666a987793e9/go.mod h1:H6x//7gZCb22OMCxBHrMx7a5I7Hp++hsVxbQ4BYO7hU=
github.com/Azure/azure-sdk-for-go/sdk/azcore v1.9.2 h1:c4k2FIYIh4xtwqrQwV0Ct1v5+ehlNXj5NI/MWVsiTkQ=
github.com/Azure/azure-sdk-for-go/sdk/azcore v1.9.2/go.mod h1:5FDJtLEO/GxwNgUxbwrY3LP0pEoThTQJtk2oysdXHxM=
github.com/Azure/azure-sdk-for-go/sdk/azcore v1.10.0 h1:n1DH8TPV4qqPTje2RcUBYwtrTWlabVp4n46+74X2pn4=
github.com/Azure/azure-sdk-for-go/sdk/azcore v1.10.0/go.mod h1:HDcZnuGbiyppErN6lB+idp4CKhjbc8gwjto6OPpyggM=
github.com/Azure/azure-sdk-for-go/sdk/azidentity v1.5.1 h1:sO0/P7g68FrryJzljemN+6GTssUXdANk6aJ7T1ZxnsQ=
github.com/Azure/azure-sdk-for-go/sdk/azidentity v1.5.1/go.mod h1:h8hyGFDsU5HMivxiS2iYFZsgDbU9OnnJ163x5UGVKYo=
github.com/Azure/azure-sdk-for-go/sdk/internal v1.5.2 h1:LqbJ/WzJUwBf8UiaSzgX7aMclParm9/5Vgp+TY51uBQ=
Expand Down Expand Up @@ -67,6 +69,8 @@ github.com/armon/go-metrics v0.4.1/go.mod h1:E6amYzXo6aW1tqzoZGT755KkbgrJsSdpwZ+
github.com/aws/aws-sdk-go v1.38.35/go.mod h1:hcU610XS61/+aQV88ixoOzUoG7v3b31pl2zKMmprdro=
github.com/aws/aws-sdk-go v1.50.28 h1:cXltYLw4dq10YPAwk8EGYJjeQlCky4tyxAllWmVQZ9Y=
github.com/aws/aws-sdk-go v1.50.28/go.mod h1:LF8svs817+Nz+DmiMQKTO3ubZ/6IaTpq3TjupRn3Eqk=
github.com/aws/aws-sdk-go v1.50.30 h1:2OelKH1eayeaH7OuL1Y9Ombfw4HK+/k0fEnJNWjyLts=
github.com/aws/aws-sdk-go v1.50.30/go.mod h1:LF8svs817+Nz+DmiMQKTO3ubZ/6IaTpq3TjupRn3Eqk=
github.com/bboreham/go-loser v0.0.0-20230920113527-fcc2c21820a3 h1:6df1vn4bBlDDo4tARvBm7l6KA9iVMnE3NWizDeWSrps=
github.com/bboreham/go-loser v0.0.0-20230920113527-fcc2c21820a3/go.mod h1:CIWtjkly68+yqLPbvwwR/fjNJA/idrtULjZWh2v1ys0=
github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
Expand Down Expand Up @@ -244,6 +248,7 @@ github.com/gorilla/websocket v1.5.0 h1:PPwGk2jz7EePpoHN/+ClbZu8SPxiqlu12wZP/3sWm
github.com/gorilla/websocket v1.5.0/go.mod h1:YR8l580nyteQvAITg2hZ9XVh4b55+EU/adAjf1fMHhE=
github.com/grafana/regexp v0.0.0-20221122212121-6b5c0a4cb7fd h1:PpuIBO5P3e9hpqBD0O/HjhShYuM6XE0i/lbE6J94kww=
github.com/grafana/regexp v0.0.0-20221122212121-6b5c0a4cb7fd/go.mod h1:M5qHK+eWfAv8VR/265dIuEpL3fNfeC21tXXp9itM24A=
github.com/grpc-ecosystem/grpc-gateway v1.16.0 h1:gmcG1KaJ57LophUzW0Hy8NmPhnMZb4M0+kPpLofRdBo=
github.com/grpc-ecosystem/grpc-gateway/v2 v2.19.1 h1:/c3QmbOGMGTOumP2iT/rCwB7b0QDGLKzqOmktBjT+Is=
github.com/grpc-ecosystem/grpc-gateway/v2 v2.19.1/go.mod h1:5SN9VR2LTsRFsrEC6FHgRbTWrTHu6tqPeKxEQv15giM=
github.com/hashicorp/consul/api v1.27.0 h1:gmJ6DPKQog1426xsdmgk5iqDyoRiNc+ipBdJOqKQFjc=
Expand Down Expand Up @@ -398,6 +403,8 @@ github.com/prometheus/common v0.26.0/go.mod h1:M7rCNAaPfAosfx8veZJCuw84e35h3Cfd9
github.com/prometheus/common v0.29.0/go.mod h1:vu+V0TpY+O6vW9J44gczi3Ap/oXXR10b+M/gUGO4Hls=
github.com/prometheus/common v0.48.0 h1:QO8U2CdOzSn1BBsmXJXduaaW+dY/5QLjfB8svtSzKKE=
github.com/prometheus/common v0.48.0/go.mod h1:0/KsvlIEfPQCQ5I2iNSAWKPZziNCvRs5EC6ILDTlAPc=
github.com/prometheus/common v0.49.0 h1:ToNTdK4zSnPVJmh698mGFkDor9wBI/iGaJy5dbH1EgI=
github.com/prometheus/common v0.49.0/go.mod h1:Kxm+EULxRbUkjGU6WFsQqo3ORzB4tyKvlWFOE9mB2sE=
github.com/prometheus/common/sigv4 v0.1.0 h1:qoVebwtwwEhS85Czm2dSROY5fTo2PAPEVdDeppTwGX4=
github.com/prometheus/common/sigv4 v0.1.0/go.mod h1:2Jkxxk9yYvCkE5G1sQT7GuEXm57JrvHu9k5YwTjsNtI=
github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
Expand Down Expand Up @@ -427,12 +434,15 @@ github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+
github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
github.com/stretchr/objx v0.5.0 h1:1zr/of2m5FGMsad5YfcqgdqdWrIhu+EBEJRhR1U7z/c=
github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo=
github.com/stretchr/objx v0.5.2 h1:xuMeJ0Sdp5ZMRXx/aWO6RZxdr3beISkG5/G/aIRr3pY=
github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
github.com/stretchr/testify v1.8.4 h1:CcVxjf3Q8PM0mHUKJCdn+eZZtm5yQwehR5yeSVQQcUk=
github.com/stretchr/testify v1.8.4/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo=
github.com/stretchr/testify v1.9.0 h1:HtqpIVDClZ4nwg75+f6Lvsy/wHu+3BoSGCbBAcpTsTg=
github.com/stretchr/testify v1.9.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY=
github.com/vultr/govultr/v2 v2.17.2 h1:gej/rwr91Puc/tgh+j33p/BLR16UrIPnSr+AIwYWZQs=
github.com/vultr/govultr/v2 v2.17.2/go.mod h1:ZFOKGWmgjytfyjeyAdhQlSWwTjh2ig+X49cAp50dzXI=
github.com/yuin/goldmark v1.1.25/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
Expand Down Expand Up @@ -805,6 +815,7 @@ k8s.io/apimachinery v0.29.2 h1:EWGpfJ856oj11C52NRCHuU7rFDwxev48z+6DSlGNsV8=
k8s.io/apimachinery v0.29.2/go.mod h1:6HVkd1FwxIagpYrHSwJlQqZI3G9LfYWRPAkUvLnXTKU=
k8s.io/client-go v0.29.2 h1:FEg85el1TeZp+/vYJM7hkDlSTFZ+c5nnK44DJ4FyoRg=
k8s.io/client-go v0.29.2/go.mod h1:knlvFZE58VpqbQpJNbCbctTVXcd35mMyAAwBdpt4jrA=
k8s.io/klog v1.0.0 h1:Pt+yjF5aB1xDSVbau4VsWe+dQNzA0qv1LlXdC2dF6Q8=
k8s.io/klog/v2 v2.120.1 h1:QXU6cPEOIslTGvZaXvFWiP9VKyeet3sawzTOvdXb4Vw=
k8s.io/klog/v2 v2.120.1/go.mod h1:3Jpz1GvMt720eyJH1ckRHK1EDfpxISzJ7I9OYgaDtPE=
k8s.io/kube-openapi v0.0.0-20231010175941-2dd684a91f00 h1:aVUu9fTY98ivBPKR9Y5w/AuzbMm96cd3YHRTU83I780=
Expand Down
2 changes: 2 additions & 0 deletions internal/otel/span_export__slog.go
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@ import (
"log/slog"
"os"
"runtime"
"sync"

_ "time/tzdata"

Expand Down Expand Up @@ -41,6 +42,7 @@ func SlogSpanExporter(log *slog.Logger) sdktrace.SpanExporter {

type stdoutSpanExporter struct {
log *slog.Logger
wg sync.WaitGroup
}

func (e *stdoutSpanExporter) Shutdown(ctx context.Context) error {
Expand Down
39 changes: 32 additions & 7 deletions pkg/otel/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,9 +6,9 @@ import (
"time"

"github.com/go-courier/logr"

"go.opentelemetry.io/otel/exporters/otlp/otlptrace"
"go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc"

"go.opentelemetry.io/otel/sdk/resource"
sdktrace "go.opentelemetry.io/otel/sdk/trace"
semconv "go.opentelemetry.io/otel/semconv/v1.20.0"
Expand All @@ -19,6 +19,16 @@ import (
"github.com/innoai-tech/infra/pkg/configuration"
)

type OtelWithBatchLog struct {
Otel
}

func (o *OtelWithBatchLog) SetDefaults() {
o.batchLog = true

o.Otel.SetDefaults()
}

type Otel struct {
// Log level
LogLevel LogLevel `flag:",omitempty"`
Expand All @@ -27,8 +37,9 @@ type Otel struct {
// When set, will collect traces
TraceCollectorEndpoint string `flag:",omitempty"`

batchLog bool
tp *sdktrace.TracerProvider
log *slog.Logger
directLogger *slog.Logger
enabledLogLevel logr.Level
}

Expand All @@ -39,12 +50,17 @@ func (o *Otel) SetDefaults() {
if o.LogFilter == "" {
o.LogFilter = OutputFilterAlways
}
if o.TraceCollectorEndpoint != "" {
o.batchLog = true
}
}

func (o *Otel) Init(ctx context.Context) error {
if o.tp == nil {
o.log = otel.NewLogger()
if !o.batchLog {
o.directLogger = otel.NewLogger()
}

if o.tp == nil {
opts := []sdktrace.TracerProviderOption{
sdktrace.WithSampler(sdktrace.AlwaysSample()),
}
Expand All @@ -55,14 +71,23 @@ func (o *Otel) Init(ctx context.Context) error {
otlptracegrpc.WithInsecure(),
otlptracegrpc.WithTimeout(3*time.Second),
)
z, err := otlptrace.New(context.Background(), client)

exporter, err := otlptrace.New(ctx, client)
if err != nil {
return err
}

opts = append(opts, sdktrace.WithBatcher(
otel.WithSpanMapExporter(otel.OutputFilter(o.LogFilter))(
otel.WithErrIgnoreExporter()(z),
otel.WithErrIgnoreExporter()(exporter),
),
))
}

if o.directLogger == nil {
opts = append(opts, sdktrace.WithBatcher(
otel.WithSpanMapExporter(otel.OutputFilter(o.LogFilter))(
otel.SlogSpanExporter(otel.NewLogger()),
),
))
}
Expand Down Expand Up @@ -95,7 +120,7 @@ func (o *Otel) Shutdown(ctx context.Context) error {
}

func (o *Otel) InjectContext(ctx context.Context) context.Context {
log := newLogger(ctx, o.tp, o.log, o.enabledLogLevel)
log := newLogger(ctx, o.tp, o.directLogger, o.enabledLogLevel)

if info := cli.InfoFromContext(ctx); info != nil {
log = log.WithValues("app", info.App)
Expand Down
10 changes: 6 additions & 4 deletions pkg/otel/log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -28,17 +28,19 @@ func Setup(t testing.TB, c any) context.Context {
func TestLog(t *testing.T) {
t.Run("FilterAlways", func(t *testing.T) {
t.Run("async", func(t *testing.T) {
ctx := Setup(t, &Otel{
LogFilter: OutputFilterAlways,
LogLevel: DebugLevel,
ctx := Setup(t, &OtelWithBatchLog{
Otel: Otel{
LogLevel: DebugLevel,
LogFilter: OutputFilterAlways,
},
})
doLog(ctx)
})

t.Run("sync", func(t *testing.T) {
ctx := Setup(t, &Otel{
LogFilter: OutputFilterAlways,
LogLevel: DebugLevel,
LogFilter: OutputFilterAlways,
})
doLog(ctx)
})
Expand Down
63 changes: 37 additions & 26 deletions pkg/otel/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -16,23 +16,23 @@ import (
func newLogger(
ctx context.Context,
tp trace.TracerProvider,
slog *slog.Logger,
directLogger *slog.Logger,
levelEnabled logr.Level,
) logr.Logger {
return &logger{
enabled: levelEnabled,
tp: tp,
slog: slog,
spanContext: &spanContext{span: trace.SpanFromContext(ctx)},
enabled: levelEnabled,
tp: tp,
directLogger: directLogger,
spanContext: &spanContext{span: trace.SpanFromContext(ctx)},
}
}

type logger struct {
enabled logr.Level
tp trace.TracerProvider
slog *slog.Logger
spanContext *spanContext
attributes []attribute.KeyValue
enabled logr.Level
tp trace.TracerProvider
directLogger *slog.Logger
spanContext *spanContext
attributes []attribute.KeyValue
}

type spanContext struct {
Expand Down Expand Up @@ -92,23 +92,23 @@ func (t *logger) WithValues(keyAndValues ...any) logr.Logger {
name, attrs := attrsFromKeyAndValues(t.spanContext.name, keyAndValues...)

return &logger{
enabled: t.enabled,
tp: t.tp,
slog: t.slog,
spanContext: t.spanContext.withName(name),
attributes: append(t.attributes, attrs...),
enabled: t.enabled,
tp: t.tp,
directLogger: t.directLogger,
spanContext: t.spanContext.withName(name),
attributes: append(t.attributes, attrs...),
}
}

func (t *logger) Start(ctx context.Context, name string, keyAndValues ...any) (context.Context, logr.Logger) {
c, attrs, spanCtx := t.spanContext.start(ctx, t.tp, name, keyAndValues...)

lgr := &logger{
enabled: t.enabled,
tp: t.tp,
spanContext: spanCtx,
slog: t.slog,
attributes: append(t.attributes, attrs...),
enabled: t.enabled,
tp: t.tp,
spanContext: spanCtx,
directLogger: t.directLogger,
attributes: append(t.attributes, attrs...),
}

return logr.WithLogger(c, lgr), lgr
Expand All @@ -126,15 +126,15 @@ func (t *logger) End() {

t.spanContext.span.End(trace.WithTimestamp(endAt))

if l := t.slog; l != nil {
if l := t.directLogger; l != nil {
attrs := t.spanContext.toAttrs(t.attributes)
attrs = append(attrs, slog.String("spanCost", endAt.Sub(t.spanContext.startedAt).String()))

if t.enabled >= logr.DebugLevel {
attrs = append(attrs, slog.Any("source", otel.Source(3)))
}

l.LogAttrs(context.Background(), slog.LevelInfo, "done", attrs...)
l.LogAttrs(context.Background(), slog.LevelDebug, "done", attrs...)
}
}

Expand All @@ -149,9 +149,13 @@ func (t *logger) info(level logr.Level, msg fmt.Stringer) {

msgStr := msg.String()

go t.span().AddEvent(msgStr, trace.WithTimestamp(time.Now()), trace.WithAttributes(t.attributes...))
t.span().AddEvent(
msgStr,
trace.WithTimestamp(time.Now()),
trace.WithAttributes(append(t.attributes, attribute.String("@level", level.String()))...),
)

if l := t.slog; l != nil {
if l := t.directLogger; l != nil {
attrs := t.spanContext.toAttrs(t.attributes)

if t.enabled >= logr.DebugLevel {
Expand All @@ -163,6 +167,7 @@ func (t *logger) info(level logr.Level, msg fmt.Stringer) {
l.LogAttrs(context.Background(), slog.LevelDebug, msgStr, attrs...)
case logr.InfoLevel:
l.LogAttrs(context.Background(), slog.LevelInfo, msgStr, attrs...)
default:
}
}
}
Expand All @@ -178,9 +183,13 @@ func (t *logger) error(level logr.Level, err error) {

attributes := t.attributes

go t.span().RecordError(err, trace.WithTimestamp(time.Now()), trace.WithAttributes(attributes...))
t.span().RecordError(
err,
trace.WithTimestamp(time.Now()),
trace.WithAttributes(append(t.attributes, attribute.String("@level", level.String()))...),
)

if l := t.slog; l != nil {
if l := t.directLogger; l != nil {
attrs := t.spanContext.toAttrs(attributes)

if t.enabled >= logr.DebugLevel {
Expand All @@ -192,6 +201,8 @@ func (t *logger) error(level logr.Level, err error) {
l.LogAttrs(context.Background(), slog.LevelWarn, err.Error(), attrs...)
case logr.ErrorLevel:
l.LogAttrs(context.Background(), slog.LevelError, err.Error(), attrs...)
default:

}
}
}
Expand Down
3 changes: 2 additions & 1 deletion pkg/otel/metric.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,8 @@ package otel

import (
"context"
"time"

"github.com/innoai-tech/infra/internal/otel"
"github.com/innoai-tech/infra/pkg/cli"
"github.com/innoai-tech/infra/pkg/configuration"
Expand All @@ -16,7 +18,6 @@ import (
sdkmetric "go.opentelemetry.io/otel/sdk/metric"
sdkresource "go.opentelemetry.io/otel/sdk/resource"
semconv "go.opentelemetry.io/otel/semconv/v1.20.0"
"time"
)

type Metric struct {
Expand Down
3 changes: 2 additions & 1 deletion pkg/otel/metric/aggregation/data_chain.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,9 +2,10 @@ package aggregation

import (
"context"
"github.com/prometheus/prometheus/util/annotations"
"time"

"github.com/prometheus/prometheus/util/annotations"

"github.com/prometheus/prometheus/model/histogram"
"github.com/prometheus/prometheus/model/labels"
"github.com/prometheus/prometheus/storage"
Expand Down
3 changes: 2 additions & 1 deletion pkg/otel/metric/aggregation/data_chain_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -3,10 +3,11 @@ package aggregation
import (
"context"
"fmt"
"github.com/prometheus/prometheus/tsdb/chunks"
"testing"
"time"

"github.com/prometheus/prometheus/tsdb/chunks"

"github.com/prometheus/prometheus/model/histogram"
"github.com/prometheus/prometheus/tsdb/chunkenc"

Expand Down
Loading

0 comments on commit 48eaf27

Please sign in to comment.