28% faster log enrichment

Author: Emilio Garcia

v3/integrations/logcontext-v2/nrslog/go.mod

@@ -4,13 +4,4 @@ go 1.21
 
 require github.com/newrelic/go-agent/v3 v3.36.0
 
-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 => ../../..

v3/integrations/logcontext-v2/nrslog/handler.go

@@ -1,7 +1,6 @@
 package nrslog
 
 import (
-	"bytes"
 	"context"
 	"log/slog"
 	"time"
@@ -36,12 +35,19 @@ func (h *NRHandler) Enabled(ctx context.Context, lvl slog.Level) bool {
 
 // Handle handles the Record.
 // It will only be called when Enabled returns true.
-// The Context argument is as for Enabled.
-// It is present solely to provide Handlers access to the context's values.
-// Canceling the context should not affect record processing.
-// (Among other things, log messages may be necessary to debug a
-// cancellation-related problem.)
 func (h *NRHandler) Handle(ctx context.Context, record slog.Record) error {
+	nrTxn := h.txn
+
+	ctxTxn := newrelic.FromContext(ctx)
+	if ctxTxn != nil {
+		nrTxn = ctxTxn
+	}
+
+	// if no app or txn, do nothing
+	if h.app == nil && nrTxn == nil {
+		return h.handler.Handle(ctx, record)
+	}
+
 	attrs := map[string]interface{}{}
 
 	record.Attrs(func(attr slog.Attr) bool {
@@ -67,32 +73,15 @@ func (h *NRHandler) Handle(ctx context.Context, record slog.Record) error {
 		Attributes: attrs,
 	}
 
-	nrTxn := h.txn
-
-	ctxTxn := newrelic.FromContext(ctx)
-	if ctxTxn != nil {
-		nrTxn = ctxTxn
-	}
-
-	var enricherOpts newrelic.EnricherOption
 	if nrTxn != nil {
 		nrTxn.RecordLog(data)
-		enricherOpts = newrelic.FromTxn(nrTxn)
+		enrichRecordTxn(nrTxn, &record)
 	} else {
 		h.app.RecordLog(data)
-		enricherOpts = newrelic.FromApp(h.app)
-	}
-
-	// add linking metadata as an attribute
-	// without disrupting normal usage of the handler
-	nrLinking := bytes.NewBuffer([]byte{})
-	err := newrelic.EnrichLog(nrLinking, enricherOpts)
-	if err == nil {
-		record.AddAttrs(slog.String("newrelic", nrLinking.String()))
+		enrichRecord(h.app, &record)
 	}
 
-	err = h.handler.Handle(ctx, record)
-	return err
+	return h.handler.Handle(ctx, record)
 }
 
 // WithAttrs returns a new Handler whose attributes consist of

v3/integrations/logcontext-v2/nrslog/handler_test.go

@@ -42,6 +42,21 @@ func TestHandler(t *testing.T) {
 	})
 }
 
+func TestHandlerNilApp(t *testing.T) {
+	out := bytes.NewBuffer([]byte{})
+	logger := New(nil, slog.NewTextHandler(out, &slog.HandlerOptions{}))
+	message := "Hello World!"
+	logger.Info(message)
+
+	logStr := out.String()
+	if strings.Contains(logStr, nrlinking) {
+		t.Errorf(" %s should not contain %s", logStr, nrlinking)
+	}
+	if len(logStr) == 0 {
+		t.Errorf("log string should not be empty")
+	}
+}
+
 func TestJSONHandler(t *testing.T) {
 	app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn,
 		newrelic.ConfigAppLogDecoratingEnabled(true),
@@ -88,12 +103,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{
 		{
@@ -361,11 +375,57 @@ func TestTransactionFromContextHandler(t *testing.T) {
 	})
 }
 
-// shockingly cheap
-func BenchmarkGetContextValue(b *testing.B) {
-	var a *bytes.Buffer
+func BenchmarkEnrichLog(b *testing.B) {
+	app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn,
+		newrelic.ConfigAppLogDecoratingEnabled(true),
+		newrelic.ConfigAppLogForwardingEnabled(true),
+	)
+	txn := app.Application.StartTransaction("my txn")
+	defer txn.End()
+	record := slog.Record{}
+
+	b.ResetTimer()
+	b.ReportAllocs()
+
+	for i := 0; i < b.N; i++ {
+		nrLinking := bytes.NewBuffer([]byte{})
+		err := newrelic.EnrichLog(nrLinking, newrelic.FromTxn(txn))
+		if err == nil {
+			record.AddAttrs(slog.String("newrelic", nrLinking.String()))
+		}
+	}
+}
+
+func BenchmarkLinkingStringEnrichment(b *testing.B) {
+	app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn,
+		newrelic.ConfigAppLogDecoratingEnabled(true),
+		newrelic.ConfigAppLogForwardingEnabled(true),
+	)
+	txn := app.Application.StartTransaction("my txn")
+	defer txn.End()
+	record := slog.Record{}
+
+	b.ResetTimer()
+	b.ReportAllocs()
+
+	for i := 0; i < b.N; i++ {
+		enrichRecordTxn(txn, &record)
+	}
+}
+
+func BenchmarkStringBuilder(b *testing.B) {
+	md := newrelic.LinkingMetadata{
+		EntityGUID: "entityGUID",
+		Hostname:   "hostname",
+		TraceID:    "traceID",
+		SpanID:     "spanID",
+		EntityName: "entityName",
+	}
+
+	b.ResetTimer()
+	b.ReportAllocs()
+
 	for i := 0; i < b.N; i++ {
-		a = bytes.NewBuffer([]byte{})
+		nrLinkingString(md)
 	}
-	a.Reset()
 }

v3/integrations/logcontext-v2/nrslog/linking.go

@@ -0,0 +1,74 @@
+package nrslog
+
+import (
+	"log/slog"
+	"strings"
+
+	"github.com/newrelic/go-agent/v3/newrelic"
+)
+
+const (
+	nrlinking = "NR-LINKING"
+	key       = "newrelic"
+)
+
+func enrichRecord(app *newrelic.Application, record *slog.Record) {
+	if !shouldEnrichLog(app) {
+		return
+	}
+
+	str := nrLinkingString(app.GetLinkingMetadata())
+	if str == "" {
+		return
+	}
+
+	record.AddAttrs(slog.String(key, str))
+}
+
+func enrichRecordTxn(txn *newrelic.Transaction, record *slog.Record) {
+	if !shouldEnrichLog(txn.Application()) {
+		return
+	}
+
+	str := nrLinkingString(txn.GetLinkingMetadata())
+	if str == "" {
+		return
+	}
+
+	record.AddAttrs(slog.String(key, str))
+}
+
+func shouldEnrichLog(app *newrelic.Application) bool {
+	config, ok := app.Config()
+	if !ok {
+		return false
+	}
+
+	return config.ApplicationLogging.Enabled && config.ApplicationLogging.LocalDecorating.Enabled
+}
+
+// nrLinkingString returns a string that represents the linking metadata
+func nrLinkingString(data newrelic.LinkingMetadata) string {
+	if data.EntityGUID == "" {
+		return ""
+	}
+
+	len := 16 + len(data.EntityGUID) + len(data.Hostname) + len(data.TraceID) + len(data.SpanID) + len(data.EntityName)
+	str := strings.Builder{}
+	str.Grow(len) // only 1 alloc
+
+	str.WriteString(nrlinking)
+	str.WriteByte('|')
+	str.WriteString(data.EntityGUID)
+	str.WriteByte('|')
+	str.WriteString(data.Hostname)
+	str.WriteByte('|')
+	str.WriteString(data.TraceID)
+	str.WriteByte('|')
+	str.WriteString(data.SpanID)
+	str.WriteByte('|')
+	str.WriteString(data.EntityName)
+	str.WriteByte('|')
+
+	return str.String()
+}

v3/newrelic/application.go

@@ -39,6 +39,31 @@ func (app *Application) IsAIMonitoringEnabled(integration string, streaming bool
 }
 */
 
+// GetLinkingMetadata returns the fields needed to link data to
+// an entity. This will return an empty struct if the application
+// is not connected or nil.
+func (app *Application) GetLinkingMetadata() LinkingMetadata {
+	if app == nil || app.app == nil {
+		return LinkingMetadata{}
+	}
+
+	reply, err := app.app.getState()
+	if err != nil {
+		app.app.Error("unable to record custom event", map[string]interface{}{
+			"event-type": "AppState",
+			"reason":     err.Error(),
+		})
+	}
+
+	md := LinkingMetadata{
+		EntityName: app.app.config.AppName,
+		Hostname:   app.app.config.hostname,
+		EntityGUID: reply.Reply.EntityGUID,
+	}
+
+	return md
+}
+
 // StartTransaction begins a Transaction with the given name.
 func (app *Application) StartTransaction(name string, opts ...TraceOption) *Transaction {
 	if app == nil {