diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index d1d5f017..064e9482 100644 --- a/.pre-commit-config.yaml +++ b/.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 diff --git a/commands.go b/commands.go index 86e1b9bb..bc11ca92 100644 --- a/commands.go +++ b/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 diff --git a/messagetracking.go b/messagetracking.go index bc69415b..a106ee65 100644 --- a/messagetracking.go +++ b/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") } } diff --git a/pkg/signalmeow/contact.go b/pkg/signalmeow/contact.go index f45f3e01..5ec22c32 100644 --- a/pkg/signalmeow/contact.go +++ b/pkg/signalmeow/contact.go @@ -27,6 +27,7 @@ import ( "strings" "github.com/google/uuid" + "github.com/rs/zerolog" "google.golang.org/protobuf/proto" "go.mau.fi/mautrix-signal/pkg/libsignalgo" @@ -34,24 +35,27 @@ import ( "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 } diff --git a/pkg/signalmeow/receiving.go b/pkg/signalmeow/receiving.go index 7dcb0284..ac92e06a 100644 --- a/pkg/signalmeow/receiving.go +++ b/pkg/signalmeow/receiving.go @@ -25,6 +25,7 @@ import ( "time" "github.com/google/uuid" + "github.com/rs/zerolog" "google.golang.org/protobuf/proto" "google.golang.org/protobuf/reflect/protoreflect" @@ -67,20 +68,21 @@ type SignalConnectionStatus struct { } func (cli *Client) StartReceiveLoops(ctx context.Context) (chan SignalConnectionStatus, error) { - ctx, cancel := context.WithCancel(ctx) + log := zerolog.Ctx(ctx).With().Str("action", "start receive loops").Logger() + ctx, cancel := context.WithCancel(log.WithContext(ctx)) cli.WSCancel = cancel authChan, err := cli.ConnectAuthedWS(ctx, cli.incomingRequestHandler) if err != nil { cancel() return nil, err } - zlog.Info().Msg("Authed websocket connecting") + log.Info().Msg("Authed websocket connecting") unauthChan, err := cli.ConnectUnauthedWS(ctx) if err != nil { cancel() return nil, err } - zlog.Info().Msg("Unauthed websocket connecting") + log.Info().Msg("Unauthed websocket connecting") statusChan := make(chan SignalConnectionStatus, 10000) initialConnectChan := make(chan struct{}) @@ -94,7 +96,7 @@ func (cli *Client) StartReceiveLoops(ctx context.Context) (chan SignalConnection for { select { case <-ctx.Done(): - zlog.Info().Msg("Context done, exiting websocket status loop") + log.Info().Msg("Context done, exiting websocket status loop") return case status := <-authChan: lastAuthStatus = status @@ -104,17 +106,17 @@ func (cli *Client) StartReceiveLoops(ctx context.Context) (chan SignalConnection case web.SignalWebsocketConnectionEventConnecting: // do nothing? case web.SignalWebsocketConnectionEventConnected: - zlog.Info().Msg("Authed websocket connected") + log.Info().Msg("Authed websocket connected") case web.SignalWebsocketConnectionEventDisconnected: - zlog.Err(status.Err).Msg("Authed websocket disconnected") + log.Err(status.Err).Msg("Authed websocket disconnected") case web.SignalWebsocketConnectionEventLoggedOut: - zlog.Err(status.Err).Msg("Authed websocket logged out") + log.Err(status.Err).Msg("Authed websocket logged out") // TODO: Also make sure unauthed websocket is disconnected //StopReceiveLoops(d) case web.SignalWebsocketConnectionEventError: - zlog.Err(status.Err).Msg("Authed websocket error") + log.Err(status.Err).Msg("Authed websocket error") case web.SignalWebsocketConnectionEventCleanShutdown: - zlog.Info().Msg("Authed websocket clean shutdown") + log.Info().Msg("Authed websocket clean shutdown") } case status := <-unauthChan: lastUnauthStatus = status @@ -124,16 +126,19 @@ func (cli *Client) StartReceiveLoops(ctx context.Context) (chan SignalConnection case web.SignalWebsocketConnectionEventConnecting: // do nothing? case web.SignalWebsocketConnectionEventConnected: - zlog.Info().Msg("Unauthed websocket connected") - zlog.Info().Msgf("lastUnauthStatus: %v, lastAuthStatus: %v, currentStatus: %v", lastUnauthStatus, lastAuthStatus, currentStatus) + log.Info(). + Any("last_unauth_status", lastUnauthStatus). + Any("last_auth_status", lastAuthStatus). + Any("current_status", currentStatus). + Msg("Unauthed websocket connected") case web.SignalWebsocketConnectionEventDisconnected: - zlog.Err(status.Err).Msg("Unauthed websocket disconnected") + log.Err(status.Err).Msg("Unauthed websocket disconnected") case web.SignalWebsocketConnectionEventLoggedOut: - zlog.Err(status.Err).Msg("Unauthed websocket logged out ** THIS SHOULD BE IMPOSSIBLE **") + log.Err(status.Err).Msg("Unauthed websocket logged out ** THIS SHOULD BE IMPOSSIBLE **") case web.SignalWebsocketConnectionEventError: - zlog.Err(status.Err).Msg("Unauthed websocket error") + log.Err(status.Err).Msg("Unauthed websocket error") case web.SignalWebsocketConnectionEventCleanShutdown: - zlog.Info().Msg("Unauthed websocket clean shutdown") + log.Info().Msg("Unauthed websocket clean shutdown") } } @@ -167,7 +172,7 @@ func (cli *Client) StartReceiveLoops(ctx context.Context) (chan SignalConnection } } if statusToSend.Event != 0 && statusToSend.Event != lastSentStatus.Event { - zlog.Info().Msgf("Sending connection status: %v", statusToSend) + log.Info().Any("status_to_send", statusToSend).Msg("Sending connection status") statusChan <- statusToSend lastSentStatus = statusToSend } @@ -181,7 +186,7 @@ func (cli *Client) StartReceiveLoops(ctx context.Context) (chan SignalConnection case <-ctx.Done(): return case <-initialConnectChan: - zlog.Info().Msg("Both websockets connected, sending contacts sync request") + log.Info().Msg("Both websockets connected, sending contacts sync request") // TODO hacky cli.SendContactSyncRequest(ctx) return @@ -244,31 +249,39 @@ func (cli *Client) checkDecryptionErrorAndDisconnect(err error) { } func (cli *Client) incomingRequestHandler(ctx context.Context, req *signalpb.WebSocketRequestMessage) (*web.SimpleResponse, error) { + log := zerolog.Ctx(ctx).With(). + Str("handler", "incoming request handler"). + Str("verb", *req.Verb). + Str("path", *req.Path). + Logger() + ctx = log.WithContext(ctx) if *req.Verb == http.MethodPut && *req.Path == "/api/v1/message" { return cli.incomingAPIMessageHandler(ctx, req) } else if *req.Verb == http.MethodPut && *req.Path == "/api/v1/queue/empty" { - zlog.Trace().Msgf("Received queue empty. verb: %v, path: %v", *req.Verb, *req.Path) + log.Trace().Msg("Received queue empty") } else { - zlog.Warn().Msgf("######## Don't know what I received ########## req: %v", req) + log.Warn().Any("req", req).Msg("Unknown websocket request message") } return &web.SimpleResponse{ Status: 200, }, nil } +// TODO: we should split this up into multiple functions func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb.WebSocketRequestMessage) (*web.SimpleResponse, error) { + log := zerolog.Ctx(ctx).With().Str("handler_type", "incoming API message handler").Logger() responseCode := 200 envelope := &signalpb.Envelope{} err := proto.Unmarshal(req.Body, envelope) if err != nil { - zlog.Err(err).Msg("Unmarshal error") + log.Err(err).Msg("Unmarshal error") return nil, err } var result *DecryptionResult switch *envelope.Type { case signalpb.Envelope_UNIDENTIFIED_SENDER: - zlog.Trace().Msgf("Received envelope type UNIDENTIFIED_SENDER, verb: %v, path: %v", *req.Verb, *req.Path) + log.Trace().Msg("Received envelope type UNIDENTIFIED_SENDER") usmc, err := libsignalgo.SealedSenderDecryptToUSMC( ctx, envelope.GetContent(), @@ -278,45 +291,54 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. if err == nil { err = fmt.Errorf("usmc is nil") } - zlog.Err(err).Msg("SealedSenderDecryptToUSMC error") + log.Err(err).Msg("SealedSenderDecryptToUSMC error") return nil, err } messageType, err := usmc.GetMessageType() if err != nil { - zlog.Err(err).Msg("GetMessageType error") + log.Err(err).Msg("GetMessageType error") } senderCertificate, err := usmc.GetSenderCertificate() if err != nil { - zlog.Err(err).Msg("GetSenderCertificate error") + log.Err(err).Msg("GetSenderCertificate error") } senderUUID, err := senderCertificate.GetSenderUUID() if err != nil { - zlog.Err(err).Msg("GetSenderUUID error") + log.Err(err).Msg("GetSenderUUID error") } senderDeviceID, err := senderCertificate.GetDeviceID() if err != nil { - zlog.Err(err).Msg("GetDeviceID error") + log.Err(err).Msg("GetDeviceID error") } senderAddress, err := libsignalgo.NewUUIDAddress(senderUUID, uint(senderDeviceID)) if err != nil { - zlog.Err(err).Msg("NewAddress error") + log.Err(err).Msg("NewAddress error") } senderE164, err := senderCertificate.GetSenderE164() if err != nil { - zlog.Err(err).Msg("GetSenderE164 error") + log.Err(err).Msg("GetSenderE164 error") } usmcContents, err := usmc.GetContents() if err != nil { - zlog.Err(err).Msg("GetContents error") + log.Err(err).Msg("GetContents error") } - zlog.Trace().Msgf("SealedSender senderUUID: %v, senderDeviceID: %v", senderUUID, senderDeviceID) + log = log.With(). + Str("sender_uuid", senderUUID.String()). + Uint32("sender_device_id", senderDeviceID). + Str("sender_e164", senderE164). + Logger() + ctx = log.WithContext(ctx) + log.Trace().Msg("Received SealedSender message") - cli.UpdateContactE164(senderUUID, senderE164) + err = cli.UpdateContactE164(ctx, senderUUID, senderE164) + if err != nil { + log.Err(err).Msg("UpdateContactE164 error") + } switch messageType { case libsignalgo.CiphertextMessageTypeSenderKey: - zlog.Trace().Msg("SealedSender messageType is CiphertextMessageTypeSenderKey ") + log.Trace().Msg("SealedSender messageType is CiphertextMessageTypeSenderKey") decryptedText, err := libsignalgo.GroupDecrypt( ctx, usmcContents, @@ -325,9 +347,9 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. ) if err != nil { if strings.Contains(err.Error(), "message with old counter") { - zlog.Warn().Msg("Duplicate message, ignoring") + log.Warn().Msg("Duplicate message, ignoring") } else { - zlog.Err(err).Msg("GroupDecrypt error") + log.Err(err).Msg("GroupDecrypt error") } } else { err = stripPadding(&decryptedText) @@ -337,7 +359,7 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. content := signalpb.Content{} err = proto.Unmarshal(decryptedText, &content) if err != nil { - zlog.Err(err).Msg("Unmarshal error") + log.Err(err).Msg("Unmarshal error") } result = &DecryptionResult{ SenderAddress: senderAddress, @@ -347,17 +369,17 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. } case libsignalgo.CiphertextMessageTypePreKey: - zlog.Trace().Msg("SealedSender messageType is CiphertextMessageTypePreKey") + log.Trace().Msg("SealedSender messageType is CiphertextMessageTypePreKey") result, err = cli.prekeyDecrypt(ctx, senderAddress, usmcContents) if err != nil { - zlog.Err(err).Msg("prekeyDecrypt error") + log.Err(err).Msg("prekeyDecrypt error") } case libsignalgo.CiphertextMessageTypeWhisper: - zlog.Trace().Msg("SealedSender messageType is CiphertextMessageTypeWhisper") + log.Trace().Msg("SealedSender messageType is CiphertextMessageTypeWhisper") message, err := libsignalgo.DeserializeMessage(usmcContents) if err != nil { - zlog.Err(err).Msg("DeserializeMessage error") + log.Err(err).Msg("DeserializeMessage error") } decryptedText, err := libsignalgo.Decrypt( ctx, @@ -367,7 +389,7 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. cli.Store.IdentityStore, ) if err != nil { - zlog.Err(err).Msg("Sealed sender Whisper Decryption error") + log.Err(err).Msg("Sealed sender Whisper Decryption error") } else { err = stripPadding(&decryptedText) if err != nil { @@ -376,7 +398,7 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. content := signalpb.Content{} err = proto.Unmarshal(decryptedText, &content) if err != nil { - zlog.Err(err).Msg("Unmarshal error") + log.Err(err).Msg("Unmarshal error") } result = &DecryptionResult{ SenderAddress: senderAddress, @@ -386,22 +408,22 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. } case libsignalgo.CiphertextMessageTypePlaintext: - zlog.Debug().Msg("SealedSender messageType is CiphertextMessageTypePlaintext") + log.Debug().Msg("SealedSender messageType is CiphertextMessageTypePlaintext") // TODO: handle plaintext (usually DecryptionErrorMessage) and retries // when implementing SenderKey groups //plaintextContent, err := libsignalgo.DeserializePlaintextContent(usmcContents) //if err != nil { - // zlog.Err(err).Msg("DeserializePlaintextContent error") + // log.Err(err).Msg("DeserializePlaintextContent error") //} //body, err := plaintextContent.GetBody() //if err != nil { - // zlog.Err(err).Msg("PlaintextContent GetBody error") + // log.Err(err).Msg("PlaintextContent GetBody error") //} //content := signalpb.Content{} //err = proto.Unmarshal(body, &content) //if err != nil { - // zlog.Err(err).Msg("PlaintextContent Unmarshal error") + // log.Err(err).Msg("PlaintextContent Unmarshal error") //} //result = &DecryptionResult{ // SenderAddress: *senderAddress, @@ -414,28 +436,31 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. }, nil default: - zlog.Warn().Msg("SealedSender messageType is unknown") + log.Warn().Msg("SealedSender messageType is unknown") } // If we couldn't decrypt with specific decryption methods, try sealedSenderDecrypt if result == nil || responseCode != 200 { - zlog.Debug().Msg("Didn't decrypt with specific methods, trying sealedSenderDecrypt") + log.Debug().Msg("Didn't decrypt with specific methods, trying sealedSenderDecrypt") var err error result, err = cli.sealedSenderDecrypt(ctx, envelope) if err != nil { if strings.Contains(err.Error(), "self send of a sealed sender message") { - zlog.Debug().Msg("Message sent by us, ignoring") + log.Debug().Msg("Message sent by us, ignoring") } else { - zlog.Err(err).Msg("sealedSenderDecrypt error") + log.Err(err).Msg("sealedSenderDecrypt error") cli.checkDecryptionErrorAndDisconnect(err) } } else { - zlog.Trace().Msgf("SealedSender decrypt result - address: %v, content: %v", result.SenderAddress, result.Content) + log.Trace(). + Any("sender_address", result.SenderAddress). + Any("content", result.Content). + Msg("SealedSender decrypt result") } } case signalpb.Envelope_PREKEY_BUNDLE: - zlog.Debug().Msgf("Received envelope type PREKEY_BUNDLE, verb: %v, path: %v", *req.Verb, *req.Path) + log.Debug().Msg("Received envelope type PREKEY_BUNDLE") sender, err := libsignalgo.NewUUIDAddressFromString( *envelope.SourceServiceId, uint(*envelope.SourceDevice), @@ -445,27 +470,30 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. } result, err = cli.prekeyDecrypt(ctx, sender, envelope.Content) if err != nil { - zlog.Err(err).Msg("prekeyDecrypt error") + log.Err(err).Msg("prekeyDecrypt error") cli.checkDecryptionErrorAndDisconnect(err) } else { - zlog.Trace().Msgf("prekey decrypt result - address: %v, data: %v", result.SenderAddress, result.Content) + log.Trace(). + Any("sender_address", result.SenderAddress). + Any("content", result.Content). + Msg("prekey decrypt result") } case signalpb.Envelope_PLAINTEXT_CONTENT: - zlog.Debug().Msgf("Received envelope type PLAINTEXT_CONTENT, verb: %v, path: %v", *req.Verb, *req.Path) + log.Debug().Msg("Received envelope type PLAINTEXT_CONTENT") case signalpb.Envelope_CIPHERTEXT: - zlog.Debug().Msgf("Received envelope type CIPHERTEXT, verb: %v, path: %v", *req.Verb, *req.Path) + log.Debug().Msg("Received envelope type CIPHERTEXT") message, err := libsignalgo.DeserializeMessage(envelope.Content) if err != nil { - zlog.Err(err).Msg("DeserializeMessage error") + log.Err(err).Msg("DeserializeMessage error") } senderAddress, err := libsignalgo.NewUUIDAddressFromString( *envelope.SourceServiceId, uint(*envelope.SourceDevice), ) if err != nil { - return nil, fmt.Errorf("NewAddress error: %v", err) + return nil, fmt.Errorf("NewAddress error: %w", err) } decryptedText, err := libsignalgo.Decrypt( ctx, @@ -476,9 +504,9 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. ) if err != nil { if strings.Contains(err.Error(), "message with old counter") { - zlog.Info().Msg("Duplicate message, ignoring") + log.Info().Msg("Duplicate message, ignoring") } else { - zlog.Err(err).Msg("Whisper Decryption error") + log.Err(err).Msg("Whisper Decryption error") } } else { err = stripPadding(&decryptedText) @@ -488,7 +516,7 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. content := signalpb.Content{} err = proto.Unmarshal(decryptedText, &content) if err != nil { - zlog.Err(err).Msg("Unmarshal error") + log.Err(err).Msg("Unmarshal error") } result = &DecryptionResult{ SenderAddress: senderAddress, @@ -497,19 +525,19 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. } case signalpb.Envelope_RECEIPT: - zlog.Debug().Msgf("Received envelope type RECEIPT, verb: %v, path: %v", *req.Verb, *req.Path) + log.Debug().Msg("Received envelope type RECEIPT") // TODO: handle receipt case signalpb.Envelope_KEY_EXCHANGE: - zlog.Debug().Msgf("Received envelope type KEY_EXCHANGE, verb: %v, path: %v", *req.Verb, *req.Path) + log.Debug().Msg("Received envelope type KEY_EXCHANGE") responseCode = 400 case signalpb.Envelope_UNKNOWN: - zlog.Warn().Msgf("Received envelope type UNKNOWN, verb: %v, path: %v", *req.Verb, *req.Path) + log.Warn().Msg("Received envelope type UNKNOWN") responseCode = 400 default: - zlog.Warn().Msgf("Received actual unknown envelope type, verb: %v, path: %v", *req.Verb, *req.Path) + log.Warn().Msg("Received actual unknown envelope type") responseCode = 400 } @@ -520,16 +548,20 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. name, _ := result.SenderAddress.Name() deviceId, _ := result.SenderAddress.DeviceID() - zlog.Debug().Msgf("Decrypted message from %v:%v", name, deviceId) - printMessage := fmt.Sprintf("Decrypted content fields (%v:%v)", name, deviceId) - printContentFieldString(content, printMessage) + log = log.With(). + Str("sender_name", name). + Uint("sender_device_id", deviceId). + Logger() + ctx = log.WithContext(ctx) + log.Debug().Msg("Decrypted message") + printContentFieldString(ctx, content, "Decrypted content fields") // If there's a sender key distribution message, process it if content.GetSenderKeyDistributionMessage() != nil { - zlog.Debug().Msg("content includes sender key distribution message") + log.Debug().Msg("content includes sender key distribution message") skdm, err := libsignalgo.DeserializeSenderKeyDistributionMessage(content.GetSenderKeyDistributionMessage()) if err != nil { - zlog.Err(err).Msg("DeserializeSenderKeyDistributionMessage error") + log.Err(err).Msg("DeserializeSenderKeyDistributionMessage error") return nil, err } err = libsignalgo.ProcessSenderKeyDistributionMessage( @@ -539,14 +571,14 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. cli.Store.SenderKeyStore, ) if err != nil { - zlog.Err(err).Msg("ProcessSenderKeyDistributionMessage error") + log.Err(err).Msg("ProcessSenderKeyDistributionMessage error") return nil, err } } theirUUID, err := result.SenderAddress.NameUUID() if err != nil { - zlog.Err(err).Msg("Name error") + log.Err(err).Msg("Name error") return nil, err } @@ -559,12 +591,12 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. if destination != nil { destinationUUID, err = uuid.Parse(*destination) if err != nil { - zlog.Err(err).Msg("Sync message destination parse error") + log.Err(err).Msg("Sync message destination parse error") return nil, err } } if destination == nil && syncSent.GetMessage().GetGroupV2() == nil && syncSent.GetEditMessage().GetDataMessage().GetGroupV2() == nil { - zlog.Warn().Msg("sync message sent destination is nil") + log.Warn().Msg("sync message sent destination is nil") } else if content.SyncMessage.Sent.Message != nil { // TODO handle expiration start ts, and maybe the sync message ts? cli.incomingDataMessage(ctx, content.SyncMessage.Sent.Message, cli.Store.ACI, destinationUUID) @@ -573,28 +605,30 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. } } if content.SyncMessage.Contacts != nil { - zlog.Debug().Msgf("Recieved sync message contacts") + log.Debug().Msg("Recieved sync message contacts") blob := content.SyncMessage.Contacts.Blob if blob != nil { contactsBytes, err := DownloadAttachment(ctx, blob) if err != nil { - zlog.Err(err).Msg("Contacts Sync DownloadAttachment error") + log.Err(err).Msg("Contacts Sync DownloadAttachment error") } // unmarshall contacts contacts, avatars, err := unmarshalContactDetailsMessages(contactsBytes) if err != nil { - zlog.Err(err).Msg("Contacts Sync unmarshalContactDetailsMessages error") + log.Err(err).Msg("Contacts Sync unmarshalContactDetailsMessages error") } - zlog.Debug().Msgf("Contacts Sync received %v contacts", len(contacts)) + log.Debug().Int("contact_count", len(contacts)).Msg("Contacts Sync received contacts") convertedContacts := make([]*types.Contact, 0, len(contacts)) for i, signalContact := range contacts { if signalContact.Aci == nil || *signalContact.Aci == "" { - zlog.Info().Msgf("Signal Contact UUID is nil, skipping: %v", signalContact) + log.Info(). + Any("contact", signalContact). + Msg("Signal Contact UUID is nil, skipping") continue } - contact, err := cli.StoreContactDetailsAsContact(signalContact, &avatars[i]) + contact, err := cli.StoreContactDetailsAsContact(ctx, signalContact, &avatars[i]) if err != nil { - zlog.Err(err).Msg("StoreContactDetailsAsContact error") + log.Err(err).Msg("StoreContactDetailsAsContact error") continue } convertedContacts = append(convertedContacts, contact) @@ -622,7 +656,7 @@ func (cli *Client) incomingAPIMessageHandler(ctx context.Context, req *signalpb. // TODO send delivery receipts after actually bridging instead of here err = cli.sendDeliveryReceipts(ctx, []uint64{content.DataMessage.GetTimestamp()}, theirUUID) if err != nil { - zlog.Err(err).Msg("sendDeliveryReceipts error") + log.Err(err).Msg("sendDeliveryReceipts error") } } @@ -675,7 +709,7 @@ func printStructFields(message protoreflect.Message, parent string, builder *str message.Range(func(fd protoreflect.FieldDescriptor, v protoreflect.Value) bool { fieldName := string(fd.Name()) currentField := parent + fieldName - builder.WriteString(fmt.Sprintf("%s (%s), ", currentField, fd.Kind().String())) + fmt.Fprintf(builder, "%s (%s), ", currentField, fd.Kind().String()) //builder.WriteString(fmt.Sprintf("%s (%s): %s, ", currentField, fd.Kind().String(), v.String())) // DEBUG: printing value, don't commit if fd.Kind() == protoreflect.MessageKind && !fd.IsList() && v.Message().IsValid() { builder.WriteString("{ ") @@ -703,21 +737,22 @@ func printStructFields(message protoreflect.Message, parent string, builder *str }) } -func printContentFieldString(c *signalpb.Content, message string) { +func printContentFieldString(ctx context.Context, c *signalpb.Content, message string) { + log := zerolog.Ctx(ctx) go func() { // catch panic defer func() { if r := recover(); r != nil { - zlog.Warn().Msgf("Panic in contentFieldsString: %v", r) + log.Warn().Any("recover", r).Msg("Panic in contentFieldsString") } }() - zlog.Debug().Msgf("%v: %v", message, contentFieldsString(c)) + log.Debug().Str("content_fields", contentFieldsString(c)).Msg(message) }() } func contentFieldsString(c *signalpb.Content) string { - builder := &strings.Builder{} - printStructFields(c.ProtoReflect(), "", builder) + var builder strings.Builder + printStructFields(c.ProtoReflect(), "", &builder) return builder.String() } @@ -811,7 +846,7 @@ func (cli *Client) sendDeliveryReceipts(ctx context.Context, deliveredTimestamps receipt := DeliveredReceiptMessageForTimestamps(deliveredTimestamps) result := cli.SendMessage(ctx, senderUUID, receipt) if !result.WasSuccessful { - zlog.Error().Msgf("Failed to send delivery receipts: %v", result) + return fmt.Errorf("failed to send delivery receipts: %v", result) } } return nil diff --git a/pkg/signalmeow/sending.go b/pkg/signalmeow/sending.go index 06cf66e7..8728d657 100644 --- a/pkg/signalmeow/sending.go +++ b/pkg/signalmeow/sending.go @@ -132,13 +132,13 @@ func checkForErrorWithSessions(err error, addresses []*libsignalgo.Address, sess return err } if addresses == nil || sessionRecords == nil { - return fmt.Errorf("Addresses or session records are nil") + return fmt.Errorf("addresses or session records are nil") } if len(addresses) != len(sessionRecords) { - return fmt.Errorf("Mismatched number of addresses (%d) and session records (%d)", len(addresses), len(sessionRecords)) + return fmt.Errorf("mismatched number of addresses (%d) and session records (%d)", len(addresses), len(sessionRecords)) } if len(addresses) == 0 || len(sessionRecords) == 0 { - return fmt.Errorf("No addresses or session records") + return fmt.Errorf("no addresses or session records") } return nil } @@ -153,7 +153,7 @@ func (cli *Client) howManyOtherDevicesDoWeHave(ctx context.Context) int { for _, address := range addresses { deviceID, err := address.DeviceID() if err != nil { - zlog.Err(err).Msg("Error getting deviceID from address") + zerolog.Ctx(ctx).Err(err).Msg("Error getting deviceID from address") continue } if deviceID != uint(cli.Store.DeviceID) { @@ -189,7 +189,9 @@ func (cli *Client) buildMessagesToSend(ctx context.Context, recipientUUID uuid.U // Don't send to this device that we are sending from if recipientUUID == cli.Store.ACI && recipientDeviceID == uint(cli.Store.DeviceID) { - zlog.Debug().Msgf("Not sending to the device I'm sending from (%v:%v)", recipientUUID, recipientDeviceID) + zerolog.Ctx(ctx).Debug(). + Uint("recipient_device_id", recipientDeviceID). + Msg("Not sending to the device I'm sending from") continue } @@ -199,6 +201,9 @@ func (cli *Client) buildMessagesToSend(ctx context.Context, recipientUUID uuid.U return nil, err } paddedMessage, err := addPadding(3, []byte(serializedMessage)) // TODO: figure out how to get actual version + if err != nil { + return nil, err + } sessionRecord := sessionRecords[i] var envelopeType int @@ -208,6 +213,9 @@ func (cli *Client) buildMessagesToSend(ctx context.Context, recipientUUID uuid.U } else { envelopeType, encryptedPayload, err = cli.buildAuthedMessageToSend(ctx, recipientAddress, paddedMessage) } + if err != nil { + return nil, err + } destinationRegistrationID, err := sessionRecord.GetRemoteRegistrationID() if err != nil { @@ -233,6 +241,9 @@ func (cli *Client) buildAuthedMessageToSend(ctx context.Context, recipientAddres cli.Store.SessionStore, cli.Store.IdentityStore, ) + if err != nil { + return 0, nil, err + } encryptedPayload, err = cipherTextMessage.Serialize() if err != nil { return 0, nil, err @@ -245,7 +256,7 @@ func (cli *Client) buildAuthedMessageToSend(ctx context.Context, recipientAddres } else if cipherMessageType == libsignalgo.CiphertextMessageTypeWhisper { // 2 -> 1 envelopeType = int(signalpb.Envelope_CIPHERTEXT) } else { - return 0, nil, fmt.Errorf("Unknown message type: %v", cipherMessageType) + return 0, nil, fmt.Errorf("unknown message type: %v", cipherMessageType) } return envelopeType, encryptedPayload, nil } @@ -374,9 +385,11 @@ func syncMessageForContactRequest() *signalpb.Content { } } -func syncMessageFromReadReceiptMessage(receiptMessage *signalpb.ReceiptMessage, messageSender uuid.UUID) *signalpb.Content { +func syncMessageFromReadReceiptMessage(ctx context.Context, receiptMessage *signalpb.ReceiptMessage, messageSender uuid.UUID) *signalpb.Content { if *receiptMessage.Type != signalpb.ReceiptMessage_READ { - zlog.Warn().Msgf("syncMessageFromReadReceiptMessage called with non-read receipt message: %v", receiptMessage.Type) + zerolog.Ctx(ctx).Warn(). + Any("receipt_message_type", receiptMessage.Type). + Msg("syncMessageFromReadReceiptMessage called with non-read receipt message") return nil } read := []*signalpb.SyncMessage_Read{} @@ -394,18 +407,28 @@ func syncMessageFromReadReceiptMessage(receiptMessage *signalpb.ReceiptMessage, } func (cli *Client) SendContactSyncRequest(ctx context.Context) error { + if cli.LastContactRequestTime == nil { + cli.LastContactRequestTime = new(int64) + } currentUnixTime := time.Now().Unix() lastRequestTime := cli.LastContactRequestTime + log := zerolog.Ctx(ctx).With(). + Str("action", "send contact sync request"). + Int64("current_unix_time", currentUnixTime). + Int64("last_request_time", *lastRequestTime). + Int64("seconds_since_last_request", currentUnixTime-*lastRequestTime). + Logger() + ctx = log.WithContext(ctx) // If we've requested in the last minute, don't request again if lastRequestTime != nil && currentUnixTime-*lastRequestTime < 60 { - zlog.Warn().Msgf("Not sending contact sync request, already sent %v seconds ago", currentUnixTime-*lastRequestTime) + log.Warn().Msg("Not sending contact sync request because we already requested it in the past minute") return nil } groupRequest := syncMessageForContactRequest() _, err := cli.sendContent(ctx, cli.Store.ACI, uint64(currentUnixTime), groupRequest, 0) if err != nil { - zlog.Err(err).Msg("Failed to send contact sync request message to myself (%v)") + log.Err(err).Msg("Failed to send contact sync request message to myself") return err } cli.LastContactRequestTime = ¤tUnixTime @@ -484,6 +507,11 @@ func wrapDataMessageInContent(dm *signalpb.DataMessage) *signalpb.Content { } func (cli *Client) SendGroupMessage(ctx context.Context, gid types.GroupIdentifier, content *signalpb.Content) (*GroupMessageSendResult, error) { + log := zerolog.Ctx(ctx).With(). + Str("action", "send group message"). + Stringer("group_id", gid). + Logger() + ctx = log.WithContext(ctx) group, err := cli.RetrieveGroupByID(ctx, gid, 0) if err != nil { return nil, err @@ -508,19 +536,21 @@ func (cli *Client) SendGroupMessage(ctx context.Context, gid types.GroupIdentifi // Don't send normal DataMessages to ourselves continue } + log := log.With().Stringer("member", member.UserID).Logger() + ctx := log.WithContext(ctx) sentUnidentified, err := cli.sendContent(ctx, member.UserID, messageTimestamp, content, 0) if err != nil { result.FailedToSendTo = append(result.FailedToSendTo, FailedSendResult{ RecipientUUID: member.UserID, Error: err, }) - zlog.Err(err).Msgf("Failed to send to %v", member.UserID) + log.Err(err).Msg("Failed to send to user") } else { result.SuccessfullySentTo = append(result.SuccessfullySentTo, SuccessfulSendResult{ RecipientUUID: member.UserID, Unidentified: sentUnidentified, }) - zlog.Trace().Msgf("Successfully sent to %v", member.UserID) + log.Trace().Msg("Successfully sent to user") } } @@ -534,7 +564,7 @@ func (cli *Client) SendGroupMessage(ctx context.Context, gid types.GroupIdentifi } _, selfSendErr := cli.sendContent(ctx, cli.Store.ACI, messageTimestamp, syncContent, 0) if selfSendErr != nil { - zlog.Err(selfSendErr).Msg("Failed to send sync message to myself (%v)") + log.Err(selfSendErr).Msg("Failed to send sync message to myself") } } @@ -543,7 +573,7 @@ func (cli *Client) SendGroupMessage(ctx context.Context, gid types.GroupIdentifi } if len(result.SuccessfullySentTo) == 0 { lastError := result.FailedToSendTo[len(result.FailedToSendTo)-1].Error - return nil, fmt.Errorf("Failed to send to any group members: %v", lastError) + return nil, fmt.Errorf("failed to send to any group members: %w", lastError) } return result, nil @@ -592,12 +622,12 @@ func (cli *Client) SendMessage(ctx context.Context, recipientID uuid.UUID, conte } else if content.GetEditMessage() != nil { syncContent = syncMessageFromSoloEditMessage(content.EditMessage, *result.SuccessfulSendResult) } else if content.GetReceiptMessage().GetType() == signalpb.ReceiptMessage_READ { - syncContent = syncMessageFromReadReceiptMessage(content.ReceiptMessage, recipientID) + syncContent = syncMessageFromReadReceiptMessage(ctx, content.ReceiptMessage, recipientID) } if syncContent != nil { _, selfSendErr := cli.sendContent(ctx, cli.Store.ACI, messageTimestamp, syncContent, 0) if selfSendErr != nil { - zlog.Err(selfSendErr).Msg("Failed to send sync message to myself") + zerolog.Ctx(ctx).Err(selfSendErr).Msg("Failed to send sync message to myself") } } } @@ -615,23 +645,28 @@ func (cli *Client) sendContent( content *signalpb.Content, retryCount int, // For ending recursive retries ) (sentUnidentified bool, err error) { - printContentFieldString(content, "Outgoing message") - zerolog.Ctx(ctx).Trace().Any("raw_content", content).Msg("Raw data of outgoing message") + log := zerolog.Ctx(ctx).With(). + Str("action", "send content"). + Stringer("recipient", recipientUUID). + Uint64("timestamp", messageTimestamp). + Logger() + ctx = log.WithContext(ctx) + printContentFieldString(ctx, content, "Outgoing message") + log.Trace().Any("raw_content", content).Msg("Raw data of outgoing message") // If it's a data message, add our profile key if content.DataMessage != nil { profileKey, err := cli.ProfileKeyForSignalID(ctx, cli.Store.ACI) if err != nil { - zlog.Err(err).Msg("Error getting profile key, not adding to outgoing message") + log.Err(err).Msg("Error getting profile key, not adding to outgoing message") } else { content.DataMessage.ProfileKey = profileKey.Slice() } } if retryCount > 3 { - err := fmt.Errorf("Too many retries") - zlog.Err(err).Msgf("sendContent too many retries: %v", retryCount) - return false, err + log.Error().Int("retry_count", retryCount).Msg("sendContent too many retries") + return false, fmt.Errorf("too many retries") } useUnidentifiedSender := true @@ -641,7 +676,7 @@ func (cli *Client) sendContent( } profileKey, err := cli.ProfileKeyForSignalID(ctx, recipientUUID) if err != nil || profileKey == nil { - zlog.Err(err).Msg("Error getting profile key") + log.Err(err).Msg("Error getting profile key") useUnidentifiedSender = false // Try to self heal by requesting contact sync, though this is slow and not guaranteed to help cli.SendContactSyncRequest(ctx) @@ -650,7 +685,7 @@ func (cli *Client) sendContent( if profileKey != nil { accessKey, err = profileKey.DeriveAccessKey() if err != nil { - zlog.Err(err).Msg("Error deriving access key") + log.Err(err).Msg("Error deriving access key") useUnidentifiedSender = false } } @@ -665,7 +700,7 @@ func (cli *Client) sendContent( var messages []MyMessage messages, err = cli.buildMessagesToSend(ctx, recipientUUID, content, useUnidentifiedSender) if err != nil { - zlog.Err(err).Msg("Error building messages to send") + log.Err(err).Msg("Error building messages to send") return false, err } @@ -684,19 +719,24 @@ func (cli *Client) sendContent( var response *signalpb.WebSocketResponseMessage if useUnidentifiedSender { - zlog.Trace().Msgf("Sending message to %v over unidentified WS", recipientUUID) + log.Trace().Msg("Sending message over unidentified WS") base64AccessKey := base64.StdEncoding.EncodeToString(accessKey[:]) request.Headers = append(request.Headers, "unidentified-access-key:"+base64AccessKey) response, err = cli.UnauthedWS.SendRequest(ctx, request) } else { - zlog.Trace().Msgf("Sending message to %v over authed WS", recipientUUID) + log.Trace().Msg("Sending message over authed WS") response, err = cli.AuthedWS.SendRequest(ctx, request) } sentUnidentified = useUnidentifiedSender if err != nil { return sentUnidentified, err } - zlog.Trace().Msgf("Received a response to a message send from: %v, id: %v, code: %v", recipientUUID, *response.Id, *response.Status) + log = log.With(). + Uint64("response_id", *response.Id). + Uint32("response_status", *response.Status). + Logger() + ctx = log.WithContext(ctx) + log.Trace().Msg("Received a response to a message send") retryableStatuses := []uint32{409, 410, 428, 500, 503} @@ -724,13 +764,11 @@ func (cli *Client) sendContent( // Try to send again (**RECURSIVELY**) sentUnidentified, err = cli.sendContent(ctx, recipientUUID, messageTimestamp, content, retryCount+1) if err != nil { - zlog.Err(err).Msg("2nd try sendMessage error") + log.Err(err).Msg("2nd try sendMessage error") return sentUnidentified, err } } else if *response.Status != 200 { - err := fmt.Errorf("Unexpected status code while sending: %v", *response.Status) - zlog.Err(err).Msg("") - return sentUnidentified, err + return sentUnidentified, fmt.Errorf("unexpected status code while sending: %d", *response.Status) } return sentUnidentified, nil @@ -738,25 +776,26 @@ func (cli *Client) sendContent( // A 409 means our device list was out of date, so we will fix it up func (cli *Client) handle409(ctx context.Context, recipientUUID uuid.UUID, response *signalpb.WebSocketResponseMessage) error { + log := zerolog.Ctx(ctx) // Decode json body var body map[string]interface{} err := json.Unmarshal(response.Body, &body) if err != nil { - zlog.Err(err).Msg("Unmarshal error") + log.Err(err).Msg("Unmarshal error") return err } // check for missingDevices and extraDevices if body["missingDevices"] != nil { - missingDevices := body["missingDevices"].([]interface{}) - zlog.Debug().Msgf("missing devices found in 409 response: %v", missingDevices) + missingDevices := body["missingDevices"].([]any) + log.Debug().Any("missing_devices", missingDevices).Msg("missing devices found in 409 response") // TODO: establish session with missing devices for _, missingDevice := range missingDevices { cli.FetchAndProcessPreKey(ctx, recipientUUID, int(missingDevice.(float64))) } } if body["extraDevices"] != nil { - extraDevices := body["extraDevices"].([]interface{}) - zlog.Debug().Msgf("extra devices found in 409 response: %v", extraDevices) + extraDevices := body["extraDevices"].([]any) + log.Debug().Any("extra_devices", extraDevices).Msg("extra devices found in 409 response") for _, extraDevice := range extraDevices { // Remove extra device from the sessionstore recipient, err := libsignalgo.NewUUIDAddress( @@ -764,12 +803,12 @@ func (cli *Client) handle409(ctx context.Context, recipientUUID uuid.UUID, respo uint(extraDevice.(float64)), ) if err != nil { - zlog.Err(err).Msg("NewAddress error") + log.Err(err).Msg("NewAddress error") return err } err = cli.Store.SessionStoreExtras.RemoveSession(ctx, recipient) if err != nil { - zlog.Err(err).Msg("RemoveSession error") + log.Err(err).Msg("RemoveSession error") return err } } @@ -779,25 +818,30 @@ func (cli *Client) handle409(ctx context.Context, recipientUUID uuid.UUID, respo // A 410 means we have a stale device, so get rid of it func (cli *Client) handle410(ctx context.Context, recipientUUID uuid.UUID, response *signalpb.WebSocketResponseMessage) error { + log := zerolog.Ctx(ctx) // Decode json body var body map[string]interface{} err := json.Unmarshal(response.Body, &body) if err != nil { - zlog.Err(err).Msg("Unmarshal error") + log.Err(err).Msg("Unmarshal error") return err } // check for staleDevices and make new sessions with them if body["staleDevices"] != nil { - staleDevices := body["staleDevices"].([]interface{}) - zlog.Debug().Msgf("stale devices found in 410 response: %v", staleDevices) + staleDevices := body["staleDevices"].([]any) + log.Debug().Any("stale_devices", staleDevices).Msg("stale devices found in 410 response") for _, staleDevice := range staleDevices { recipient, err := libsignalgo.NewUUIDAddress( recipientUUID, uint(staleDevice.(float64)), ) + if err != nil { + log.Err(err).Msg("error creating new UUID Address") + return err + } err = cli.Store.SessionStoreExtras.RemoveSession(ctx, recipient) if err != nil { - zlog.Err(err).Msg("RemoveSession error") + log.Err(err).Msg("RemoveSession error") return err } cli.FetchAndProcessPreKey(ctx, recipientUUID, int(staleDevice.(float64))) @@ -810,11 +854,12 @@ func (cli *Client) handle410(ctx context.Context, recipientUUID uuid.UUID, respo // We ~~will~~ could try sending a "pushChallenge" response, but if that doesn't work we just gotta wait. // TODO: explore captcha response func (cli *Client) handle428(ctx context.Context, recipientUUID uuid.UUID, response *signalpb.WebSocketResponseMessage) error { + log := zerolog.Ctx(ctx) // Decode json body var body map[string]interface{} err := json.Unmarshal(response.Body, &body) if err != nil { - zlog.Err(err).Msg("Unmarshal error") + log.Err(err).Msg("Unmarshal error") return err } @@ -829,12 +874,12 @@ func (cli *Client) handle428(ctx context.Context, recipientUUID uuid.UUID, respo if key == "Retry-After" { retryAfterSeconds, err = strconv.ParseUint(value, 10, 64) if err != nil { - zlog.Err(err).Msg("ParseUint error") + log.Err(err).Msg("ParseUint error") } } } if retryAfterSeconds > 0 { - zlog.Warn().Msgf("Got rate limited, need to wait %v seconds", retryAfterSeconds) + log.Warn().Uint64("retry_after_seconds", retryAfterSeconds).Msg("Got rate limited") } // TODO: responding to a pushChallenge this way doesn't work, server just returns 422 // Luckily challenges seem rare when sending with sealed sender diff --git a/portal.go b/portal.go index 292305a0..3283402e 100644 --- a/portal.go +++ b/portal.go @@ -201,10 +201,15 @@ var signalFormatParams *signalfmt.FormatParams var matrixFormatParams *matrixfmt.HTMLParser func (br *SignalBridge) NewPortal(dbPortal *database.Portal) *Portal { + log := br.ZLog.With().Str("chat_id", dbPortal.ChatID).Logger() + if dbPortal.MXID != "" { + log = log.With().Stringer("room_id", dbPortal.MXID).Logger() + } + portal := &Portal{ Portal: dbPortal, bridge: br, - log: br.ZLog.With().Str("chat_id", dbPortal.ChatID).Logger(), + log: log, signalMessages: make(chan portalSignalMessage, br.Config.Bridge.PortalMessageBuffer), matrixMessages: make(chan portalMatrixMessage, br.Config.Bridge.PortalMessageBuffer), @@ -618,7 +623,7 @@ func (portal *Portal) handleMatrixReaction(ctx context.Context, sender *User, ev err = portal.sendSignalMessage(ctx, msg, sender, evt.ID) if err != nil { portal.sendMessageStatusCheckpointFailed(ctx, evt, err) - portal.log.Error().Msgf("Failed to send reaction %s", evt.ID) + log.Error().Msg("Failed to send reaction") return } @@ -714,7 +719,7 @@ func (portal *Portal) sendSignalMessage(ctx context.Context, msg *signalpb.Conte } else if len(result.SuccessfullySentTo) < totalRecipients { log.Warn().Msg("Only sent event to some members of Signal group") } else { - log.Debug().Msgf("Sent event to all members of Signal group") + log.Debug().Msg("Sent event to all members of Signal group") } } return err @@ -1245,7 +1250,7 @@ func (portal *Portal) setTyping(userIDs []id.UserID, isTyping bool) { // require SenderKey sending to not be terrible if portal.IsPrivateChat() { // this is a 1:1 chat - portal.log.Debug().Msgf("Sending Typing event to Signal %s", portal.ChatID) + portal.log.Debug().Msg("Sending Typing event to Signal") ctx := context.TODO() typingMessage := signalmeow.TypingMessage(isTyping) result := user.Client.SendMessage(ctx, portal.UserID(), typingMessage) @@ -1497,6 +1502,7 @@ func (portal *Portal) CreateMatrixRoom(ctx context.Context, user *User, groupRev portal.log.Warn().Err(err).Msg("failed to create room") return err } + portal.log = portal.log.With().Stringer("room_id", resp.RoomID).Logger() portal.NameSet = len(req.Name) > 0 portal.TopicSet = len(req.Topic) > 0 @@ -1507,9 +1513,10 @@ func (portal *Portal) CreateMatrixRoom(ctx context.Context, user *User, groupRev portal.bridge.portalsLock.Unlock() err = portal.Update(ctx) if err != nil { - portal.log.Err(err).Msg("Failed to save created portal mxid") + portal.log.Err(err).Msg("Failed to save portal room ID") + return err } - portal.log.Info().Msgf("Created matrix room %s", portal.MXID) + portal.log.Info().Msg("Created matrix room for portal") inviteMembership := event.MembershipInvite if autoJoinInvites { diff --git a/provisioning.go b/provisioning.go index 11cbe0a2..bb7755f2 100644 --- a/provisioning.go +++ b/provisioning.go @@ -146,14 +146,14 @@ type ResolveIdentifierResponseOtherUser struct { AvatarURL string `json:"avatar_url"` } -func (prov *ProvisioningAPI) resolveIdentifier(user *User, phoneNum string) (int, *ResolveIdentifierResponse, error) { +func (prov *ProvisioningAPI) resolveIdentifier(ctx context.Context, user *User, phoneNum string) (int, *ResolveIdentifierResponse, error) { if !strings.HasPrefix(phoneNum, "+") { phoneNum = "+" + phoneNum } if user.Client == nil { - return http.StatusUnauthorized, nil, fmt.Errorf("Not currently connected to Signal") + return http.StatusUnauthorized, nil, errors.New("not currently connected to Signal") } - contact, err := user.Client.ContactByE164(phoneNum) + contact, err := user.Client.ContactByE164(ctx, phoneNum) if err != nil { return http.StatusInternalServerError, nil, fmt.Errorf("Error looking up number in local contact list: %w", err) } @@ -187,9 +187,10 @@ func (prov *ProvisioningAPI) ResolveIdentifier(w http.ResponseWriter, r *http.Re Str("user_id", user.MXID.String()). Str("phone_num", phoneNum). Logger() + ctx := log.WithContext(r.Context()) log.Debug().Msg("resolving identifier") - status, resp, err := prov.resolveIdentifier(user, phoneNum) + status, resp, err := prov.resolveIdentifier(ctx, user, phoneNum) if err != nil { errCode := "M_INTERNAL" if status == http.StatusNotFound { @@ -221,9 +222,10 @@ func (prov *ProvisioningAPI) StartPM(w http.ResponseWriter, r *http.Request) { Str("user_id", user.MXID.String()). Str("phone_num", phoneNum). Logger() + ctx := log.WithContext(r.Context()) log.Debug().Msg("starting private message") - status, resp, err := prov.resolveIdentifier(user, phoneNum) + status, resp, err := prov.resolveIdentifier(ctx, user, phoneNum) if err != nil { errCode := "M_INTERNAL" if status == http.StatusNotFound { diff --git a/puppet.go b/puppet.go index d824c6b5..c2d2584f 100644 --- a/puppet.go +++ b/puppet.go @@ -244,7 +244,7 @@ func (puppet *Puppet) UpdateInfo(ctx context.Context, source *User, info *types. var err error if info == nil { log.Debug().Msg("Fetching contact info to update puppet") - info, err = source.Client.ContactByID(puppet.SignalID) + info, err = source.Client.ContactByID(ctx, puppet.SignalID) if err != nil { log.Err(err).Msg("Failed to fetch contact info") return