Merge branch 'fix/PRXS-2061-FixFieldDuplicates' into 'master'

Исправлено дублирование полей в фильтрующем zap core

See merge request perxis/perxis-go!176

logs/zap/core.go

 package zap
 
 import (
-	"fmt"
-
-	oid "git.perx.ru/perxis/perxis-go/id"
 	"git.perx.ru/perxis/perxis-go/logs"
-	"git.perx.ru/perxis/perxis-go/pkg/id"
-	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )
 
@@ -20,22 +15,25 @@ type WriteSyncer interface {
 type Core struct {
 	zapcore.LevelEnabler
 
-	writeSyncer WriteSyncer
-	fields      []zap.Field
+	ws  WriteSyncer
+	enc Encoder
 }
 
 func NewCore(writeSyncer WriteSyncer) *Core {
 	return &Core{
 		LevelEnabler: zapcore.InfoLevel,
-		writeSyncer:  writeSyncer,
+		ws:           writeSyncer,
+		enc:          NewEntryEncoder(),
 	}
 }
 
 func (core *Core) With(fields []zapcore.Field) zapcore.Core {
+	enc := core.enc.Clone()
+	enc.AddFields(fields)
 	return &Core{
 		LevelEnabler: core.LevelEnabler,
-		writeSyncer:  core.writeSyncer,
-		fields:       append(core.fields, fields...),
+		ws:           core.ws,
+		enc:          enc,
 	}
 }
 
@@ -47,48 +45,13 @@ func (core *Core) Check(entry zapcore.Entry, checkedEntry *zapcore.CheckedEntry)
 }
 
 func (core *Core) Write(entry zapcore.Entry, fields []zapcore.Field) error {
-	return core.writeSyncer.Write(core.getEntry(entry, fields))
+	encodedEntry, err := core.enc.EncodeEntry(entry, fields)
+	if err != nil {
+		return err
 	}
-
-func (core *Core) Sync() error {
-	return core.writeSyncer.Sync()
-}
-
-func (core *Core) getEntry(entry zapcore.Entry, fields []zapcore.Field) *logs.Entry {
-	if len(core.fields) > 0 {
-		fields = append(fields, core.fields...)
-	}
-
-	enc := zapcore.NewMapObjectEncoder()
-	for _, field := range fields {
-		field.AddTo(enc)
-	}
-
-	ent := &logs.Entry{
-		ID:        id.GenerateNewID(),
-		Timestamp: entry.Time,
-		Level:     logs.Level(entry.Level),
-		Message:   entry.Message,
+	return core.ws.Write(encodedEntry)
 }
 
-	ent.Category, _ = enc.Fields["category"].(string)
-	ent.Component, _ = enc.Fields["component"].(string)
-	ent.Event, _ = enc.Fields["event"].(string)
-	ent.ObjectID, _ = enc.Fields["object"].(*oid.ObjectId)
-	ent.CallerID, _ = enc.Fields["caller"].(*oid.ObjectId)
-	ent.Attr = enc.Fields["attr"]
-
-	if err, _ := enc.Fields["error"].(error); err != nil {
-		ent.Message = fmt.Sprintf("%s. Error: %s", ent.Message, err.Error())
-	}
-
-	if tags, ok := enc.Fields["tags"].([]any); ok {
-		for _, item := range tags {
-			if tag, ok := item.(string); ok {
-				ent.Tags = append(ent.Tags, tag)
-			}
-		}
-	}
-
-	return ent
+func (core *Core) Sync() error {
+	return core.ws.Sync()
 }

logs/zap/entry_encoder.go

+package zap
+
+import (
+	"fmt"
+	"slices"
+
+	oid "git.perx.ru/perxis/perxis-go/id"
+	"git.perx.ru/perxis/perxis-go/logs"
+	"git.perx.ru/perxis/perxis-go/pkg/id"
+	"git.perx.ru/perxis/perxis-go/zap"
+	"go.uber.org/zap/zapcore"
+)
+
+type Encoder interface {
+	Clone() Encoder
+	AddFields([]zapcore.Field)
+	EncodeEntry(zapcore.Entry, []zapcore.Field) (*logs.Entry, error)
+}
+
+type entryEncoder struct {
+	fields []zapcore.Field
+}
+
+func NewEntryEncoder() Encoder {
+	return &entryEncoder{}
+}
+
+func (enc *entryEncoder) AddFields(fields []zapcore.Field) {
+	enc.fields = slices.Concat(enc.fields, fields)
+}
+
+func (enc *entryEncoder) Clone() Encoder {
+	return enc.clone()
+}
+
+func (enc *entryEncoder) clone() *entryEncoder {
+	return &entryEncoder{fields: slices.Clone(enc.fields)}
+}
+
+func (enc *entryEncoder) EncodeEntry(entry zapcore.Entry, fields []zapcore.Field) (*logs.Entry, error) {
+	ent := &logs.Entry{
+		ID:        id.GenerateNewID(),
+		Timestamp: entry.Time,
+		Level:     logs.Level(entry.Level),
+		Message:   entry.Message,
+	}
+
+	clone := enc.clone()
+	clone.AddFields(fields)
+
+	for i := range clone.fields {
+		switch clone.fields[i].Key {
+		// При добавлении новых полей стоит учитывать, как zap хранит значения в структуре Field.
+		// Например:
+		// zap.Bool хранит bool как 1/0 в поле Field.Integer
+		case "category":
+			ent.Category = clone.fields[i].String
+		case "component":
+			ent.Component = clone.fields[i].String
+		case "event":
+			ent.Event = clone.fields[i].String
+		case "object":
+			ent.ObjectID, _ = clone.fields[i].Interface.(*oid.ObjectId)
+		case "caller":
+			ent.CallerID, _ = clone.fields[i].Interface.(*oid.ObjectId)
+		case "attr":
+			ent.Attr = clone.fields[i].Interface
+		case "error":
+			if err, _ := clone.fields[i].Interface.(error); err != nil {
+				ent.Message = fmt.Sprintf("%s. Error: %s", ent.Message, err.Error())
+			}
+		case "tags":
+			ent.Tags, _ = clone.fields[i].Interface.(zap.StringArray)
+		}
+	}
+
+	return ent, nil
+}

logs/zap/entry_encoder_slow.go

+package zap
+
+import (
+	"fmt"
+	"maps"
+
+	oid "git.perx.ru/perxis/perxis-go/id"
+	"git.perx.ru/perxis/perxis-go/logs"
+	"git.perx.ru/perxis/perxis-go/pkg/id"
+	"go.uber.org/zap/zapcore"
+)
+
+type EncoderSlow interface {
+	zapcore.ObjectEncoder
+
+	Clone() EncoderSlow
+	EncodeEntry(zapcore.Entry, []zapcore.Field) (*logs.Entry, error)
+}
+
+type entryEncoderSlow struct {
+	*zapcore.MapObjectEncoder
+}
+
+func NewEntryEncoderSlow() EncoderSlow {
+	return &entryEncoderSlow{MapObjectEncoder: zapcore.NewMapObjectEncoder()}
+}
+
+func (enc *entryEncoderSlow) Clone() EncoderSlow {
+	return enc.clone()
+}
+
+func (enc *entryEncoderSlow) clone() *entryEncoderSlow {
+	objEnc := zapcore.NewMapObjectEncoder()
+	maps.Copy(objEnc.Fields, enc.MapObjectEncoder.Fields)
+	return &entryEncoderSlow{MapObjectEncoder: objEnc}
+}
+
+func (enc *entryEncoderSlow) EncodeEntry(entry zapcore.Entry, fields []zapcore.Field) (*logs.Entry, error) {
+	clone := enc.clone()
+	for i := range fields {
+		fields[i].AddTo(clone)
+	}
+
+	ent := &logs.Entry{
+		ID:        id.GenerateNewID(),
+		Timestamp: entry.Time,
+		Level:     logs.Level(entry.Level),
+		Message:   entry.Message,
+	}
+
+	ent.Category, _ = clone.Fields["category"].(string)
+	ent.Component, _ = clone.Fields["component"].(string)
+	ent.Event, _ = clone.Fields["event"].(string)
+	ent.ObjectID, _ = clone.Fields["object"].(*oid.ObjectId)
+	ent.CallerID, _ = clone.Fields["caller"].(*oid.ObjectId)
+	ent.Attr = clone.Fields["attr"]
+
+	if err, _ := clone.Fields["error"].(error); err != nil {
+		ent.Message = fmt.Sprintf("%s. Error: %s", ent.Message, err.Error())
+	}
+
+	if tags, ok := clone.Fields["tags"].([]any); ok {
+		for i := range tags {
+			if tag, ok := tags[i].(string); ok {
+				ent.Tags = append(ent.Tags, tag)
+			}
+		}
+	}
+
+	return ent, nil
+}

logs/zap/core_test.go → logs/zap/entry_encoder_test.go

 package zap
 
 import (
+	"fmt"
 	"testing"
 
 	"git.perx.ru/perxis/perxis-go/id"
 	"git.perx.ru/perxis/perxis-go/logs"
+	"git.perx.ru/perxis/perxis-go/pkg/items"
 	logzap "git.perx.ru/perxis/perxis-go/zap"
 	"github.com/stretchr/testify/require"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )
 
-func TestCore_getEntry(t *testing.T) {
-	core := NewCore(nil)
-
+func TestEntryEncoder_EncodeEntry(t *testing.T) {
 	tests := []struct {
 		name  string
 		input struct {
@@ -54,12 +54,78 @@ func TestCore_getEntry(t *testing.T) {
 		},
 	}
 
+	enc := NewEntryEncoder()
+
 	for _, tc := range tests {
 		t.Run(tc.name, func(t *testing.T) {
-			got := core.getEntry(tc.input.entry, tc.input.fields)
+			got, _ := enc.EncodeEntry(tc.input.entry, tc.input.fields)
 			got.ID = tc.want.ID               // игнорируем ID
 			got.Timestamp = tc.want.Timestamp // игнорируем Timestamp
 			require.Equal(t, tc.want, got)
 		})
 	}
 }
+
+func BenchmarkEntryEncoderSimple(b *testing.B) {
+	fields := []zapcore.Field{
+		logzap.Event(items.EventCreateItem),
+		logzap.Object(items.NewItem("WPNN", "9VGP", "GxNv", "W0fl", nil, nil)),
+		logzap.Caller("/system"),
+		logzap.Tags("tag1", "tag2", "tag3"),
+	}
+
+	enc := NewEntryEncoderSlow()
+	for i := 0; i < b.N; i++ {
+		_, _ = enc.EncodeEntry(zapcore.Entry{Message: fmt.Sprintf("Msg: %d", i)}, fields)
+	}
+}
+
+func BenchmarkEntryEncoderUnknownFields(b *testing.B) {
+	fields := []zapcore.Field{
+		logzap.Event(items.EventCreateItem),
+		logzap.Object(items.NewItem("WPNN", "9VGP", "GxNv", "W0fl", nil, nil)),
+		logzap.Caller("/system"),
+		logzap.Tags("tag1", "tag2", "tag3"),
+	}
+
+	for i := 0; i < 1000; i++ {
+		fields = append(fields, zap.String(fmt.Sprintf("Key: %d", i), fmt.Sprintf("Value: %d", i)))
+	}
+
+	enc := NewEntryEncoderSlow()
+	for i := 0; i < b.N; i++ {
+		_, _ = enc.EncodeEntry(zapcore.Entry{Message: fmt.Sprintf("Msg: %d", i)}, fields)
+	}
+}
+
+func BenchmarkEntryEncoderV2Simple(b *testing.B) {
+	fields := []zapcore.Field{
+		logzap.Event(items.EventCreateItem),
+		logzap.Object(items.NewItem("WPNN", "9VGP", "GxNv", "W0fl", nil, nil)),
+		logzap.Caller("/system"),
+		logzap.Tags("tag1", "tag2", "tag3"),
+	}
+
+	enc := NewEntryEncoder()
+	for i := 0; i < b.N; i++ {
+		_, _ = enc.EncodeEntry(zapcore.Entry{Message: fmt.Sprintf("Msg: %d", i)}, fields)
+	}
+}
+
+func BenchmarkEntryEncoderV2UnknownFields(b *testing.B) {
+	fields := []zapcore.Field{
+		logzap.Event(items.EventCreateItem),
+		logzap.Object(items.NewItem("WPNN", "9VGP", "GxNv", "W0fl", nil, nil)),
+		logzap.Caller("/system"),
+		logzap.Tags("tag1", "tag2", "tag3"),
+	}
+
+	for i := 0; i < 1000; i++ {
+		fields = append(fields, zap.String(fmt.Sprintf("Key: %d", i), fmt.Sprintf("Value: %d", i)))
+	}
+
+	enc := NewEntryEncoder()
+	for i := 0; i < b.N; i++ {
+		_, _ = enc.EncodeEntry(zapcore.Entry{Message: fmt.Sprintf("Msg: %d", i)}, fields)
+	}
+}

zap/channels.go

@@ -17,7 +17,7 @@ func ContainsChannels(channels ...string) FilterFunc {
 	return func(entry zapcore.Entry, fields []zapcore.Field) bool {
 		for _, f := range fields {
 			if f.Key == channelKey && f.Type == zapcore.SkipType {
-				for _, v := range f.Interface.(stringArray) {
+				for _, v := range f.Interface.(StringArray) {
 					if data.Contains(v, channels) {
 						return true
 					}

zap/field.go

@@ -10,9 +10,9 @@ import (
 	"go.uber.org/zap/zapcore"
 )
 
-type stringArray []string
+type StringArray []string
 
-func (ss stringArray) MarshalLogArray(arr zapcore.ArrayEncoder) error {
+func (ss StringArray) MarshalLogArray(arr zapcore.ArrayEncoder) error {
 	for i := range ss {
 		arr.AppendString(ss[i])
 	}
@@ -24,7 +24,7 @@ func Channels(channels ...string) zap.Field {
 	return zap.Field{
 		Key:       channelKey,
 		Type:      zapcore.SkipType, // используем тип zapcore.SkipType, чтобы при кодировании поле игнорировалось
-		Interface: stringArray(channels),
+		Interface: StringArray(channels),
 	}
 }
 
@@ -60,9 +60,9 @@ func CallerFromContext(ctx context.Context) zap.Field {
 }
 
 func Attr(attr any) zap.Field {
-	return zap.Any("attr", attr)
+	return zap.Reflect("attr", attr)
 }
 
 func Tags(tags ...string) zap.Field {
-	return zap.Strings("tags", tags)
+	return zap.Array("tags", StringArray(tags))
 }

zap/field_test.go

@@ -19,8 +19,8 @@ func TestChannels(t *testing.T) {
 		field zap.Field
 		want  zap.Field
 	}{
-		{name: "ok", field: Channels("master"), want: zap.Field{Key: channelKey, Type: zapcore.SkipType, Interface: stringArray{"master"}}},
-		{name: "invalid", field: Channels(), want: zap.Field{Key: channelKey, Type: zapcore.SkipType, Interface: stringArray(nil)}},
+		{name: "ok", field: Channels("master"), want: zap.Field{Key: channelKey, Type: zapcore.SkipType, Interface: StringArray{"master"}}},
+		{name: "invalid", field: Channels(), want: zap.Field{Key: channelKey, Type: zapcore.SkipType, Interface: StringArray(nil)}},
 	}
 
 	for _, tc := range tests {
@@ -208,13 +208,13 @@ func TestTags(t *testing.T) {
 		field zap.Field
 		want  zap.Field
 	}{
-		{name: "ok", field: Tags("a", "b", "c"), want: zap.Strings("tags", []string{"a", "b", "c"})},
-		{name: "invalid", field: Tags(nil...), want: zap.Strings("tags", nil)},
+		{name: "ok", field: Tags("a", "b", "c"), want: zap.Array("tags", StringArray{"a", "b", "c"})},
+		{name: "invalid", field: Tags(nil...), want: zap.Array("tags", StringArray(nil))},
 	}
 
 	for _, tc := range tests {
 		t.Run(tc.name, func(t *testing.T) {
-			assert.True(t, tc.want.Equals(tc.field))
+			assert.Equal(t, tc.want, tc.field)
 		})
 	}
 }

zap/filter_core.go

 package zap
 
 import (
+	"slices"
+
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )
@@ -51,9 +53,9 @@ type filterCore struct {
 
 	filters []FilterFunc
 
-	// fields хранит контекст записей ядра, передаваемых при вызове With.
+	// context хранит контекст записей ядра, передаваемых при вызове With.
 	// В методе Write передаются только поля конкретной записи, но мы также хотим учитывать поля контекста ядра.
-	fields []zap.Field
+	context []zap.Field
 }
 
 // WithFilters - добавить фильтры, которые будут применяться при записи лога (вызове `core.Write`)
@@ -80,7 +82,7 @@ func (core *filterCore) With(fields []zapcore.Field) zapcore.Core {
 	return &filterCore{
 		Core:    core.Core.With(fields),
 		filters: core.filters,
-		fields:  append(core.fields, fields...),
+		context: slices.Concat(core.context, fields),
 	}
 }
 
@@ -92,15 +94,11 @@ func (core *filterCore) Check(entry zapcore.Entry, checkedEntry *zapcore.Checked
 }
 
 func (core *filterCore) Write(entry zapcore.Entry, fields []zapcore.Field) error {
-	if len(core.fields) > 0 {
-		fields = append(core.fields, fields...)
-	}
-
+	all := slices.Concat(core.context, fields)
 	for _, filter := range core.filters {
-		if !filter(entry, fields) {
+		if !filter(entry, all) {
 			return nil
 		}
 	}
-
 	return core.Core.Write(entry, fields)
 }

zap/filter_core_test.go

@@ -9,6 +9,20 @@ import (
 	"go.uber.org/zap/zaptest/observer"
 )
 
+func TestFilterCore_With(t *testing.T) {
+	core, logs := observer.New(zapcore.InfoLevel)
+	core = WithFilters(core)
+
+	field := zap.String("k", "v")
+	err := core.With([]zapcore.Field{field}).Write(zapcore.Entry{Message: "msg"}, nil)
+	require.NoError(t, err)
+
+	entries := logs.All()
+	require.Len(t, entries, 1)
+	require.Len(t, entries[0].Context, 1)
+	require.True(t, field.Equals(entries[0].Context[0]))
+}
+
 func TestFilterCore_Write(t *testing.T) {
 	core, logs := observer.New(zapcore.InfoLevel)
 	core = WithFilters(core, ContainsField(zap.Bool("check", true)))