From f2544da7a4220f95723012127ffe2df81f1b989a Mon Sep 17 00:00:00 2001 From: Sumner Evans Date: Sat, 30 Dec 2023 15:01:01 -0700 Subject: [PATCH] signalmeow/web/GetAttachment: use structured logging Signed-off-by: Sumner Evans --- pkg/signalmeow/attachments.go | 6 +++--- pkg/signalmeow/keys.go | 2 +- pkg/signalmeow/receiving.go | 6 +++--- pkg/signalmeow/sending.go | 6 +++--- pkg/signalmeow/web/web.go | 40 ++++++++++++++++++++++++++--------- 5 files changed, 40 insertions(+), 20 deletions(-) diff --git a/pkg/signalmeow/attachments.go b/pkg/signalmeow/attachments.go index 38c71d3f..72cc3559 100644 --- a/pkg/signalmeow/attachments.go +++ b/pkg/signalmeow/attachments.go @@ -57,12 +57,12 @@ func getAttachmentPath(id uint64, key string, cdnNumber uint32) (string, error) // ErrInvalidMACForAttachment signals that the downloaded attachment has an invalid MAC. var ErrInvalidMACForAttachment = errors.New("invalid MAC for attachment") -func fetchAndDecryptAttachment(a *signalpb.AttachmentPointer) ([]byte, error) { +func fetchAndDecryptAttachment(ctx context.Context, a *signalpb.AttachmentPointer) ([]byte, error) { path, err := getAttachmentPath(a.GetCdnId(), a.GetCdnKey(), a.GetCdnNumber()) if err != nil { return nil, err } - resp, err := web.GetAttachment(path, a.GetCdnNumber(), nil) + resp, err := web.GetAttachment(ctx, path, a.GetCdnNumber(), nil) if err != nil { return nil, err } @@ -134,7 +134,7 @@ func encryptAndUploadAttachment(ctx context.Context, device *Device, body []byte return nil, err } var uploadAttributes attachmentV3UploadAttributes - err = web.DecodeHTTPResponseBody(&uploadAttributes, resp) + err = web.DecodeHTTPResponseBody(ctx, &uploadAttributes, resp) if err != nil { log.Err(err).Msg("Error decoding response body fetching upload attributes") return nil, err diff --git a/pkg/signalmeow/keys.go b/pkg/signalmeow/keys.go index 7c2831ed..b0c15736 100644 --- a/pkg/signalmeow/keys.go +++ b/pkg/signalmeow/keys.go @@ -314,7 +314,7 @@ func FetchAndProcessPreKey(ctx context.Context, device *Device, theirUuid string return err } var prekeyResponse prekeyResponse - err = web.DecodeHTTPResponseBody(&prekeyResponse, resp) + err = web.DecodeHTTPResponseBody(ctx, &prekeyResponse, resp) if err != nil { zlog.Err(err).Msg("Fetching prekeys, error with response body") return err diff --git a/pkg/signalmeow/receiving.go b/pkg/signalmeow/receiving.go index 69e3d001..a86f910f 100644 --- a/pkg/signalmeow/receiving.go +++ b/pkg/signalmeow/receiving.go @@ -550,7 +550,7 @@ func (d *Device) incomingAPIMessageHandler(ctx context.Context, req *signalpb.We zlog.Debug().Msgf("Recieved sync message contacts") blob := content.SyncMessage.Contacts.Blob if blob != nil { - contactsBytes, err := fetchAndDecryptAttachment(blob) + contactsBytes, err := fetchAndDecryptAttachment(ctx, blob) if err != nil { zlog.Err(err).Msg("Contacts Sync fetchAndDecryptAttachment error") } @@ -830,7 +830,7 @@ func incomingDataMessage(ctx context.Context, device *Device, dataMessage *signa // If there's attachements, handle them (one at a time for now) if dataMessage.Attachments != nil { for index, attachmentPointer := range dataMessage.Attachments { - bytes, err := fetchAndDecryptAttachment(attachmentPointer) + bytes, err := fetchAndDecryptAttachment(ctx, attachmentPointer) if err != nil { zlog.Err(err).Msg("fetchAndDecryptAttachment error") continue @@ -891,7 +891,7 @@ func incomingDataMessage(ctx context.Context, device *Device, dataMessage *signa // if a sticker and has data, send it if dataMessage.Sticker != nil && dataMessage.Sticker.Data != nil { - bytes, err := fetchAndDecryptAttachment(dataMessage.Sticker.Data) + bytes, err := fetchAndDecryptAttachment(ctx, dataMessage.Sticker.Data) if err != nil { zlog.Error().Err(err).Msgf("failed to decrypt sticker: %v", dataMessage.Sticker.Data) } else { diff --git a/pkg/signalmeow/sending.go b/pkg/signalmeow/sending.go index 3c75dd59..f9ea813a 100644 --- a/pkg/signalmeow/sending.go +++ b/pkg/signalmeow/sending.go @@ -39,7 +39,7 @@ import ( type SignalContent signalpb.Content type AttachmentPointer signalpb.AttachmentPointer -func senderCertificate(d *Device) (*libsignalgo.SenderCertificate, error) { +func senderCertificate(ctx context.Context, d *Device) (*libsignalgo.SenderCertificate, error) { if d.Connection.SenderCertificate != nil { // TODO: check for expired certificate return d.Connection.SenderCertificate, nil @@ -56,7 +56,7 @@ func senderCertificate(d *Device) (*libsignalgo.SenderCertificate, error) { if err != nil { return nil, err } - err = web.DecodeHTTPResponseBody(&r, resp) + err = web.DecodeHTTPResponseBody(ctx, &r, resp) if err != nil { return nil, err } @@ -247,7 +247,7 @@ func buildAuthedMessageToSend(ctx context.Context, d *Device, recipientAddress * } func buildSSMessageToSend(ctx context.Context, d *Device, recipientAddress *libsignalgo.Address, paddedMessage []byte) (envelopeType int, encryptedPayload []byte, err error) { - cert, err := senderCertificate(d) + cert, err := senderCertificate(ctx, d) if err != nil { return 0, nil, err } diff --git a/pkg/signalmeow/web/web.go b/pkg/signalmeow/web/web.go index 1e23c64f..5a04d4a1 100644 --- a/pkg/signalmeow/web/web.go +++ b/pkg/signalmeow/web/web.go @@ -18,10 +18,12 @@ package web import ( "bytes" + "context" "crypto/tls" "crypto/x509" "encoding/json" "fmt" + "io" "net/http" "net/url" "os" @@ -170,16 +172,17 @@ func SendHTTPRequest(method string, path string, opt *HTTPReqOpt) (*http.Respons } // DecodeHTTPResponseBody checks status code, reads an http.Response's Body and decodes it into the provided interface. -func DecodeHTTPResponseBody(out any, resp *http.Response) error { +func DecodeHTTPResponseBody(ctx context.Context, out any, resp *http.Response) error { defer resp.Body.Close() // Check if status code indicates success if resp.StatusCode < 200 || resp.StatusCode >= 300 { // Read the whole body and log it - buf := new(bytes.Buffer) - buf.ReadFrom(resp.Body) - body := buf.String() - zlog.Debug().Msgf("Response body: %v", body) + body, _ := io.ReadAll(resp.Body) + zerolog.Ctx(ctx).Debug(). + Str("body", string(body)). + Int("status_code", resp.StatusCode). + Msg("unexpected status code") return fmt.Errorf("Unexpected status code: %d %s", resp.StatusCode, resp.Status) } @@ -192,7 +195,12 @@ func DecodeHTTPResponseBody(out any, resp *http.Response) error { } // Download an attachment from the CDN -func GetAttachment(path string, cdnNumber uint32, opt *HTTPReqOpt) (*http.Response, error) { +func GetAttachment(ctx context.Context, path string, cdnNumber uint32, opt *HTTPReqOpt) (*http.Response, error) { + log := zerolog.Ctx(ctx).With(). + Str("action", "get_attachment"). + Str("path", path). + Uint32("cdn_number", cdnNumber). + Logger() if opt == nil { opt = &HTTPReqOpt{} } @@ -207,21 +215,33 @@ func GetAttachment(path string, cdnNumber uint32, opt *HTTPReqOpt) (*http.Respon opt.Host = CDNHosts[cdnNumber] } else { opt.Host = CDNHosts[0] - zlog.Warn().Msgf("Invalid CDN index %v, using %s", cdnNumber, opt.Host) + log.Warn().Msg("Invalid CDN index") } } + log.Debug().Str("host", opt.Host).Msg("getting attachment") urlStr := "https://" + opt.Host + path - req, err := http.NewRequest("GET", urlStr, nil) + req, err := http.NewRequest(http.MethodGet, urlStr, nil) + if err != nil { + return nil, err + } //const SERVICE_REFLECTOR_HOST = "europe-west1-signal-cdn-reflector.cloudfunctions.net" //req.Header.Add("Host", SERVICE_REFLECTOR_HOST) req.Header.Add("Content-Type", "application/octet-stream") httpReqCounter++ - zlog.Debug().Msgf("Sending Attachment HTTP request %v, url: %s", httpReqCounter, urlStr) + log = log.With(). + Int("request_number", httpReqCounter). + Str("url", urlStr). + Logger() + + log.Debug().Msg("Sending Attachment HTTP request") client := proxiedHTTPClient() resp, err := client.Do(req) - zlog.Debug().Msgf("Received Attachment HTTP response %v, status: %v", httpReqCounter, resp.StatusCode) + if err != nil { + return nil, err + } + log.Debug().Msg("Received Attachment HTTP response") return resp, err }