pre-commit: ban Msgf() from zerolog

.pre-commit-config.yaml

@@ -1,6 +1,6 @@
 repos:
   - repo: https://github.com/pre-commit/pre-commit-hooks
-    rev: v4.4.0
+    rev: v4.5.0
     hooks:
       - id: trailing-whitespace
         exclude_types: [markdown]
@@ -13,3 +13,8 @@ repos:
     hooks:
       - id: go-imports-repo
       - id: go-vet-repo-mod
+
+  - repo: https://github.com/beeper/pre-commit-go
+    rev: v0.2.3
+    hooks:
+      - id: zerolog-ban-msgf

bridge/commands/event.go

@@ -69,30 +69,30 @@ func (ce *Event) ReplyAdvanced(msg string, allowMarkdown, allowHTML bool) {
 	content.MsgType = event.MsgNotice
 	_, err := ce.MainIntent().SendMessageEvent(context.Background(), ce.RoomID, event.EventMessage, content)
 	if err != nil {
-		ce.ZLog.Error().Err(err).Msgf("Failed to reply to command")
+		ce.ZLog.Error().Err(err).Msg("Failed to reply to command")
 	}
 }
 
 // React sends a reaction to the command.
 func (ce *Event) React(key string) {
 	_, err := ce.MainIntent().SendReaction(context.Background(), ce.RoomID, ce.EventID, key)
 	if err != nil {
-		ce.ZLog.Error().Err(err).Msgf("Failed to react to command")
+		ce.ZLog.Error().Err(err).Msg("Failed to react to command")
 	}
 }
 
 // Redact redacts the command.
 func (ce *Event) Redact(req ...mautrix.ReqRedact) {
 	_, err := ce.MainIntent().RedactEvent(context.Background(), ce.RoomID, ce.EventID, req...)
 	if err != nil {
-		ce.ZLog.Error().Err(err).Msgf("Failed to redact command")
+		ce.ZLog.Error().Err(err).Msg("Failed to redact command")
 	}
 }
 
 // MarkRead marks the command event as read.
 func (ce *Event) MarkRead() {
 	err := ce.MainIntent().SendReceipt(context.Background(), ce.RoomID, ce.EventID, event.ReceiptTypeRead, nil)
 	if err != nil {
-		ce.ZLog.Error().Err(err).Msgf("Failed to mark command as read")
+		ce.ZLog.Error().Err(err).Msg("Failed to mark command as read")
 	}
 }

crypto/keysharing.go

@@ -43,6 +43,14 @@ var (
 // Deprecated: this only supports a single key request target, so the whole automatic cancelling feature isn't very useful.
 func (mach *OlmMachine) RequestRoomKey(ctx context.Context, toUser id.UserID, toDevice id.DeviceID,
 	roomID id.RoomID, senderKey id.SenderKey, sessionID id.SessionID) (chan bool, error) {
+	log := zerolog.Ctx(ctx).With().
+		Str("action", "request_room_key").
+		Str("to_user", toUser.String()).
+		Str("to_device", toDevice.String()).
+		Str("room_id", roomID.String()).
+		Str("sender_key", senderKey.String()).
+		Str("session_id", sessionID.String()).
+		Logger()
 
 	requestID := mach.Client.TxnID()
 	keyResponseReceived := make(chan struct{})
@@ -58,11 +66,11 @@ func (mach *OlmMachine) RequestRoomKey(ctx context.Context, toUser id.UserID, to
 		select {
 		case <-keyResponseReceived:
 			// key request successful
-			mach.Log.Debug().Msgf("Key for session %v was received, cancelling other key requests", sessionID)
+			log.Debug().Msg("Key for session was received, cancelling other key requests")
 			resChan <- true
 		case <-ctx.Done():
 			// if the context is done, key request was unsuccessful
-			mach.Log.Debug().Msgf("Context closed (%v) before forwared key for session %v received, sending key request cancellation", ctx.Err(), sessionID)
+			log.Debug().Err(err).Msg("Context closed before forwared key for session received, sending key request cancellation")
 			resChan <- false
 		}
 

crypto/verification.go

@@ -18,6 +18,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/rs/zerolog"
 	"maunium.net/go/mautrix"
 	"maunium.net/go/mautrix/crypto/canonicaljson"
 	"maunium.net/go/mautrix/crypto/olm"
@@ -89,13 +90,11 @@ func (mach *OlmMachine) getPKAndKeysMAC(sas *olm.SAS, sendingUser id.UserID, sen
 	if err != nil {
 		return "", "", err
 	}
-	mach.Log.Trace().Msgf("sas.CalculateMAC(\"%s\", \"%s\") -> \"%s\"", signingKey, sasInfo+mainKeyID.String(), string(pubKeyMac))
 
 	keysMac, err := sas.CalculateMAC([]byte(keyIDString), []byte(sasInfo+"KEY_IDS"))
 	if err != nil {
 		return "", "", err
 	}
-	mach.Log.Trace().Msgf("sas.CalculateMAC(\"%s\", \"%s\") -> \"%s\"", keyIDString, sasInfo+"KEY_IDS", string(keysMac))
 
 	return string(pubKeyMac), string(keysMac), nil
 }
@@ -141,50 +140,57 @@ func (mach *OlmMachine) getTransactionState(ctx context.Context, transactionID s
 // handleVerificationStart handles an incoming m.key.verification.start message.
 // It initializes the state for this SAS verification process and stores it.
 func (mach *OlmMachine) handleVerificationStart(ctx context.Context, userID id.UserID, content *event.VerificationStartEventContent, transactionID string, timeout time.Duration, inRoomID id.RoomID) {
-	mach.Log.Debug().Msgf("Received verification start from %v", content.FromDevice)
+	log := zerolog.Ctx(ctx).With().
+		Str("action", "handle_verification_start").
+		Str("user_id", userID.String()).
+		Str("from_device", content.FromDevice.String()).
+		Str("transaction_id", transactionID).
+		Logger()
+	ctx = log.WithContext(ctx)
+	log.Debug().Msg("Received verification start")
 	otherDevice, err := mach.GetOrFetchDevice(ctx, userID, content.FromDevice)
 	if err != nil {
-		mach.Log.Error().Msgf("Could not find device %v of user %v", content.FromDevice, userID)
+		log.Error().Msg("Could not find device for user")
 		return
 	}
-	warnAndCancel := func(logReason, cancelReason string) {
-		mach.Log.Warn().Msgf("Canceling verification transaction %v as it %s", transactionID, logReason)
+	warnAndCancel := func(reason string) {
+		log.Warn().Str("reason", reason).Msg("Canceling verification")
 		if inRoomID == "" {
-			_ = mach.SendSASVerificationCancel(ctx, otherDevice.UserID, otherDevice.DeviceID, transactionID, cancelReason, event.VerificationCancelUnknownMethod)
+			_ = mach.SendSASVerificationCancel(ctx, otherDevice.UserID, otherDevice.DeviceID, transactionID, reason, event.VerificationCancelUnknownMethod)
 		} else {
-			_ = mach.SendInRoomSASVerificationCancel(ctx, inRoomID, otherDevice.UserID, transactionID, cancelReason, event.VerificationCancelUnknownMethod)
+			_ = mach.SendInRoomSASVerificationCancel(ctx, inRoomID, otherDevice.UserID, transactionID, reason, event.VerificationCancelUnknownMethod)
 		}
 	}
 	switch {
 	case content.Method != event.VerificationMethodSAS:
-		warnAndCancel("is not SAS", "Only SAS method is supported")
+		warnAndCancel("Only SAS method is supported")
 	case !content.SupportsKeyAgreementProtocol(event.KeyAgreementCurve25519HKDFSHA256):
-		warnAndCancel("does not support key agreement protocol curve25519-hkdf-sha256",
-			"Only curve25519-hkdf-sha256 key agreement protocol is supported")
+		warnAndCancel("Only curve25519-hkdf-sha256 key agreement protocol is supported")
 	case !content.SupportsHashMethod(event.VerificationHashSHA256):
-		warnAndCancel("does not support SHA256 hashing", "Only SHA256 hashing is supported")
+		warnAndCancel("Only SHA256 hashing is supported")
 	case !content.SupportsMACMethod(event.HKDFHMACSHA256):
-		warnAndCancel("does not support MAC method hkdf-hmac-sha256", "Only hkdf-hmac-sha256 MAC method is supported")
+		warnAndCancel("Only hkdf-hmac-sha256 MAC method is supported")
 	case !content.SupportsSASMethod(event.SASDecimal):
-		warnAndCancel("does not support decimal SAS", "Decimal SAS method must be supported")
+		warnAndCancel("Decimal SAS method must be supported")
 	default:
 		mach.actuallyStartVerification(ctx, userID, content, otherDevice, transactionID, timeout, inRoomID)
 	}
 }
 
 func (mach *OlmMachine) actuallyStartVerification(ctx context.Context, userID id.UserID, content *event.VerificationStartEventContent, otherDevice *id.Device, transactionID string, timeout time.Duration, inRoomID id.RoomID) {
+	log := zerolog.Ctx(ctx)
 	if inRoomID != "" && transactionID != "" {
 		verState, err := mach.getTransactionState(ctx, transactionID, userID)
 		if err != nil {
-			mach.Log.Error().Msgf("Failed to get transaction state for in-room verification %s start: %v", transactionID, err)
+			log.Err(err).Msg("Failed to get transaction state for in-room verification start")
 			_ = mach.SendInRoomSASVerificationCancel(ctx, inRoomID, otherDevice.UserID, transactionID, "Internal state error in gomuks :(", "net.maunium.internal_error")
 			return
 		}
 		mach.timeoutAfter(ctx, verState, transactionID, timeout)
 		sasMethods := commonSASMethods(verState.hooks, content.ShortAuthenticationString)
 		err = mach.SendInRoomSASVerificationAccept(ctx, inRoomID, userID, content, transactionID, verState.sas.GetPubkey(), sasMethods)
 		if err != nil {
-			mach.Log.Error().Msgf("Error accepting in-room SAS verification: %v", err)
+			log.Err(err).Msg("Error accepting in-room SAS verification")
 		}
 		verState.chosenSASMethod = sasMethods[0]
 		verState.verificationStarted = true
@@ -194,7 +200,7 @@ func (mach *OlmMachine) actuallyStartVerification(ctx context.Context, userID id
 	if resp == AcceptRequest {
 		sasMethods := commonSASMethods(hooks, content.ShortAuthenticationString)
 		if len(sasMethods) == 0 {
-			mach.Log.Error().Msgf("No common SAS methods: %v", content.ShortAuthenticationString)
+			log.Error().Any("sas", content.ShortAuthenticationString).Msg("No common SAS methods")
 			if inRoomID == "" {
 				_ = mach.SendSASVerificationCancel(ctx, otherDevice.UserID, otherDevice.DeviceID, transactionID, "No common SAS methods", event.VerificationCancelUnknownMethod)
 			} else {
@@ -219,7 +225,7 @@ func (mach *OlmMachine) actuallyStartVerification(ctx context.Context, userID id
 		_, loaded := mach.keyVerificationTransactionState.LoadOrStore(userID.String()+":"+transactionID, verState)
 		if loaded {
 			// transaction already exists
-			mach.Log.Error().Msgf("Transaction %v already exists, canceling", transactionID)
+			log.Error().Msg("Transaction already exists, canceling")
 			if inRoomID == "" {
 				_ = mach.SendSASVerificationCancel(ctx, otherDevice.UserID, otherDevice.DeviceID, transactionID, "Transaction already exists", event.VerificationCancelUnexpectedMessage)
 			} else {
@@ -237,21 +243,21 @@ func (mach *OlmMachine) actuallyStartVerification(ctx context.Context, userID id
 			err = mach.SendInRoomSASVerificationAccept(ctx, inRoomID, userID, content, transactionID, verState.sas.GetPubkey(), sasMethods)
 		}
 		if err != nil {
-			mach.Log.Error().Msgf("Error accepting SAS verification: %v", err)
+			log.Err(err).Msg("Error accepting SAS verification from user")
 		}
 	} else if resp == RejectRequest {
-		mach.Log.Debug().Msgf("Not accepting SAS verification %v from %v of user %v", transactionID, otherDevice.DeviceID, otherDevice.UserID)
+		log.Debug().Msg("Not accepting SAS verification")
 		var err error
 		if inRoomID == "" {
 			err = mach.SendSASVerificationCancel(ctx, otherDevice.UserID, otherDevice.DeviceID, transactionID, "Not accepted by user", event.VerificationCancelByUser)
 		} else {
 			err = mach.SendInRoomSASVerificationCancel(ctx, inRoomID, otherDevice.UserID, transactionID, "Not accepted by user", event.VerificationCancelByUser)
 		}
 		if err != nil {
-			mach.Log.Error().Msgf("Error canceling SAS verification: %v", err)
+			log.Err(err).Msg("Error canceling SAS verification")
 		}
 	} else {
-		mach.Log.Debug().Msgf("Ignoring SAS verification %v from %v of user %v", transactionID, otherDevice.DeviceID, otherDevice.UserID)
+		log.Debug().Msg("Ignoring SAS verification from user")
 	}
 }
 
@@ -560,6 +566,12 @@ func (mach *OlmMachine) handleVerificationCancel(userID id.UserID, content *even
 
 // handleVerificationRequest handles an incoming m.key.verification.request message.
 func (mach *OlmMachine) handleVerificationRequest(ctx context.Context, userID id.UserID, content *event.VerificationRequestEventContent, transactionID string, inRoomID id.RoomID) {
+	log := zerolog.Ctx(ctx).With().
+		Str("action", "handle_in_room_verification_ready").
+		Str("user_id", userID.String()).
+		Logger()
+	ctx = log.WithContext(ctx)
+
 	mach.Log.Debug().Msgf("Received verification request from %v", content.FromDevice)
 	otherDevice, err := mach.GetOrFetchDevice(ctx, userID, content.FromDevice)
 	if err != nil {

crypto/verification_in_room.go

@@ -12,6 +12,7 @@ import (
 	"errors"
 	"time"
 
+	"github.com/rs/zerolog"
 	"maunium.net/go/mautrix/crypto/canonicaljson"
 	"maunium.net/go/mautrix/crypto/olm"
 	"maunium.net/go/mautrix/event"
@@ -210,6 +211,15 @@ func (mach *OlmMachine) SendInRoomSASVerificationKey(ctx context.Context, roomID
 
 // SendInRoomSASVerificationMAC sends the MAC of a device's key to the partner device for an in-room verification.
 func (mach *OlmMachine) SendInRoomSASVerificationMAC(ctx context.Context, roomID id.RoomID, userID id.UserID, deviceID id.DeviceID, transactionID string, sas *olm.SAS) error {
+	log := zerolog.Ctx(ctx).With().
+		Str("action", "send_in_room_sas_verification_mac").
+		Str("room_id", roomID.String()).
+		Str("user_id", userID.String()).
+		Str("device_id", deviceID.String()).
+		Str("transaction_id", transactionID).
+		Logger()
+	ctx = log.WithContext(ctx)
+
 	keyID := id.NewKeyID(id.KeyAlgorithmEd25519, mach.Client.DeviceID.String())
 
 	signingKey := mach.account.SigningKey()
@@ -224,9 +234,12 @@ func (mach *OlmMachine) SendInRoomSASVerificationMAC(ctx context.Context, roomID
 		masterKeyMAC, _, err := mach.getPKAndKeysMAC(sas, mach.Client.UserID, mach.Client.DeviceID,
 			userID, deviceID, transactionID, masterKey, masterKeyID, keyIDsMap)
 		if err != nil {
-			mach.Log.Error().Msgf("Error generating master key MAC: %v", err)
+			log.Err(err).Msg("Error generating master key MAC")
 		} else {
-			mach.Log.Debug().Msgf("Generated master key `%v` MAC: %v", masterKey, masterKeyMAC)
+			log.Debug().
+				Any("master_key", masterKey).
+				Any("master_key_mac", masterKeyMAC).
+				Msg("Generated master key and MAC")
 			macMap[masterKeyID] = masterKeyMAC
 		}
 	}
@@ -235,8 +248,12 @@ func (mach *OlmMachine) SendInRoomSASVerificationMAC(ctx context.Context, roomID
 	if err != nil {
 		return err
 	}
-	mach.Log.Debug().Msgf("MAC of key %s is: %s", signingKey, pubKeyMac)
-	mach.Log.Debug().Msgf("MAC of key ID(s) %s is: %s", keyID, keysMac)
+	log.Debug().
+		Any("signing_key", signingKey).
+		Any("pub_key_mac", pubKeyMac).
+		Any("key_id", keyID).
+		Any("keys_mac", keysMac).
+		Msg("Computed public key and keys MAC")
 	macMap[keyID] = pubKeyMac
 
 	content := &event.VerificationMacEventContent{
@@ -257,11 +274,16 @@ func (mach *OlmMachine) SendInRoomSASVerificationMAC(ctx context.Context, roomID
 // NewInRoomSASVerificationWith starts the in-room SAS verification process with another user in the given room.
 // It returns the generated transaction ID.
 func (mach *OlmMachine) NewInRoomSASVerificationWith(ctx context.Context, inRoomID id.RoomID, userID id.UserID, hooks VerificationHooks, timeout time.Duration) (string, error) {
+	log := zerolog.Ctx(ctx).With().
+		Str("action", "new_in_room_sas_verification_with").
+		Str("user_id", userID.String()).
+		Logger()
+	ctx = log.WithContext(ctx)
 	return mach.newInRoomSASVerificationWithInner(ctx, inRoomID, &id.Device{UserID: userID}, hooks, "", timeout)
 }
 
 func (mach *OlmMachine) newInRoomSASVerificationWithInner(ctx context.Context, inRoomID id.RoomID, device *id.Device, hooks VerificationHooks, transactionID string, timeout time.Duration) (string, error) {
-	mach.Log.Debug().Msgf("Starting new in-room verification transaction user %v", device.UserID)
+	zerolog.Ctx(ctx).Debug().Msg("Starting new in-room verification transaction")
 
 	request := transactionID == ""
 	if request {
@@ -312,15 +334,22 @@ func (mach *OlmMachine) newInRoomSASVerificationWithInner(ctx context.Context, i
 }
 
 func (mach *OlmMachine) handleInRoomVerificationReady(ctx context.Context, userID id.UserID, roomID id.RoomID, content *event.VerificationReadyEventContent, transactionID string) {
+	log := zerolog.Ctx(ctx).With().
+		Str("action", "handle_in_room_verification_ready").
+		Str("user_id", userID.String()).
+		Str("from_device", content.FromDevice.String()).
+		Logger()
+	ctx = log.WithContext(ctx)
+
 	device, err := mach.GetOrFetchDevice(ctx, userID, content.FromDevice)
 	if err != nil {
-		mach.Log.Error().Msgf("Error fetching device %v of user %v: %v", content.FromDevice, userID, err)
+		log.Err(err).Msg("Error fetching device")
 		return
 	}
 
 	verState, err := mach.getTransactionState(ctx, transactionID, userID)
 	if err != nil {
-		mach.Log.Error().Msgf("Error getting transaction state: %v", err)
+		log.Err(err).Msg("Error getting transaction state")
 		return
 	}
 	//mach.keyVerificationTransactionState.Delete(userID.String() + ":" + transactionID)