gotd: reduce unnecessary debug logs

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)

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

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)

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 {

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 (
+	var d crypto.EncryptedMessageData
-		d   crypto.EncryptedMessageData
-		log = c.log
-	)
 	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")
 	}

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

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

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)

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")
 	}