pre-commit: ban Msgf() from zerolog

.pre-commit-config.yaml

@@ -20,4 +20,5 @@ repos:
   - repo: https://github.com/beeper/pre-commit-go
     rev: v0.3.0
     hooks:
+      - id: zerolog-ban-msgf
       - id: zerolog-use-stringer

commands.go

@@ -204,7 +204,7 @@ func fnPM(ce *WrappedCommandEvent) {
 
 	user := ce.User
 	number := strings.Join(ce.Args, "")
-	contact, err := user.Client.ContactByE164(number)
+	contact, err := user.Client.ContactByE164(ce.Ctx, number)
 	if err != nil {
 		ce.Reply("Error looking up number in local contact list: %v", err)
 		return

messagetracking.go

@@ -184,15 +184,16 @@ func (portal *Portal) sendMessageMetrics(ctx context.Context, evt *event.Event,
 	if evt.Type == event.EventRedaction {
 		log = log.With().Stringer("redacts", evt.Redacts).Logger()
 	}
+	ctx = log.WithContext(ctx)
 
 	origEvtID := evt.ID
 	if retryMeta := evt.Content.AsMessage().MessageSendRetry; retryMeta != nil {
 		origEvtID = retryMeta.OriginalEventID
 	}
 	if err != nil {
-		logEvt := portal.log.Error()
+		logEvt := log.Error()
 		if part == "Ignoring" {
-			logEvt = portal.log.Debug()
+			logEvt = log.Debug()
 		}
 		logEvt.Err(err).Msg("Sending message metrics for event")
 		reason, statusCode, isCertain, sendNotice, _ := errorToStatusReason(err)
@@ -203,7 +204,7 @@ func (portal *Portal) sendMessageMetrics(ctx context.Context, evt *event.Event,
 		}
 		portal.sendStatusEvent(ctx, origEvtID, evt.ID, err, nil)
 	} else {
-		portal.log.Debug().Msg("Sending metrics for successfully handled Matrix event")
+		log.Debug().Msg("Sending metrics for successfully handled Matrix event")
 		portal.sendDeliveryReceipt(ctx, evt.ID)
 		portal.bridge.SendMessageSuccessCheckpoint(evt, status.MsgStepRemote, ms.getRetryNum())
 		var deliveredTo *[]id.UserID
@@ -218,7 +219,7 @@ func (portal *Portal) sendMessageMetrics(ctx context.Context, evt *event.Event,
 		}
 	}
 	if ms != nil {
-		portal.log.Debug().Object("timings", ms.timings).Msg("Timings for event")
+		log.Debug().Object("timings", ms.timings).Msg("Timings for event")
 	}
 }
 

pkg/signalmeow/contact.go

@@ -27,31 +27,35 @@ import (
 	"strings"
 
 	"github.com/google/uuid"
+	"github.com/rs/zerolog"
 	"google.golang.org/protobuf/proto"
 
 	"go.mau.fi/mautrix-signal/pkg/libsignalgo"
 	signalpb "go.mau.fi/mautrix-signal/pkg/signalmeow/protobuf"
 	"go.mau.fi/mautrix-signal/pkg/signalmeow/types"
 )
 
-func (cli *Client) StoreContactDetailsAsContact(contactDetails *signalpb.ContactDetails, avatar *[]byte) (*types.Contact, error) {
-	ctx := context.TODO()
+func (cli *Client) StoreContactDetailsAsContact(ctx context.Context, contactDetails *signalpb.ContactDetails, avatar *[]byte) (*types.Contact, error) {
 	parsedUUID, err := uuid.Parse(contactDetails.GetAci())
 	if err != nil {
 		return nil, err
 	}
+	log := zerolog.Ctx(ctx).With().
+		Str("action", "store contact details as contact").
+		Str("uuid", parsedUUID.String()).
+		Logger()
 	existingContact, err := cli.Store.ContactStore.LoadContact(ctx, parsedUUID)
 	if err != nil {
-		zlog.Err(err).Msg("StoreContactDetailsAsContact error loading contact")
+		log.Err(err).Msg("error loading contact")
 		return nil, err
 	}
 	if existingContact == nil {
-		zlog.Debug().Msgf("StoreContactDetailsAsContact: creating new contact for uuid: %v", parsedUUID)
+		log.Debug().Msg("creating new contact")
 		existingContact = &types.Contact{
 			UUID: parsedUUID,
 		}
 	} else {
-		zlog.Debug().Msgf("StoreContactDetailsAsContact: updating existing contact for uuid: %v", parsedUUID)
+		log.Debug().Msg("updating existing contact")
 	}
 
 	existingContact.E164 = contactDetails.GetNumber()
@@ -61,7 +65,7 @@ func (cli *Client) StoreContactDetailsAsContact(contactDetails *signalpb.Contact
 		existingContact.ProfileKey = &profileKey
 		err = cli.Store.ProfileKeyStore.StoreProfileKey(ctx, existingContact.UUID, profileKey)
 		if err != nil {
-			zlog.Err(err).Msg("StoreContactDetailsAsContact error storing profile key")
+			log.Err(err).Msg("storing profile key")
 			//return *existingContact, nil, err
 		}
 	}
@@ -82,36 +86,39 @@ func (cli *Client) StoreContactDetailsAsContact(contactDetails *signalpb.Contact
 		}
 	}
 
-	zlog.Debug().Msgf("StoreContactDetailsAsContact: storing contact for uuid: %v", contactDetails.GetAci())
+	log.Debug().Msg("storing contact")
 	storeErr := cli.Store.ContactStore.StoreContact(ctx, *existingContact)
 	if storeErr != nil {
-		zlog.Err(storeErr).Msg("StoreContactDetailsAsContact: error storing contact")
+		log.Err(storeErr).Msg("error storing contact")
 		return existingContact, storeErr
 	}
 	return existingContact, nil
 }
 
-func (cli *Client) fetchContactThenTryAndUpdateWithProfile(profileUuid uuid.UUID) (*types.Contact, error) {
-	ctx := context.TODO()
+func (cli *Client) fetchContactThenTryAndUpdateWithProfile(ctx context.Context, profileUUID uuid.UUID) (*types.Contact, error) {
+	log := zerolog.Ctx(ctx).With().
+		Str("action", "fetch contact then try and update with profile").
+		Stringer("profile_uuid", profileUUID).
+		Logger()
 	contactChanged := false
 
-	existingContact, err := cli.Store.ContactStore.LoadContact(ctx, profileUuid)
+	existingContact, err := cli.Store.ContactStore.LoadContact(ctx, profileUUID)
 	if err != nil {
-		zlog.Err(err).Msg("fetchContactThenTryAndUpdateWithProfile: error loading contact")
+		log.Err(err).Msg("error loading contact")
 		return nil, err
 	}
 	if existingContact == nil {
-		zlog.Debug().Msgf("fetchContactThenTryAndUpdateWithProfile: creating new contact for uuid: %v", profileUuid)
+		log.Debug().Msg("creating new contact")
 		existingContact = &types.Contact{
-			UUID: profileUuid,
+			UUID: profileUUID,
 		}
 		contactChanged = true
 	} else {
-		zlog.Debug().Msgf("fetchContactThenTryAndUpdateWithProfile: updating existing contact for uuid: %v", profileUuid)
+		log.Debug().Msg("updating existing contact")
 	}
-	profile, err := cli.RetrieveProfileByID(ctx, profileUuid)
+	profile, err := cli.RetrieveProfileByID(ctx, profileUUID)
 	if err != nil {
-		zlog.Err(err).Msgf("fetchContactThenTryAndUpdateWithProfile: error retrieving profile for uuid: %v", profileUuid)
+		log.Err(err).Msg("error retrieving profile")
 		//return nil, nil, err
 		// Don't return here, we still want to return what we have
 	}
@@ -140,56 +147,56 @@ func (cli *Client) fetchContactThenTryAndUpdateWithProfile(profileUuid uuid.UUID
 	}
 
 	if contactChanged {
-		storeErr := cli.Store.ContactStore.StoreContact(ctx, *existingContact)
-		if storeErr != nil {
-			zlog.Err(storeErr).Msg("fetchContactThenTryAndUpdateWithProfile: error storing contact")
+		err := cli.Store.ContactStore.StoreContact(ctx, *existingContact)
+		if err != nil {
+			log.Err(err).Msg("error storing contact")
+			return nil, err
 		}
 	}
 	return existingContact, nil
 }
 
-func (cli *Client) UpdateContactE164(uuid uuid.UUID, e164 string) error {
-	ctx := context.TODO()
+func (cli *Client) UpdateContactE164(ctx context.Context, uuid uuid.UUID, e164 string) error {
+	log := zerolog.Ctx(ctx).With().
+		Str("action", "update contact e164").
+		Stringer("uuid", uuid).
+		Str("e164", e164).
+		Logger()
 	existingContact, err := cli.Store.ContactStore.LoadContact(ctx, uuid)
 	if err != nil {
-		zlog.Err(err).Msg("UpdateContactE164: error loading contact")
+		log.Err(err).Msg("error loading contact")
 		return err
 	}
 	if existingContact == nil {
-		zlog.Debug().Msgf("UpdateContactE164: creating new contact for uuid: %v", uuid)
+		log.Debug().Msg("creating new contact")
 		existingContact = &types.Contact{
 			UUID: uuid,
 		}
 	} else {
-		zlog.Debug().Msgf("UpdateContactE164: found existing contact for uuid: %v", uuid)
+		log.Debug().Msg("found existing contact")
 	}
-	if existingContact.E164 != e164 {
-		zlog.Debug().Msgf("UpdateContactE164: e164 changed for uuid: %v", uuid)
-		existingContact.E164 = e164
-		storeErr := cli.Store.ContactStore.StoreContact(ctx, *existingContact)
-		if storeErr != nil {
-			zlog.Err(storeErr).Msg("UpdateContactE164: error storing contact")
-			return storeErr
-		}
+	if existingContact.E164 == e164 {
+		return nil
 	}
-	return nil
+	log.Debug().Msg("e164 changed for contact")
+	existingContact.E164 = e164
+	return cli.Store.ContactStore.StoreContact(ctx, *existingContact)
 }
 
-func (cli *Client) ContactByID(uuid uuid.UUID) (*types.Contact, error) {
-	return cli.fetchContactThenTryAndUpdateWithProfile(uuid)
+func (cli *Client) ContactByID(ctx context.Context, uuid uuid.UUID) (*types.Contact, error) {
+	return cli.fetchContactThenTryAndUpdateWithProfile(ctx, uuid)
 }
 
-func (cli *Client) ContactByE164(e164 string) (*types.Contact, error) {
-	ctx := context.TODO()
+func (cli *Client) ContactByE164(ctx context.Context, e164 string) (*types.Contact, error) {
 	contact, err := cli.Store.ContactStore.LoadContactByE164(ctx, e164)
 	if err != nil {
-		zlog.Err(err).Msg("ContactByE164 error loading contact")
+		zerolog.Ctx(ctx).Err(err).Msg("ContactByE164 error loading contact")
 		return nil, err
 	}
 	if contact == nil {
 		return nil, nil
 	}
-	contact, err = cli.fetchContactThenTryAndUpdateWithProfile(contact.UUID)
+	contact, err = cli.fetchContactThenTryAndUpdateWithProfile(ctx, contact.UUID)
 	return contact, err
 }