diff --git a/pkg/logging/logging.go b/pkg/logging/logging.go index 0be62f9c2e..ad4a07db3e 100644 --- a/pkg/logging/logging.go +++ b/pkg/logging/logging.go @@ -3,6 +3,7 @@ package logging import ( "context" "encoding" + "encoding/base64" "fmt" "io" "log/slog" @@ -201,3 +202,16 @@ func TxID(t txIDGetter, scheme scheme) slog.Attr { var val slog.LogValuer = txIDSlogValuer{t: t, scheme: scheme} return slog.Any("txID", val) } + +type base64SlogValuer []byte + +func (v base64SlogValuer) LogValue() slog.Value { + return slog.StringValue(base64.StdEncoding.EncodeToString(v)) +} + +// Data returns a slog.Attr that lazily encodes the given bytes as base64 string. +// Encoding happens only if the record is actually handled. +func Data(data []byte) slog.Attr { + var val slog.LogValuer = base64SlogValuer(data) + return slog.Any("data", val) +} diff --git a/pkg/logging/logging_internal_test.go b/pkg/logging/logging_internal_test.go index 5319e2beca..532e77b58f 100644 --- a/pkg/logging/logging_internal_test.go +++ b/pkg/logging/logging_internal_test.go @@ -104,3 +104,45 @@ func TestError(t *testing.T) { }) } } + +func TestData(t *testing.T) { + data := []byte{0x00, 0x01, 0xfe, 0xff, 'a', 'b', 'c'} + const expected = "AAH+/2FiYw==" + for _, test := range []struct { + name string + handler func(w *bytes.Buffer) slog.Handler + check func(t *testing.T, out []byte) + }{ + { + name: "text", + handler: func(w *bytes.Buffer) slog.Handler { return slog.NewTextHandler(w, nil) }, + check: func(t *testing.T, out []byte) { + assert.Contains(t, string(out), `data="`+expected+`"`) + }, + }, + { + name: "json", + handler: func(w *bytes.Buffer) slog.Handler { return slog.NewJSONHandler(w, nil) }, + check: func(t *testing.T, out []byte) { + var m map[string]any + require.NoError(t, json.Unmarshal(out, &m)) + assert.Equal(t, expected, m["data"]) + }, + }, + } { + t.Run(test.name, func(t *testing.T) { + buf := new(bytes.Buffer) + slog.New(test.handler(buf)).Info("test", Data(data)) + test.check(t, buf.Bytes()) + }) + } +} + +func BenchmarkDataDiscarded(b *testing.B) { + data := make([]byte, 1<<20) + l := slog.New(slog.DiscardHandler) + b.ReportAllocs() + for b.Loop() { + l.Debug("test", Data(data)) + } +} diff --git a/pkg/networking/session.go b/pkg/networking/session.go index db3b750689..76d1d859ab 100644 --- a/pkg/networking/session.go +++ b/pkg/networking/session.go @@ -4,7 +4,6 @@ import ( "bufio" "bytes" "context" - "encoding/base64" "errors" "fmt" "io" @@ -196,7 +195,7 @@ func (s *Session) waitForSend(data []byte) error { defer s.tp.Put(timer) if s.logger.Enabled(s.ctx, slog.LevelDebug) { - s.logger.Debug("Sending data", "data", base64.StdEncoding.EncodeToString(data)) + s.logger.Debug("Sending data", logging.Data(data)) } select { case s.sendCh <- newSendPacket(data, errCh): @@ -252,9 +251,7 @@ func (s *Session) sendLoop() error { if dataBuf.Len() > 0 { data := dataBuf.Bytes() if s.logger.Enabled(s.ctx, slog.LevelDebug) { - s.logger.Debug("Sending data to connection", - "len", len(data), - "data", base64.StdEncoding.EncodeToString(data)) + s.logger.Debug("Sending data to connection", slog.Int("len", len(data)), logging.Data(data)) } written, err := s.writeConnIfNotClosed(data) if err != nil { @@ -402,8 +399,7 @@ func (s *Session) readMessagePayload(hdr Header, conn io.Reader) error { // The slice of bytes passed into the handler is only valid for the duration of the handler invocation. // So inside the handler better deserialize message or make a copy of the bytes. if s.logger.Enabled(s.ctx, slog.LevelDebug) { - s.logger.Debug("Invoking OnReceive handler", "message", - base64.StdEncoding.EncodeToString(s.receiveBuffer.Bytes())) + s.logger.Debug("Invoking OnReceive handler", logging.Data(s.receiveBuffer.Bytes())) } s.config.handler.OnReceive(s, s.receiveBuffer) // Invoke OnReceive handler. return nil diff --git a/pkg/p2p/peer/handle.go b/pkg/p2p/peer/handle.go index a4b375806f..baf6734bd5 100644 --- a/pkg/p2p/peer/handle.go +++ b/pkg/p2p/peer/handle.go @@ -76,7 +76,9 @@ func Handle(ctx context.Context, peer Peer, parent Parent, remote Remote, logger case bb := <-remote.FromCh: if !errSentToParent { - dl.Debug("Receiving from network", "peer", peer.ID(), "data", proto.B64Bytes(bb.Bytes())) + if dl.Enabled(ctx, slog.LevelDebug) { + dl.Debug("Receiving from network", slog.Any("peer", peer.ID()), logging.Data(bb.Bytes())) + } err := bytesToMessage(bb.Bytes(), parent.MessageCh, peer, logger) if err != nil { out := InfoMessage{Peer: peer, Value: &InternalErr{Err: err}} diff --git a/pkg/p2p/peer/peer_impl.go b/pkg/p2p/peer/peer_impl.go index d42261a3b1..0494b9a145 100644 --- a/pkg/p2p/peer/peer_impl.go +++ b/pkg/p2p/peer/peer_impl.go @@ -85,7 +85,9 @@ func (a *PeerImpl) SendMessage(m proto.Message) { slog.Error("Failed to send message", logging.Type(m), logging.Error(err)) return } - a.logger.Debug("Sending to network", "peer", a.id, "data", proto.B64Bytes(b)) + if a.logger.Enabled(context.Background(), slog.LevelDebug) { + a.logger.Debug("Sending to network", slog.Any("peer", a.id), logging.Data(b)) + } select { case a.remote.ToCh <- b: