From b5bc6bfd611ae57c786b644c745767e91294775a Mon Sep 17 00:00:00 2001 From: Tulir Asokan Date: Mon, 17 Jul 2023 16:43:34 +0300 Subject: [PATCH] Clean up logs and move some functions --- libgm/client.go | 45 +++++--- libgm/event_handler.go | 7 +- libgm/media_processor.go | 146 -------------------------- libgm/pair.go | 2 - libgm/pairing_handler.go | 6 +- libgm/qr.go | 24 ----- libgm/rpc.go | 2 +- libgm/updates_handler.go | 21 ++-- libgm/{image_builder.go => upload.go} | 140 ++++++++++++++++++++++++ 9 files changed, 185 insertions(+), 208 deletions(-) delete mode 100644 libgm/media_processor.go delete mode 100644 libgm/qr.go rename libgm/{image_builder.go => upload.go} (58%) diff --git a/libgm/client.go b/libgm/client.go index 35f5386..918a62a 100644 --- a/libgm/client.go +++ b/libgm/client.go @@ -123,7 +123,7 @@ func (c *Client) Connect() error { if bugleErr != nil { return fmt.Errorf("failed to check bugle default: %w", err) } - c.Logger.Debug().Any("isBugle", bugleRes.Success).Msg("IsBugleDefault") + c.Logger.Debug().Bool("bugle_default", bugleRes.Success).Msg("Got is bugle default response on connect") sessionErr := c.SetActiveSession() if sessionErr != nil { return fmt.Errorf("failed to set active session: %w", err) @@ -145,6 +145,20 @@ func (c *Client) StartLogin() (string, error) { return qr, nil } +func (c *Client) GenerateQRCodeData(pairingKey []byte) (string, error) { + urlData := &binary.URLData{ + PairingKey: pairingKey, + AESKey: c.AuthData.RequestCrypto.AESKey, + HMACKey: c.AuthData.RequestCrypto.HMACKey, + } + encodedURLData, err := proto.Marshal(urlData) + if err != nil { + return "", err + } + cData := base64.StdEncoding.EncodeToString(encodedURLData) + return util.QRCodeURLBase + cData, nil +} + func (c *Client) Disconnect() { c.rpc.CloseConnection() c.http.CloseIdleConnections() @@ -165,10 +179,10 @@ func (c *Client) Reconnect() error { } err := c.Connect() if err != nil { - c.Logger.Err(err).Any("tachyonAuthToken", c.AuthData.TachyonAuthToken).Msg("Failed to reconnect") + c.Logger.Err(err).Msg("Failed to reconnect") return err } - c.Logger.Debug().Any("tachyonAuthToken", c.AuthData.TachyonAuthToken).Msg("Successfully reconnected to server") + c.Logger.Debug().Msg("Successfully reconnected to server") return nil } @@ -190,9 +204,9 @@ func (c *Client) DownloadMedia(mediaID string, key []byte) ([]byte, error) { ConfigVersion: util.ConfigMessage, }, } - downloadMetadataBytes, err2 := proto.Marshal(downloadMetadata) - if err2 != nil { - return nil, err2 + downloadMetadataBytes, err := proto.Marshal(downloadMetadata) + if err != nil { + return nil, err } downloadMetadataEncoded := base64.StdEncoding.EncodeToString(downloadMetadataBytes) req, err := http.NewRequest("GET", util.UploadMediaURL, nil) @@ -204,13 +218,11 @@ func (c *Client) DownloadMedia(mediaID string, key []byte) ([]byte, error) { if reqErr != nil { return nil, reqErr } - c.Logger.Info().Any("url", util.UploadMediaURL).Any("headers", res.Request.Header).Msg("Decrypt Image Headers") defer res.Body.Close() - encryptedBuffImg, err3 := io.ReadAll(res.Body) - if err3 != nil { - return nil, err3 + encryptedBuffImg, err := io.ReadAll(res.Body) + if err != nil { + return nil, err } - c.Logger.Debug().Any("key", key).Any("encryptedLength", len(encryptedBuffImg)).Msg("Attempting to decrypt image") cryptor, err := crypto.NewImageCryptor(key) if err != nil { return nil, err @@ -257,7 +269,7 @@ func (c *Client) diffVersionFormat(curr *binary.ConfigVersion, latest *binary.Co } func (c *Client) updateWebEncryptionKey(key []byte) { - c.Logger.Debug().Any("key", key).Msg("Updated WebEncryptionKey") + c.Logger.Debug().Msg("Updated WebEncryptionKey") c.AuthData.WebEncryptionKey = key } @@ -269,14 +281,19 @@ func (c *Client) updateTachyonAuthToken(t []byte, validFor int64) { } c.AuthData.TachyonExpiry = time.Now().UTC().Add(time.Microsecond * time.Duration(validFor)) c.AuthData.TachyonTTL = validForDuration.Microseconds() - c.Logger.Debug().Time("tachyon_expiry", c.AuthData.TachyonExpiry).Int64("valid_for", validFor).Msg("Updated tachyon token") + c.Logger.Debug(). + Time("tachyon_expiry", c.AuthData.TachyonExpiry). + Int64("valid_for", validFor). + Msg("Updated tachyon token") } func (c *Client) refreshAuthToken() error { if c.AuthData.Browser == nil || time.Until(c.AuthData.TachyonExpiry) > RefreshTachyonBuffer { return nil } - c.Logger.Debug().Time("tachyon_expiry", c.AuthData.TachyonExpiry).Msg("Refreshing auth token") + c.Logger.Debug(). + Time("tachyon_expiry", c.AuthData.TachyonExpiry). + Msg("Refreshing auth token") jwk := c.AuthData.RefreshKey requestID := uuid.NewString() timestamp := time.Now().UnixMilli() * 1000 diff --git a/libgm/event_handler.go b/libgm/event_handler.go index 70938fa..c9371e5 100644 --- a/libgm/event_handler.go +++ b/libgm/event_handler.go @@ -77,11 +77,6 @@ func (r *RPC) HandleRPCMsg(msg *binary.InternalMessage) { } r.client.handleUpdatesEvent(response) default: - r.client.Logger.Debug().Any("res", response).Msg("Got unknown bugleroute") + r.client.Logger.Debug().Any("res", response).Msg("Got unknown bugle route") } - -} - -func (r *RPC) HandleByLength(data []byte) { - r.client.Logger.Debug().Any("byteLength", len(data)).Any("corrupt raw", string(data)).Msg("RPC Corrupt json") } diff --git a/libgm/media_processor.go b/libgm/media_processor.go deleted file mode 100644 index fab86b4..0000000 --- a/libgm/media_processor.go +++ /dev/null @@ -1,146 +0,0 @@ -package libgm - -import ( - "bytes" - "encoding/base64" - "errors" - "io" - "net/http" - "strconv" - - "github.com/google/uuid" - "google.golang.org/protobuf/proto" - - "go.mau.fi/mautrix-gmessages/libgm/binary" - "go.mau.fi/mautrix-gmessages/libgm/util" -) - -type StartGoogleUpload struct { - UploadID string - UploadURL string - UploadStatus string - ChunkGranularity int64 - ControlURL string - MimeType string - - EncryptedMediaBytes []byte -} - -type MediaUpload struct { - MediaID string - MediaNumber int64 -} - -var ( - errStartUploadMedia = errors.New("failed to start uploading media") - errFinalizeUploadMedia = errors.New("failed to finalize uploading media") -) - -func (c *Client) FinalizeUploadMedia(upload *StartGoogleUpload) (*MediaUpload, error) { - encryptedImageSize := strconv.Itoa(len(upload.EncryptedMediaBytes)) - - finalizeUploadHeaders := util.NewMediaUploadHeaders(encryptedImageSize, "upload, finalize", "0", upload.MimeType, "") - req, reqErr := http.NewRequest("POST", upload.UploadURL, bytes.NewBuffer(upload.EncryptedMediaBytes)) - if reqErr != nil { - return nil, reqErr - } - - req.Header = *finalizeUploadHeaders - - res, resErr := c.http.Do(req) - if resErr != nil { - panic(resErr) - } - - statusCode := res.StatusCode - if statusCode != 200 { - return nil, errFinalizeUploadMedia - } - - defer res.Body.Close() - - rHeaders := res.Header - googleResponse, err3 := io.ReadAll(base64.NewDecoder(base64.StdEncoding, res.Body)) - if err3 != nil { - return nil, err3 - } - - uploadStatus := rHeaders.Get("x-goog-upload-status") - c.Logger.Debug().Str("upload_status", uploadStatus).Msg("Upload complete") - - mediaIDs := &binary.UploadMediaResponse{} - err3 = proto.Unmarshal(googleResponse, mediaIDs) - if err3 != nil { - return nil, err3 - } - return &MediaUpload{ - MediaID: mediaIDs.Media.MediaID, - MediaNumber: mediaIDs.Media.MediaNumber, - }, nil -} - -func (c *Client) StartUploadMedia(encryptedImageBytes []byte, mime string) (*StartGoogleUpload, error) { - encryptedImageSize := strconv.Itoa(len(encryptedImageBytes)) - - startUploadHeaders := util.NewMediaUploadHeaders(encryptedImageSize, "start", "", mime, "resumable") - startUploadPayload, buildPayloadErr := c.buildStartUploadPayload() - if buildPayloadErr != nil { - return nil, buildPayloadErr - } - - req, reqErr := http.NewRequest("POST", util.UploadMediaURL, bytes.NewBuffer([]byte(startUploadPayload))) - if reqErr != nil { - return nil, reqErr - } - - req.Header = *startUploadHeaders - - res, resErr := c.http.Do(req) - if resErr != nil { - panic(resErr) - } - - statusCode := res.StatusCode - if statusCode != 200 { - return nil, errStartUploadMedia - } - - rHeaders := res.Header - - chunkGranularity, convertErr := strconv.Atoi(rHeaders.Get("x-goog-upload-chunk-granularity")) - if convertErr != nil { - return nil, convertErr - } - - uploadResponse := &StartGoogleUpload{ - UploadID: rHeaders.Get("x-guploader-uploadid"), - UploadURL: rHeaders.Get("x-goog-upload-url"), - UploadStatus: rHeaders.Get("x-goog-upload-status"), - ChunkGranularity: int64(chunkGranularity), - ControlURL: rHeaders.Get("x-goog-upload-control-url"), - MimeType: mime, - - EncryptedMediaBytes: encryptedImageBytes, - } - return uploadResponse, nil -} - -func (c *Client) buildStartUploadPayload() (string, error) { - protoData := &binary.StartMediaUploadPayload{ - ImageType: 1, - AuthData: &binary.AuthMessage{ - RequestID: uuid.NewString(), - TachyonAuthToken: c.AuthData.TachyonAuthToken, - ConfigVersion: util.ConfigMessage, - }, - Mobile: c.AuthData.Mobile, - } - - protoDataBytes, err := proto.Marshal(protoData) - if err != nil { - return "", err - } - protoDataEncoded := base64.StdEncoding.EncodeToString(protoDataBytes) - - return protoDataEncoded, nil -} diff --git a/libgm/pair.go b/libgm/pair.go index 4e0ad80..3709a6b 100644 --- a/libgm/pair.go +++ b/libgm/pair.go @@ -34,12 +34,10 @@ func (c *Client) RegisterPhoneRelay() (*binary.RegisterPhoneRelayResponse, error }, }) if err != nil { - c.Logger.Err(err) return nil, err } relayResponse, reqErr := c.MakeRelayRequest(util.RegisterPhoneRelayURL, body) if reqErr != nil { - c.Logger.Err(reqErr) return nil, err } responseBody, err := io.ReadAll(relayResponse.Body) diff --git a/libgm/pairing_handler.go b/libgm/pairing_handler.go index 0b61f64..9f74caa 100644 --- a/libgm/pairing_handler.go +++ b/libgm/pairing_handler.go @@ -11,9 +11,8 @@ import ( func (c *Client) handlePairingEvent(response *pblite.Response) { pairEventData, ok := response.Data.Decrypted.(*binary.PairEvents) - if !ok { - c.Logger.Error().Any("pairEventData", pairEventData).Msg("failed to assert response into PairEvents") + c.Logger.Error().Type("decrypted_type", response.Data.Decrypted).Msg("Unexpected data type in pair event") return } @@ -21,10 +20,9 @@ func (c *Client) handlePairingEvent(response *pblite.Response) { case *binary.PairEvents_Paired: c.completePairing(evt.Paired) case *binary.PairEvents_Revoked: - c.Logger.Debug().Any("data", evt).Msg("Revoked Device") c.triggerEvent(evt.Revoked) default: - c.Logger.Debug().Any("response", response).Any("evt", evt).Msg("Invalid PairEvents type") + c.Logger.Debug().Any("evt", evt).Msg("Unknown pair event type") } } diff --git a/libgm/qr.go b/libgm/qr.go deleted file mode 100644 index a1c5ebf..0000000 --- a/libgm/qr.go +++ /dev/null @@ -1,24 +0,0 @@ -package libgm - -import ( - "encoding/base64" - - "google.golang.org/protobuf/proto" - - "go.mau.fi/mautrix-gmessages/libgm/binary" - "go.mau.fi/mautrix-gmessages/libgm/util" -) - -func (c *Client) GenerateQRCodeData(pairingKey []byte) (string, error) { - urlData := &binary.URLData{ - PairingKey: pairingKey, - AESKey: c.AuthData.RequestCrypto.AESKey, - HMACKey: c.AuthData.RequestCrypto.HMACKey, - } - encodedURLData, err := proto.Marshal(urlData) - if err != nil { - return "", err - } - cData := base64.StdEncoding.EncodeToString(encodedURLData) - return util.QRCodeURLBase + cData, nil -} diff --git a/libgm/rpc.go b/libgm/rpc.go index 4766814..9dd5fea 100644 --- a/libgm/rpc.go +++ b/libgm/rpc.go @@ -155,7 +155,7 @@ func (r *RPC) startReadingData(rc io.ReadCloser) { } accumulatedData = append(accumulatedData, chunk...) if !json.Valid(accumulatedData) { - r.client.Logger.Debug().Str("data", string(chunk)).Msg("Invalid JSON") + r.client.Logger.Trace().Bytes("data", chunk).Msg("Invalid JSON, reading next chunk") continue } currentBlock := accumulatedData diff --git a/libgm/updates_handler.go b/libgm/updates_handler.go index 83586c2..5a705ce 100644 --- a/libgm/updates_handler.go +++ b/libgm/updates_handler.go @@ -12,7 +12,7 @@ func (c *Client) handleUpdatesEvent(res *pblite.Response) { case binary.ActionType_GET_UPDATES: data, ok := res.Data.Decrypted.(*binary.UpdateEvents) if !ok { - c.Logger.Error().Any("res", res).Msg("failed to assert ActionType_GET_UPDATES event into UpdateEvents") + c.Logger.Error().Type("data_type", res.Data.Decrypted).Msg("Unexpected data type in GET_UPDATES event") return } @@ -40,17 +40,16 @@ func (c *Client) handleUpdatesEvent(res *pblite.Response) { case *binary.UpdateEvents_TypingEvent: c.rpc.logContent(res) c.triggerEvent(evt.TypingEvent.GetData()) - default: - c.Logger.Debug().Any("evt", evt).Any("res", res).Msg("Got unknown event type") - } + default: + c.Logger.Trace().Any("evt", evt).Msg("Got unknown event type") + } default: - c.Logger.Error().Any("response", res).Msg("ignoring response.") + c.Logger.Trace().Any("response", res).Msg("Got unexpected response") } } func (c *Client) handleClientReady(newSessionId string) { - c.Logger.Info().Any("sessionId", newSessionId).Msg("Client is ready!") conversations, convErr := c.ListConversations(25, binary.ListConversationsPayload_INBOX) if convErr != nil { panic(convErr) @@ -67,13 +66,13 @@ func (c *Client) handleUserAlertEvent(res *pblite.Response, data *binary.UserAle alertType := data.AlertType switch alertType { case binary.AlertType_BROWSER_ACTIVE: - newSessionId := res.Data.RequestID - c.Logger.Info().Any("sessionId", newSessionId).Msg("[NEW_BROWSER_ACTIVE] Opened new browser connection") - if newSessionId != c.sessionHandler.sessionID { - evt := events.NewBrowserActive(newSessionId) + newSessionID := res.Data.RequestID + c.Logger.Debug().Any("session_id", newSessionID).Msg("Got browser active notification") + if newSessionID != c.sessionHandler.sessionID { + evt := events.NewBrowserActive(newSessionID) c.triggerEvent(evt) } else { - go c.handleClientReady(newSessionId) + go c.handleClientReady(newSessionID) } default: c.triggerEvent(data) diff --git a/libgm/image_builder.go b/libgm/upload.go similarity index 58% rename from libgm/image_builder.go rename to libgm/upload.go index b66de9e..933c6a9 100644 --- a/libgm/image_builder.go +++ b/libgm/upload.go @@ -1,10 +1,20 @@ package libgm import ( + "bytes" + "encoding/base64" + "errors" + "io" + "net/http" + "strconv" "strings" + "github.com/google/uuid" + "google.golang.org/protobuf/proto" + "go.mau.fi/mautrix-gmessages/libgm/binary" "go.mau.fi/mautrix-gmessages/libgm/crypto" + "go.mau.fi/mautrix-gmessages/libgm/util" ) type MediaType struct { @@ -107,3 +117,133 @@ func (c *Client) UploadMedia(data []byte, fileName, mime string) (*binary.MediaC DecryptionKey: decryptionKey, }, nil } + +type StartGoogleUpload struct { + UploadID string + UploadURL string + UploadStatus string + ChunkGranularity int64 + ControlURL string + MimeType string + + EncryptedMediaBytes []byte +} + +type MediaUpload struct { + MediaID string + MediaNumber int64 +} + +var ( + errStartUploadMedia = errors.New("failed to start uploading media") + errFinalizeUploadMedia = errors.New("failed to finalize uploading media") +) + +func (c *Client) FinalizeUploadMedia(upload *StartGoogleUpload) (*MediaUpload, error) { + encryptedImageSize := strconv.Itoa(len(upload.EncryptedMediaBytes)) + + finalizeUploadHeaders := util.NewMediaUploadHeaders(encryptedImageSize, "upload, finalize", "0", upload.MimeType, "") + req, reqErr := http.NewRequest("POST", upload.UploadURL, bytes.NewBuffer(upload.EncryptedMediaBytes)) + if reqErr != nil { + return nil, reqErr + } + + req.Header = *finalizeUploadHeaders + + res, resErr := c.http.Do(req) + if resErr != nil { + panic(resErr) + } + + statusCode := res.StatusCode + if statusCode != 200 { + return nil, errFinalizeUploadMedia + } + + defer res.Body.Close() + + rHeaders := res.Header + googleResponse, err3 := io.ReadAll(base64.NewDecoder(base64.StdEncoding, res.Body)) + if err3 != nil { + return nil, err3 + } + + uploadStatus := rHeaders.Get("x-goog-upload-status") + c.Logger.Debug().Str("upload_status", uploadStatus).Msg("Upload complete") + + mediaIDs := &binary.UploadMediaResponse{} + err3 = proto.Unmarshal(googleResponse, mediaIDs) + if err3 != nil { + return nil, err3 + } + return &MediaUpload{ + MediaID: mediaIDs.Media.MediaID, + MediaNumber: mediaIDs.Media.MediaNumber, + }, nil +} + +func (c *Client) StartUploadMedia(encryptedImageBytes []byte, mime string) (*StartGoogleUpload, error) { + encryptedImageSize := strconv.Itoa(len(encryptedImageBytes)) + + startUploadHeaders := util.NewMediaUploadHeaders(encryptedImageSize, "start", "", mime, "resumable") + startUploadPayload, buildPayloadErr := c.buildStartUploadPayload() + if buildPayloadErr != nil { + return nil, buildPayloadErr + } + + req, reqErr := http.NewRequest("POST", util.UploadMediaURL, bytes.NewBuffer([]byte(startUploadPayload))) + if reqErr != nil { + return nil, reqErr + } + + req.Header = *startUploadHeaders + + res, resErr := c.http.Do(req) + if resErr != nil { + panic(resErr) + } + + statusCode := res.StatusCode + if statusCode != 200 { + return nil, errStartUploadMedia + } + + rHeaders := res.Header + + chunkGranularity, convertErr := strconv.Atoi(rHeaders.Get("x-goog-upload-chunk-granularity")) + if convertErr != nil { + return nil, convertErr + } + + uploadResponse := &StartGoogleUpload{ + UploadID: rHeaders.Get("x-guploader-uploadid"), + UploadURL: rHeaders.Get("x-goog-upload-url"), + UploadStatus: rHeaders.Get("x-goog-upload-status"), + ChunkGranularity: int64(chunkGranularity), + ControlURL: rHeaders.Get("x-goog-upload-control-url"), + MimeType: mime, + + EncryptedMediaBytes: encryptedImageBytes, + } + return uploadResponse, nil +} + +func (c *Client) buildStartUploadPayload() (string, error) { + protoData := &binary.StartMediaUploadPayload{ + ImageType: 1, + AuthData: &binary.AuthMessage{ + RequestID: uuid.NewString(), + TachyonAuthToken: c.AuthData.TachyonAuthToken, + ConfigVersion: util.ConfigMessage, + }, + Mobile: c.AuthData.Mobile, + } + + protoDataBytes, err := proto.Marshal(protoData) + if err != nil { + return "", err + } + protoDataEncoded := base64.StdEncoding.EncodeToString(protoDataBytes) + + return protoDataEncoded, nil +}