From 7a0d5c1a1269f50cee2d10b430b55ea6d15e4ce1 Mon Sep 17 00:00:00 2001 From: Emilio Garcia Date: Wed, 20 Nov 2024 10:51:25 -0500 Subject: [PATCH] Fix: nrslog integration with slog.Handler interface --- .../logcontext-v2/nrslog/example/main.go | 2 +- v3/integrations/logcontext-v2/nrslog/go.mod | 13 +- .../logcontext-v2/nrslog/handler.go | 193 +++++++----------- .../logcontext-v2/nrslog/handler_test.go | 57 +++++- .../logcontext-v2/nrslog/logger.go | 52 +++++ .../logcontext-v2/nrslog/writer.go | 70 ------- 6 files changed, 187 insertions(+), 200 deletions(-) create mode 100644 v3/integrations/logcontext-v2/nrslog/logger.go delete mode 100644 v3/integrations/logcontext-v2/nrslog/writer.go diff --git a/v3/integrations/logcontext-v2/nrslog/example/main.go b/v3/integrations/logcontext-v2/nrslog/example/main.go index 247d018d4..58da1b3b3 100644 --- a/v3/integrations/logcontext-v2/nrslog/example/main.go +++ b/v3/integrations/logcontext-v2/nrslog/example/main.go @@ -21,7 +21,7 @@ func main() { } app.WaitForConnection(time.Second * 5) - log := slog.New(nrslog.TextHandler(app, os.Stdout, &slog.HandlerOptions{})) + log := slog.New(nrslog.WrapHandler(app, slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{}))) log.Info("I am a log message") diff --git a/v3/integrations/logcontext-v2/nrslog/go.mod b/v3/integrations/logcontext-v2/nrslog/go.mod index 9469f90b7..cac36ee0e 100644 --- a/v3/integrations/logcontext-v2/nrslog/go.mod +++ b/v3/integrations/logcontext-v2/nrslog/go.mod @@ -2,7 +2,18 @@ module github.com/newrelic/go-agent/v3/integrations/logcontext-v2/nrslog go 1.21 -require github.com/newrelic/go-agent/v3 v3.35.0 +require ( + github.com/newrelic/go-agent/v3 v3.35.0 + github.com/pkg/errors v0.9.1 +) +require ( + golang.org/x/net v0.25.0 // indirect + golang.org/x/sys v0.20.0 // indirect + golang.org/x/text v0.15.0 // indirect + google.golang.org/genproto/googleapis/rpc v0.0.0-20240528184218-531527333157 // indirect + google.golang.org/grpc v1.65.0 // indirect + google.golang.org/protobuf v1.34.2 // indirect +) replace github.com/newrelic/go-agent/v3 => ../../.. diff --git a/v3/integrations/logcontext-v2/nrslog/handler.go b/v3/integrations/logcontext-v2/nrslog/handler.go index 9c476910f..3d96b79de 100644 --- a/v3/integrations/logcontext-v2/nrslog/handler.go +++ b/v3/integrations/logcontext-v2/nrslog/handler.go @@ -1,9 +1,11 @@ package nrslog import ( + "bytes" "context" - "io" + "fmt" "log/slog" + "time" "github.com/newrelic/go-agent/v3/newrelic" ) @@ -11,90 +13,35 @@ import ( // NRHandler is an Slog handler that includes logic to implement New Relic Logs in Context type NRHandler struct { handler slog.Handler - w *LogWriter app *newrelic.Application txn *newrelic.Transaction } -// TextHandler creates a wrapped Slog TextHandler, enabling it to both automatically capture logs -// and to enrich logs locally depending on your logs in context configuration in your New Relic -// application. -func TextHandler(app *newrelic.Application, w io.Writer, opts *slog.HandlerOptions) NRHandler { - nrWriter := NewWriter(w, app) - textHandler := slog.NewTextHandler(nrWriter, opts) - wrappedHandler := WrapHandler(app, textHandler) - wrappedHandler.addWriter(&nrWriter) - return wrappedHandler -} - -// JSONHandler creates a wrapped Slog JSONHandler, enabling it to both automatically capture logs -// and to enrich logs locally depending on your logs in context configuration in your New Relic -// application. -func JSONHandler(app *newrelic.Application, w io.Writer, opts *slog.HandlerOptions) NRHandler { - nrWriter := NewWriter(w, app) - jsonHandler := slog.NewJSONHandler(nrWriter, opts) - wrappedHandler := WrapHandler(app, jsonHandler) - wrappedHandler.addWriter(&nrWriter) - return wrappedHandler -} - -// WithTransaction creates a new Slog Logger object to be used for logging within a given transaction. -// Calling this function with a logger having underlying TransactionFromContextHandler handler is a no-op. -func WithTransaction(txn *newrelic.Transaction, logger *slog.Logger) *slog.Logger { - if txn == nil || logger == nil { - return logger - } - - h := logger.Handler() - switch nrHandler := h.(type) { - case NRHandler: - txnHandler := nrHandler.WithTransaction(txn) - return slog.New(txnHandler) - default: - return logger - } -} - -// WithTransaction creates a new Slog Logger object to be used for logging within a given transaction it its found -// in a context. -// Calling this function with a logger having underlying TransactionFromContextHandler handler is a no-op. -func WithContext(ctx context.Context, logger *slog.Logger) *slog.Logger { - if ctx == nil { - return logger - } - - txn := newrelic.FromContext(ctx) - return WithTransaction(txn, logger) +// WithTransactionFromContext creates a wrapped NRHandler, enabling it to automatically reference New Relic +// +// Warning: This function is deprecated and will be removed in a future release. +func WithTransactionFromContext(handler *NRHandler) *NRHandler { + return handler } // WrapHandler returns a new handler that is wrapped with New Relic tools to capture // log data based on your application's logs in context settings. -func WrapHandler(app *newrelic.Application, handler slog.Handler) NRHandler { - return NRHandler{ +func WrapHandler(app *newrelic.Application, handler slog.Handler) *NRHandler { + return &NRHandler{ handler: handler, app: app, } } -// addWriter is an internal helper function to append an io.Writer to the NRHandler object -func (h *NRHandler) addWriter(w *LogWriter) { - h.w = w -} - // WithTransaction returns a new handler that is configured to capture log data // and attribute it to a specific transaction. -func (h *NRHandler) WithTransaction(txn *newrelic.Transaction) NRHandler { - handler := NRHandler{ +func (h *NRHandler) WithTransaction(txn *newrelic.Transaction) *NRHandler { + handler := &NRHandler{ handler: h.handler, app: h.app, txn: txn, } - if h.w != nil { - writer := h.w.WithTransaction(txn) - handler.addWriter(&writer) - } - return handler } @@ -107,7 +54,7 @@ func (h *NRHandler) WithTransaction(txn *newrelic.Transaction) NRHandler { // or the method does not take a context. // The context is passed so Enabled can use its values // to make a decision. -func (h NRHandler) Enabled(ctx context.Context, lvl slog.Level) bool { +func (h *NRHandler) Enabled(ctx context.Context, lvl slog.Level) bool { return h.handler.Enabled(ctx, lvl) } @@ -120,48 +67,98 @@ func (h NRHandler) Enabled(ctx context.Context, lvl slog.Level) bool { // cancellation-related problem.) // // Handle methods that produce output should observe the following rules: -// - If r.Time is the zero time, ignore the time. -// - If r.PC is zero, ignore it. +// - If r.Time is the zero time, time will not be added to your log print, but a timestamp will be sent to newrelic. // - Attr's values should be resolved. // - If an Attr's key and value are both the zero value, ignore the Attr. // This can be tested with attr.Equal(Attr{}). // - If a group's key is empty, inline the group's Attrs. // - If a group has no Attrs (even if it has a non-empty key), // ignore it. -func (h NRHandler) Handle(ctx context.Context, record slog.Record) error { +func (h *NRHandler) Handle(ctx context.Context, record slog.Record) error { attrs := map[string]interface{}{} record.Attrs(func(attr slog.Attr) bool { - attrs[attr.Key] = attr.Value.Any() + // ignore empty attributes + if !attr.Equal(slog.Attr{}) { + attrs[attr.Key] = attr.Value.Any() + } return true }) + // timestamp must be sent to newrelic + logTime := record.Time.UnixMilli() + if record.Time.IsZero() { + logTime = time.Now().UnixMilli() + } + data := newrelic.LogData{ Severity: record.Level.String(), - Timestamp: record.Time.UnixMilli(), + Timestamp: logTime, Message: record.Message, Attributes: attrs, } - if h.txn != nil { - h.txn.RecordLog(data) + + // attempt to get the transaction from the context + txn := newrelic.FromContext(ctx) + if txn == nil { + txn = h.txn + } + + if txn != nil { + txn.RecordLog(data) } else { h.app.RecordLog(data) } - return h.handler.Handle(ctx, record) + var err error + + // enrich log with newrelic metadata + // this will always return a valid log message even if an error occurs + enrichedRecord, enrichErr := enrichLog(record.Message, h.app, txn) + record.Message = enrichedRecord + if enrichErr != nil { + err = fmt.Errorf("failed to enrich logs with New Relic metadata: %v", enrichErr) + } + handleErr := h.handler.Handle(ctx, record) + if handleErr != nil { + if err != nil { + err = fmt.Errorf("%w; %w", err, handleErr) + } else { + err = handleErr + } + } + + return err +} + +// enrich log always returns a valid log message even if an error occurs +func enrichLog(record string, app *newrelic.Application, txn *newrelic.Transaction) (string, error) { + var buf *bytes.Buffer + var err error + + if txn != nil { + buf = bytes.NewBuffer([]byte(record)) + err = newrelic.EnrichLog(buf, newrelic.FromTxn(txn)) + } else if app != nil { + buf = bytes.NewBuffer([]byte(record)) + err = newrelic.EnrichLog(buf, newrelic.FromApp(app)) + } else { + return record, nil + } + + return buf.String(), err } // WithAttrs returns a new Handler whose attributes consist of // both the receiver's attributes and the arguments. // The Handler owns the slice: it may retain, modify or discard it. -func (h NRHandler) WithAttrs(attrs []slog.Attr) slog.Handler { +func (h *NRHandler) WithAttrs(attrs []slog.Attr) slog.Handler { handler := h.handler.WithAttrs(attrs) - return NRHandler{ + return &NRHandler{ handler: handler, app: h.app, txn: h.txn, } - } // WithGroup returns a new Handler with the given group appended to @@ -183,49 +180,11 @@ func (h NRHandler) WithAttrs(attrs []slog.Attr) slog.Handler { // logger.LogAttrs(level, msg, slog.Group("s", slog.Int("a", 1), slog.Int("b", 2))) // // If the name is empty, WithGroup returns the receiver. -func (h NRHandler) WithGroup(name string) slog.Handler { +func (h *NRHandler) WithGroup(name string) slog.Handler { handler := h.handler.WithGroup(name) - return NRHandler{ + return &NRHandler{ handler: handler, app: h.app, txn: h.txn, } } - -// NRHandler is an Slog handler that includes logic to implement New Relic Logs in Context. -// New Relic transaction value is taken from context. It cannot be set directly. -// This serves as a quality of life improvement for cases where slog.Default global instance is -// referenced, allowing to use slog methods directly and maintaining New Relic instrumentation. -type TransactionFromContextHandler struct { - NRHandler -} - -// WithTransactionFromContext creates a wrapped NRHandler, enabling it to automatically reference New Relic -// transaction from context. -func WithTransactionFromContext(handler NRHandler) TransactionFromContextHandler { - return TransactionFromContextHandler{handler} -} - -// Handle handles the Record. -// It will only be called when Enabled returns true. -// The Context argument is as for Enabled and NewRelic transaction. -// Canceling the context should not affect record processing. -// (Among other things, log messages may be necessary to debug a -// cancellation-related problem.) -// -// Handle methods that produce output should observe the following rules: -// - If r.Time is the zero time, ignore the time. -// - If r.PC is zero, ignore it. -// - Attr's values should be resolved. -// - If an Attr's key and value are both the zero value, ignore the Attr. -// This can be tested with attr.Equal(Attr{}). -// - If a group's key is empty, inline the group's Attrs. -// - If a group has no Attrs (even if it has a non-empty key), -// ignore it. -func (h TransactionFromContextHandler) Handle(ctx context.Context, record slog.Record) error { - if txn := newrelic.FromContext(ctx); txn != nil { - return h.NRHandler.WithTransaction(txn).Handle(ctx, record) - } - - return h.NRHandler.Handle(ctx, record) -} diff --git a/v3/integrations/logcontext-v2/nrslog/handler_test.go b/v3/integrations/logcontext-v2/nrslog/handler_test.go index 4e3d6d774..263011261 100644 --- a/v3/integrations/logcontext-v2/nrslog/handler_test.go +++ b/v3/integrations/logcontext-v2/nrslog/handler_test.go @@ -7,6 +7,7 @@ import ( "os" "strings" "testing" + "time" "github.com/newrelic/go-agent/v3/internal" "github.com/newrelic/go-agent/v3/internal/integrationsupport" @@ -19,13 +20,39 @@ var ( host, _ = sysinfo.Hostname() ) -func TestHandler(t *testing.T) { +func TestHandlerZeroTime(t *testing.T) { app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn, newrelic.ConfigAppLogDecoratingEnabled(true), newrelic.ConfigAppLogForwardingEnabled(true), ) out := bytes.NewBuffer([]byte{}) - handler := TextHandler(app.Application, out, &slog.HandlerOptions{}) + handler := WrapHandler(app.Application, slog.NewTextHandler(out, &slog.HandlerOptions{})) + handler.Handle(context.Background(), slog.Record{ + Level: slog.LevelInfo, + Message: "Hello World!", + Time: time.Time{}, + }) + logcontext.ValidateDecoratedOutput(t, out, &logcontext.DecorationExpect{ + EntityGUID: integrationsupport.TestEntityGUID, + Hostname: host, + EntityName: integrationsupport.SampleAppName, + }) + app.ExpectLogEvents(t, []internal.WantLog{ + { + Severity: slog.LevelInfo.String(), + Message: "Hello World!", + Timestamp: internal.MatchAnyUnixMilli, + }, + }) +} + +func TestWrapHandler(t *testing.T) { + app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn, + newrelic.ConfigAppLogDecoratingEnabled(true), + newrelic.ConfigAppLogForwardingEnabled(true), + ) + out := bytes.NewBuffer([]byte{}) + handler := WrapHandler(app.Application, slog.NewTextHandler(out, &slog.HandlerOptions{})) log := slog.New(handler) message := "Hello World!" log.Info(message) @@ -89,12 +116,11 @@ func TestHandlerTransactions(t *testing.T) { log.Debug(backgroundMsg) txn.End() - /* - logcontext.ValidateDecoratedOutput(t, out, &logcontext.DecorationExpect{ - EntityGUID: integrationsupport.TestEntityGUID, - Hostname: host, - EntityName: integrationsupport.SampleAppName, - }) */ + logcontext.ValidateDecoratedOutput(t, out, &logcontext.DecorationExpect{ + EntityGUID: integrationsupport.TestEntityGUID, + Hostname: host, + EntityName: integrationsupport.SampleAppName, + }) app.ExpectLogEvents(t, []internal.WantLog{ { @@ -134,6 +160,8 @@ func TestHandlerTransactionCtx(t *testing.T) { EntityGUID: integrationsupport.TestEntityGUID, Hostname: host, EntityName: integrationsupport.SampleAppName, + SpanID: txninfo.SpanID, + TraceID: txninfo.TraceID, }) app.ExpectLogEvents(t, []internal.WantLog{ @@ -202,7 +230,8 @@ func TestWithAttributes(t *testing.T) { handler := TextHandler(app.Application, out, &slog.HandlerOptions{}) log := slog.New(handler) message := "Hello World!" - log = log.With(slog.String("string key", "val"), slog.Int("int key", 1)) + emptyAttr := slog.Attr{} + log = log.With(slog.String("string key", "val"), slog.Int("int key", 1), emptyAttr) log.Info(message) @@ -220,10 +249,13 @@ func TestWithAttributes(t *testing.T) { t.Errorf("expected %s to contain %s", log1, attrString) } + if strings.Contains(log1, emptyAttr.String()) { + t.Errorf("expected %s to not contain empty attributes %+v", log1, emptyAttr) + } + if !strings.Contains(log2, attrString) { t.Errorf("expected %s to contain %s", log2, attrString) } - } func TestWithAttributesFromContext(t *testing.T) { @@ -244,6 +276,7 @@ func TestWithAttributesFromContext(t *testing.T) { slog.Any("some_map", map[string]interface{}{"a": 1.0, "b": 2}), ) + txninfo := txn.GetLinkingMetadata() txn.End() app.ExpectLogEvents(t, []internal.WantLog{ @@ -261,10 +294,12 @@ func TestWithAttributesFromContext(t *testing.T) { "answer": 42, "some_map": map[string]interface{}{"a": 1.0, "b": 2}, }, + SpanID: txninfo.SpanID, + TraceID: txninfo.TraceID, }, }) - } + func TestWithGroup(t *testing.T) { app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn, newrelic.ConfigAppLogDecoratingEnabled(false), diff --git a/v3/integrations/logcontext-v2/nrslog/logger.go b/v3/integrations/logcontext-v2/nrslog/logger.go new file mode 100644 index 000000000..dded46508 --- /dev/null +++ b/v3/integrations/logcontext-v2/nrslog/logger.go @@ -0,0 +1,52 @@ +package nrslog + +import ( + "context" + "io" + "log/slog" + + "github.com/newrelic/go-agent/v3/newrelic" +) + +// TextHandler is a wrapper on slog.NewTextHandler that includes New Relic Logs in Context. +// This method has been preserved for backwards compatibility, but is not longer recommended. +// Deprecated: Use WrapHandler instead. +func TextHandler(app *newrelic.Application, w io.Writer, opts *slog.HandlerOptions) *NRHandler { + return WrapHandler(app, slog.NewTextHandler(w, opts)) +} + +// TextHandler is a wrapper on slog.NewTextHandler that includes New Relic Logs in Context. +// This method has been preserved for backwards compatibility, but is not longer recommended. +// Deprecated: Use WrapHandler instead. +func JSONHandler(app *newrelic.Application, w io.Writer, opts *slog.HandlerOptions) *NRHandler { + return WrapHandler(app, slog.NewJSONHandler(w, opts)) +} + +// WithTransaction creates a new Slog Logger object to be used for logging within a given transaction. +// If no transaction is found, the original logger will be returned. +func WithTransaction(txn *newrelic.Transaction, logger *slog.Logger) *slog.Logger { + if txn == nil || logger == nil { + return logger + } + + h := logger.Handler() + switch nrHandler := h.(type) { + case *NRHandler: + txnHandler := nrHandler.WithTransaction(txn) + return slog.New(txnHandler) + default: + return logger + } +} + +// WithContext creates a new Slog Logger object if a transaction is found in the context. +// The new logger will exclusively log for a given transaction. +// If no transaction is found, the original logger is returned. +func WithContext(ctx context.Context, logger *slog.Logger) *slog.Logger { + if ctx == nil { + return logger + } + + txn := newrelic.FromContext(ctx) + return WithTransaction(txn, logger) +} diff --git a/v3/integrations/logcontext-v2/nrslog/writer.go b/v3/integrations/logcontext-v2/nrslog/writer.go deleted file mode 100644 index 4248469a4..000000000 --- a/v3/integrations/logcontext-v2/nrslog/writer.go +++ /dev/null @@ -1,70 +0,0 @@ -package nrslog - -import ( - "bytes" - "io" - - "github.com/newrelic/go-agent/v3/newrelic" -) - -// LogWriter is an io.Writer that captures log data for use with New Relic Logs in Context -type LogWriter struct { - debug bool - out io.Writer - app *newrelic.Application - txn *newrelic.Transaction -} - -// New creates a new NewRelicWriter Object -// output is the io.Writer destination that you want your log to be written to -// app must be a vaild, non nil new relic Application -func NewWriter(output io.Writer, app *newrelic.Application) LogWriter { - return LogWriter{ - out: output, - app: app, - } -} - -// DebugLogging enables or disables debug error messages being written in the IO output. -// By default, the nrwriter debug logging is set to false and will fail silently -func (b *LogWriter) DebugLogging(enabled bool) { - b.debug = enabled -} - -// WithTransaction duplicates the current NewRelicWriter and sets the transaction to txn -func (b *LogWriter) WithTransaction(txn *newrelic.Transaction) LogWriter { - return LogWriter{ - out: b.out, - app: b.app, - debug: b.debug, - txn: txn, - } -} - -// EnrichLog attempts to enrich a log with New Relic linking metadata. If it fails, -// it will return the original log line unless debug=true, otherwise it will print -// an error on a following line. -func (b *LogWriter) EnrichLog(p []byte) []byte { - logLine := bytes.TrimRight(p, "\n") - buf := bytes.NewBuffer(logLine) - - var enrichErr error - if b.txn != nil { - enrichErr = newrelic.EnrichLog(buf, newrelic.FromTxn(b.txn)) - } else { - enrichErr = newrelic.EnrichLog(buf, newrelic.FromApp(b.app)) - } - - if b.debug && enrichErr != nil { - buf.WriteString("\n") - buf.WriteString(enrichErr.Error()) - } - - buf.WriteString("\n") - return buf.Bytes() -} - -// Write implements io.Write -func (b LogWriter) Write(p []byte) (n int, err error) { - return b.out.Write(b.EnrichLog(p)) -}