Merge pull request #902 from mirackara/nrzaplogattribs

Zap Field Attributes Reporting

v3/integrations/logcontext-v2/nrzap/example/main.go

@@ -1,6 +1,7 @@
 package main
 
 import (
+	"errors"
 	"os"
 	"time"
 
@@ -14,7 +15,10 @@ func main() {
 	app, err := newrelic.NewApplication(
 		newrelic.ConfigAppName("nrzerolog example"),
 		newrelic.ConfigInfoLogger(os.Stdout),
+		newrelic.ConfigDebugLogger(os.Stdout),
 		newrelic.ConfigFromEnvironment(),
+		// This is enabled by default. if disabled, the attributes will be marshalled at harvest time.
+		newrelic.ConfigZapAttributesEncoder(false),
 	)
 	if err != nil {
 		panic(err)
@@ -29,16 +33,29 @@ func main() {
 	}
 
 	backgroundLogger := zap.New(backgroundCore)
-	backgroundLogger.Info("this is a background log message")
+	backgroundLogger.Info("this is a background log message with fields test", zap.Any("foo", 3.14))
 
 	txn := app.StartTransaction("nrzap example transaction")
 	txnCore, err := nrzap.WrapTransactionCore(core, txn)
 	if err != nil && err != nrzap.ErrNilTxn {
 		panic(err)
 	}
-
 	txnLogger := zap.New(txnCore)
-	txnLogger.Info("this is a transaction log message")
+	txnLogger.Info("this is a transaction log message with custom fields",
+		zap.String("zapstring", "region-test-2"),
+		zap.Int("zapint", 123),
+		zap.Duration("zapduration", 200*time.Millisecond),
+		zap.Bool("zapbool", true),
+		zap.Object("zapobject", zapcore.ObjectMarshalerFunc(func(enc zapcore.ObjectEncoder) error {
+			enc.AddString("foo", "bar")
+			return nil
+		})),
+
+		zap.Any("zapmap", map[string]any{"pi": 3.14, "duration": 2 * time.Second}),
+	)
+
+	err = errors.New("OW! an error occurred")
+	txnLogger.Error("this is an error log message", zap.Error(err))
 
 	txn.End()
 

v3/integrations/logcontext-v2/nrzap/nrzap.go

@@ -2,6 +2,8 @@ package nrzap
 
 import (
 	"errors"
+	"math"
+	"time"
 
 	"github.com/newrelic/go-agent/v3/internal"
 	"github.com/newrelic/go-agent/v3/newrelic"
@@ -24,12 +26,79 @@ type newrelicApplicationState struct {
 	txn *newrelic.Transaction
 }
 
+// Helper function that converts zap fields to a map of string interface
+func convertFieldWithMapEncoder(fields []zap.Field) map[string]interface{} {
+	attributes := make(map[string]interface{})
+	for _, field := range fields {
+		enc := zapcore.NewMapObjectEncoder()
+		field.AddTo(enc)
+		for key, value := range enc.Fields {
+			// Format time.Duration values as strings
+			if durationVal, ok := value.(time.Duration); ok {
+				attributes[key] = durationVal.String()
+			} else {
+				attributes[key] = value
+			}
+		}
+	}
+	return attributes
+}
+
+func convertFieldsAtHarvestTime(fields []zap.Field) map[string]interface{} {
+	attributes := make(map[string]interface{})
+	for _, field := range fields {
+		if field.Interface != nil {
+
+			// Handles ErrorType fields
+			if field.Type == zapcore.ErrorType {
+				attributes[field.Key] = field.Interface.(error).Error()
+			} else {
+				// Handles all interface types
+				attributes[field.Key] = field.Interface
+			}
+
+		} else if field.String != "" { // Check if the field is a string and doesn't contain an interface
+			attributes[field.Key] = field.String
+
+		} else {
+			// Float Types
+			if field.Type == zapcore.Float32Type {
+				attributes[field.Key] = math.Float32frombits(uint32(field.Integer))
+				continue
+			} else if field.Type == zapcore.Float64Type {
+				attributes[field.Key] = math.Float64frombits(uint64(field.Integer))
+				continue
+			}
+			// Bool Type
+			if field.Type == zapcore.BoolType {
+				field.Interface = field.Integer == 1
+				attributes[field.Key] = field.Interface
+			} else {
+				// Integer Types
+				attributes[field.Key] = field.Integer
+
+			}
+		}
+	}
+	return attributes
+}
+
 // internal handler function to manage writing a log to the new relic application
 func (nr *newrelicApplicationState) recordLog(entry zapcore.Entry, fields []zap.Field) {
+	attributes := map[string]interface{}{}
+	cfg, _ := nr.app.Config()
+
+	// Check if the attributes should be frontloaded or marshalled at harvest time
+	if cfg.ApplicationLogging.ZapLogger.AttributesFrontloaded {
+		attributes = convertFieldWithMapEncoder(fields)
+	} else {
+		attributes = convertFieldsAtHarvestTime(fields)
+	}
 	data := newrelic.LogData{
-		Timestamp: entry.Time.UnixMilli(),
-		Severity:  entry.Level.String(),
-		Message:   entry.Message,
+		Timestamp:  entry.Time.UnixMilli(),
+		Severity:   entry.Level.String(),
+		Message:    entry.Message,
+		Attributes: attributes,
 	}
 
 	if nr.txn != nil {

v3/integrations/logcontext-v2/nrzap/nrzap_test.go

@@ -5,6 +5,7 @@ import (
 	"io"
 	"os"
 	"testing"
+	"time"
 
 	"github.com/newrelic/go-agent/v3/internal"
 	"github.com/newrelic/go-agent/v3/internal/integrationsupport"
@@ -131,6 +132,9 @@ func TestTransactionLogger(t *testing.T) {
 
 	app.ExpectLogEvents(t, []internal.WantLog{
 		{
+			Attributes: map[string]interface{}{
+				"test-key": "test-val",
+			},
 			Severity:  zap.ErrorLevel.String(),
 			Message:   msg,
 			Timestamp: internal.MatchAnyUnixMilli,
@@ -140,6 +144,110 @@ func TestTransactionLogger(t *testing.T) {
 	})
 }
 
+func TestTransactionLoggerWithFields(t *testing.T) {
+	app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn,
+		newrelic.ConfigAppLogDecoratingEnabled(true),
+		newrelic.ConfigAppLogForwardingEnabled(true),
+		newrelic.ConfigZapAttributesEncoder(true),
+	)
+
+	txn := app.StartTransaction("test transaction")
+	txnMetadata := txn.GetTraceMetadata()
+
+	core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), os.Stdout, zap.InfoLevel)
+	wrappedCore, err := WrapTransactionCore(core, txn)
+	if err != nil {
+		t.Error(err)
+	}
+
+	logger := zap.New(wrappedCore)
+
+	msg := "this is a test info message"
+
+	// for background logging:
+	logger.Info(msg,
+		zap.String("region", "region-test-2"),
+		zap.Any("anyValue", map[string]interface{}{"pi": 3.14, "duration": 2 * time.Second}),
+		zap.Duration("duration", 1*time.Second),
+		zap.Int("int", 123),
+		zap.Bool("bool", true),
+	)
+
+	logger.Sync()
+
+	// ensure txn gets written to an event and logs get released
+	txn.End()
+
+	app.ExpectLogEvents(t, []internal.WantLog{
+		{
+			Attributes: map[string]interface{}{
+				"region":   "region-test-2",
+				"anyValue": map[string]interface{}{"pi": 3.14, "duration": 2 * time.Second},
+				"duration": 1 * time.Second,
+				"int":      123,
+				"bool":     true,
+			},
+			Severity:  zap.InfoLevel.String(),
+			Message:   msg,
+			Timestamp: internal.MatchAnyUnixMilli,
+			TraceID:   txnMetadata.TraceID,
+			SpanID:    txnMetadata.SpanID,
+		},
+	})
+}
+
+func TestTransactionLoggerWithFieldsAtHarvestTime(t *testing.T) {
+	app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn,
+		newrelic.ConfigAppLogDecoratingEnabled(true),
+		newrelic.ConfigAppLogForwardingEnabled(true),
+		newrelic.ConfigZapAttributesEncoder(false),
+	)
+
+	txn := app.StartTransaction("test transaction")
+	txnMetadata := txn.GetTraceMetadata()
+
+	core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), os.Stdout, zap.InfoLevel)
+	wrappedCore, err := WrapTransactionCore(core, txn)
+	if err != nil {
+		t.Error(err)
+	}
+
+	logger := zap.New(wrappedCore)
+
+	msg := "this is a test info message"
+
+	// for background logging:
+	logger.Info(msg,
+		zap.String("region", "region-test-2"),
+		zap.Any("anyValue", map[string]interface{}{"pi": 3.14, "duration": 2 * time.Second}),
+		zap.Duration("duration", 1*time.Second),
+		zap.Int("int", 123),
+		zap.Bool("bool", true),
+	)
+
+	logger.Sync()
+
+	// ensure txn gets written to an event and logs get released
+	txn.End()
+
+	app.ExpectLogEvents(t, []internal.WantLog{
+		{
+			Attributes: map[string]interface{}{
+				"region":   "region-test-2",
+				"anyValue": map[string]interface{}{"pi": 3.14, "duration": 2 * time.Second},
+				"duration": 1 * time.Second,
+				"int":      123,
+				"bool":     true,
+			},
+			Severity:  zap.InfoLevel.String(),
+			Message:   msg,
+			Timestamp: internal.MatchAnyUnixMilli,
+			TraceID:   txnMetadata.TraceID,
+			SpanID:    txnMetadata.SpanID,
+		},
+	})
+}
+
 func TestTransactionLoggerNilTxn(t *testing.T) {
 	app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn,
 		newrelic.ConfigAppLogDecoratingEnabled(true),
@@ -204,6 +312,41 @@ func BenchmarkZapBaseline(b *testing.B) {
 	}
 }
 
+func BenchmarkFieldConversion(b *testing.B) {
+	b.ResetTimer()
+	b.ReportAllocs()
+
+	for i := 0; i < b.N; i++ {
+		convertFieldWithMapEncoder([]zap.Field{
+			zap.String("test-key", "test-val"),
+			zap.Any("test-key", map[string]interface{}{"pi": 3.14, "duration": 2 * time.Second}),
+		})
+	}
+}
+
+func BenchmarkFieldUnmarshalling(b *testing.B) {
+	b.ResetTimer()
+	b.ReportAllocs()
+	for i := 0; i < b.N; i++ {
+		convertFieldsAtHarvestTime([]zap.Field{
+			zap.String("test-key", "test-val"),
+			zap.Any("test-key", map[string]interface{}{"pi": 3.14, "duration": 2 * time.Second}),
+		})
+
+	}
+}
+
+func BenchmarkZapWithAttribute(b *testing.B) {
+	core := zapcore.NewCore(zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(io.Discard), zap.InfoLevel)
+	logger := zap.New(core)
+	b.ResetTimer()
+	b.ReportAllocs()
+
+	for i := 0; i < b.N; i++ {
+		logger.Info("this is a test message", zap.Any("test-key", "test-val"))
+	}
+}
+
 func BenchmarkZapWrappedCore(b *testing.B) {
 	app := integrationsupport.NewTestApp(integrationsupport.SampleEverythingReplyFn,
 		newrelic.ConfigAppLogDecoratingEnabled(true),

v3/internal/expect.go

@@ -29,11 +29,12 @@ type WantError struct {
 
 // WantLog is a traced log event expectation
 type WantLog struct {
-	Severity  string
-	Message   string
-	SpanID    string
-	TraceID   string
-	Timestamp int64
+	Attributes map[string]interface{}
+	Severity   string
+	Message    string
+	SpanID     string
+	TraceID    string
+	Timestamp  int64
 }
 
 func uniquePointer() *struct{} {

v3/newrelic/attributes_from_internal.go

@@ -5,10 +5,12 @@ package newrelic
 
 import (
 	"bytes"
+	"encoding/json"
 	"fmt"
 	"math"
 	"net/http"
 	"net/url"
+	"reflect"
 	"sort"
 	"strconv"
 	"strings"
@@ -19,6 +21,9 @@ const (
 	// listed as span attributes to simplify code. It is not listed in the
 	// public attributes.go file for this reason to prevent confusion.
 	spanAttributeQueryParameters = "query_parameters"
+
+	// The collector can only allow attributes to be a maximum of 256 bytes
+	maxAttributeLengthBytes = 256
 )
 
 var (
@@ -452,6 +457,9 @@ func addUserAttribute(a *attributes, key string, val interface{}, d destinationS
 func writeAttributeValueJSON(w *jsonFieldsWriter, key string, val interface{}) {
 	switch v := val.(type) {
 	case string:
+		if len(v) > maxAttributeLengthBytes {
+			v = v[:maxAttributeLengthBytes]
+		}
 		w.stringField(key, v)
 	case bool:
 		if v {
@@ -486,7 +494,17 @@ func writeAttributeValueJSON(w *jsonFieldsWriter, key string, val interface{}) {
 	case float64:
 		w.floatField(key, v)
 	default:
-		w.stringField(key, fmt.Sprintf("%T", v))
+		// attempt to construct a JSON string
+		kind := reflect.ValueOf(v).Kind()
+		if kind == reflect.Struct || kind == reflect.Map || kind == reflect.Slice || kind == reflect.Array {
+			bytes, _ := json.Marshal(v)
+			if len(bytes) > maxAttributeLengthBytes {
+				bytes = bytes[:maxAttributeLengthBytes]
+			}
+			w.stringField(key, string(bytes))
+		} else {
+			w.stringField(key, fmt.Sprintf("%T", v))
+		}
 	}
 }