From c83a361c0b0ede81fc8b9a8d17a226356ef237dd Mon Sep 17 00:00:00 2001 From: Tulir Asokan Date: Thu, 4 Dec 2025 14:44:13 +0200 Subject: [PATCH] gotd: reduce unnecessary debug logs --- pkg/gotd/mtproto/ack.go | 4 ---- pkg/gotd/mtproto/handle_ack.go | 2 -- pkg/gotd/mtproto/handle_message.go | 3 --- pkg/gotd/mtproto/handle_result.go | 2 -- pkg/gotd/mtproto/new_encrypted_msg.go | 11 +---------- pkg/gotd/mtproto/rpc.go | 10 +--------- pkg/gotd/rpc/ack.go | 2 -- pkg/gotd/rpc/engine.go | 4 ---- pkg/gotd/telegram/internal/manager/conn.go | 19 ++++++++++++++----- 9 files changed, 16 insertions(+), 41 deletions(-) diff --git a/pkg/gotd/mtproto/ack.go b/pkg/gotd/mtproto/ack.go index 5cb4fb45..fce253ed 100644 --- a/pkg/gotd/mtproto/ack.go +++ b/pkg/gotd/mtproto/ack.go @@ -10,8 +10,6 @@ import ( ) func (c *Conn) ackLoop(ctx context.Context) error { - log := c.log.Named("ack") - var buf []int64 send := func() { defer func() { buf = buf[:0] }() @@ -20,8 +18,6 @@ func (c *Conn) ackLoop(ctx context.Context) error { c.log.Error("Failed to ACK", zap.Error(err)) return } - - log.Debug("Ack", zap.Int64s("msg_ids", buf)) } ticker := c.clock.Ticker(c.ackInterval) diff --git a/pkg/gotd/mtproto/handle_ack.go b/pkg/gotd/mtproto/handle_ack.go index daa3628b..f2592997 100644 --- a/pkg/gotd/mtproto/handle_ack.go +++ b/pkg/gotd/mtproto/handle_ack.go @@ -2,7 +2,6 @@ package mtproto import ( "github.com/go-faster/errors" - "go.uber.org/zap" "go.mau.fi/mautrix-telegram/pkg/gotd/bin" "go.mau.fi/mautrix-telegram/pkg/gotd/mt" @@ -14,7 +13,6 @@ func (c *Conn) handleAck(b *bin.Buffer) error { return errors.Wrap(err, "decode") } - c.log.Debug("Received ack", zap.Int64s("msg_ids", ack.MsgIDs)) c.rpc.NotifyAcks(ack.MsgIDs) return nil diff --git a/pkg/gotd/mtproto/handle_message.go b/pkg/gotd/mtproto/handle_message.go index 2dbadbec..625bf3e1 100644 --- a/pkg/gotd/mtproto/handle_message.go +++ b/pkg/gotd/mtproto/handle_message.go @@ -2,7 +2,6 @@ package mtproto import ( "github.com/go-faster/errors" - "go.uber.org/zap" "go.mau.fi/mautrix-telegram/pkg/gotd/bin" "go.mau.fi/mautrix-telegram/pkg/gotd/mt" @@ -16,8 +15,6 @@ func (c *Conn) handleMessage(msgID int64, b *bin.Buffer) error { return errors.Wrap(err, "peek message type") } - c.logWithBuffer(b).Debug("Handle message", zap.Int64("msg_id", msgID)) - switch id { case mt.NewSessionCreatedTypeID: return c.handleSessionCreated(b) diff --git a/pkg/gotd/mtproto/handle_result.go b/pkg/gotd/mtproto/handle_result.go index 46558a72..7aa4c53a 100644 --- a/pkg/gotd/mtproto/handle_result.go +++ b/pkg/gotd/mtproto/handle_result.go @@ -21,7 +21,6 @@ func (c *Conn) handleResult(b *bin.Buffer) error { b.ResetTo(res.Result) msgID := zap.Int64("msg_id", res.RequestMessageID) - c.logWithBuffer(b).Debug("Handle result", msgID) // Handling gzipped results. id, err := b.PeekID() @@ -36,7 +35,6 @@ func (c *Conn) handleResult(b *bin.Buffer) error { // Replacing buffer so callback will deal with uncompressed data. b = content - c.logWithBuffer(b).Debug("Decompressed", msgID) // Replacing id with inner id if error is compressed for any reason. if id, err = b.PeekID(); err != nil { diff --git a/pkg/gotd/mtproto/new_encrypted_msg.go b/pkg/gotd/mtproto/new_encrypted_msg.go index 8e76b6d4..c45a5c20 100644 --- a/pkg/gotd/mtproto/new_encrypted_msg.go +++ b/pkg/gotd/mtproto/new_encrypted_msg.go @@ -2,7 +2,6 @@ package mtproto import ( "github.com/go-faster/errors" - "go.uber.org/zap" "go.mau.fi/mautrix-telegram/pkg/gotd/bin" "go.mau.fi/mautrix-telegram/pkg/gotd/crypto" @@ -16,14 +15,8 @@ func (c *Conn) newEncryptedMessage(id int64, seq int32, payload bin.Encoder, b * // 1) Generate Length() method for every encoder, to count length without encoding. // 2) Re-use buffer instead of using yet one. // 3) Do not send proto.GZIP if gzipped size is equal or bigger. - var ( - d crypto.EncryptedMessageData - log = c.log - ) + var d crypto.EncryptedMessageData if c.compressThreshold <= 0 { - if obj, ok := payload.(interface{ TypeID() uint32 }); ok { - log = c.logWithTypeID(obj.TypeID()) - } d = crypto.EncryptedMessageData{ SessionID: s.ID, Salt: s.Salt, @@ -38,7 +31,6 @@ func (c *Conn) newEncryptedMessage(id int64, seq int32, payload bin.Encoder, b * return errors.Wrap(err, "encode payload") } - log = c.logWithType(payloadBuf) if payloadBuf.Len() > c.compressThreshold { d = crypto.EncryptedMessageData{ SessionID: s.ID, @@ -59,7 +51,6 @@ func (c *Conn) newEncryptedMessage(id int64, seq int32, payload bin.Encoder, b * } } - log.Debug("Request", zap.Int64("msg_id", id)) if err := c.cipher.Encrypt(s.Key, d, b); err != nil { return errors.Wrap(err, "encrypt") } diff --git a/pkg/gotd/mtproto/rpc.go b/pkg/gotd/mtproto/rpc.go index 44adb1b7..c6d089f7 100644 --- a/pkg/gotd/mtproto/rpc.go +++ b/pkg/gotd/mtproto/rpc.go @@ -23,22 +23,14 @@ func (c *Conn) Invoke(ctx context.Context, input bin.Encoder, output bin.Decoder Output: output, } - log := c.log.With( - zap.Int64("msg_id", req.MsgID), - ) - log.Debug("Invoke start") - defer log.Debug("Invoke end") - if err := c.rpc.Do(ctx, req); err != nil { var badMsgErr *badMessageError if errors.As(err, &badMsgErr) && badMsgErr.Code == codeIncorrectServerSalt { - // Should retry with new salt. - c.log.Debug("Setting server salt") // Store salt from server. c.storeSalt(badMsgErr.NewSalt) // Reset saved salts to fetch new. c.salts.Reset() - c.log.Info("Retrying request after basMsgErr", zap.Int64("msg_id", req.MsgID)) + c.log.Info("Retrying request after updating salt from badMsgErr", zap.Int64("msg_id", req.MsgID)) return c.rpc.Do(ctx, req) } return err diff --git a/pkg/gotd/rpc/ack.go b/pkg/gotd/rpc/ack.go index c2d5b494..f4680377 100644 --- a/pkg/gotd/rpc/ack.go +++ b/pkg/gotd/rpc/ack.go @@ -12,7 +12,6 @@ func (e *Engine) NotifyAcks(ids []int64) { for _, id := range ids { ch, ok := e.ack[id] if !ok { - e.log.Debug("Acknowledge callback not set", zap.Int64("msg_id", id)) continue } @@ -31,7 +30,6 @@ func (e *Engine) waitAck(id int64) chan struct{} { return c } - log.Debug("Waiting for acknowledge") c := make(chan struct{}) e.ack[id] = c return c diff --git a/pkg/gotd/rpc/engine.go b/pkg/gotd/rpc/engine.go index 2c352462..ff1f5841 100644 --- a/pkg/gotd/rpc/engine.go +++ b/pkg/gotd/rpc/engine.go @@ -88,7 +88,6 @@ func (e *Engine) Do(ctx context.Context, req Request) error { defer retryClose() log := e.log.With(zap.Int64("msg_id", req.MsgID)) - log.Debug("Do called") done := make(chan struct{}) @@ -100,8 +99,6 @@ func (e *Engine) Do(ctx context.Context, req Request) error { ) handler := func(rpcBuff *bin.Buffer, rpcErr error) error { - log.Debug("Handler called") - if ok := atomic.CompareAndSwapUint32(&handlerCalled, 0, 1); !ok { log.Warn("Handler already called") @@ -207,7 +204,6 @@ func (e *Engine) retryUntilAck(ctx context.Context, req Request) (sent bool, err case <-e.reqCtx.Done(): return errors.Wrap(e.reqCtx.Err(), "engine forcibly closed") case <-ackChan: - log.Debug("Acknowledged") return nil case <-timer.C(): timer.Reset(e.retryInterval) diff --git a/pkg/gotd/telegram/internal/manager/conn.go b/pkg/gotd/telegram/internal/manager/conn.go index e7746d27..ece9f5c7 100644 --- a/pkg/gotd/telegram/internal/manager/conn.go +++ b/pkg/gotd/telegram/internal/manager/conn.go @@ -96,7 +96,7 @@ func (c *Conn) OnSession(session mtproto.Session) error { return c.handler.OnSession(cfg, session) } -func (c *Conn) trackInvoke() func() { +func (c *Conn) trackInvoke() func(bin.Encoder, bin.Decoder, *error) { start := c.clock.Now() c.mux.Lock() @@ -105,7 +105,7 @@ func (c *Conn) trackInvoke() func() { c.ongoing++ c.latest = start - return func() { + return func(input bin.Encoder, output bin.Decoder, retErr *error) { c.mux.Lock() defer c.mux.Unlock() @@ -113,9 +113,18 @@ func (c *Conn) trackInvoke() func() { end := c.clock.Now() c.latest = end - c.log.Debug("Invoke", + var respField zap.Field + if retErr != nil { + respField = zap.Error(*retErr) + } else { + respField = zap.Any("response_payload", output) + } + + c.log.Debug("Request completed", zap.Duration("duration", end.Sub(start)), zap.Int("ongoing", c.ongoing), + zap.Any("request_payload", input), + respField, ) } } @@ -160,9 +169,9 @@ func (c *Conn) Ready() <-chan struct{} { } // Invoke implements Invoker. -func (c *Conn) Invoke(ctx context.Context, input bin.Encoder, output bin.Decoder) error { +func (c *Conn) Invoke(ctx context.Context, input bin.Encoder, output bin.Decoder) (retErr error) { // Tracking ongoing invokes. - defer c.trackInvoke()() + defer c.trackInvoke()(input, output, &retErr) if err := c.waitSession(ctx); err != nil { return errors.Wrap(err, "waitSession") }