From 0c79e50ca8e66dade1e62f40e7fda115feaa80d0 Mon Sep 17 00:00:00 2001 From: Andrea Maria Piana Date: Tue, 24 Nov 2020 13:36:52 +0100 Subject: [PATCH] Remove unnecessary logs & fix flaky test --- protocol/datasync/datasync.go | 2 +- protocol/datasync/transport.go | 5 +++ protocol/encryption/encryptor.go | 11 ++++-- protocol/encryption/protocol.go | 37 +++---------------- .../encryption/sharedsecret/sharedsecret.go | 17 --------- protocol/messenger.go | 2 - protocol/messenger_test.go | 9 +++++ protocol/pushnotificationclient/client.go | 3 -- 8 files changed, 29 insertions(+), 57 deletions(-) diff --git a/protocol/datasync/datasync.go b/protocol/datasync/datasync.go index 27181a702..be1cec1f7 100644 --- a/protocol/datasync/datasync.go +++ b/protocol/datasync/datasync.go @@ -31,7 +31,7 @@ func (d *DataSync) Handle(sender *ecdsa.PublicKey, payload []byte) [][]byte { datasyncMessage, err := unwrap(payload) // If it failed to decode is not a protobuf message, if it successfully decoded but body is empty, is likedly a protobuf wrapped message if err != nil || !datasyncMessage.IsValid() { - logger.Debug("handling non-datasync message", zap.Error(err), zap.Bool("datasyncMessage.IsValid()", datasyncMessage.IsValid())) + logger.Debug("handling non-datasync message", zap.Error(err), zap.Bool("datasyncMessage.IsValid()", datasyncMessage.IsValid()), zap.Any("message", datasyncMessage)) // Not a datasync message, return unchanged payloads = append(payloads, payload) } else { diff --git a/protocol/datasync/transport.go b/protocol/datasync/transport.go index d02c53e59..9d49e40e1 100644 --- a/protocol/datasync/transport.go +++ b/protocol/datasync/transport.go @@ -67,6 +67,11 @@ func (t *NodeTransport) Send(_ state.PeerID, peer state.PeerID, payload protobuf payloads := splitPayloadInBatches(&payload, int(t.maxMessageSize)) for _, payload := range payloads { + if !payload.IsValid() { + t.logger.Error("payload is invalid") + continue + } + data, err := proto.Marshal(payload) if err != nil { return err diff --git a/protocol/encryption/encryptor.go b/protocol/encryption/encryptor.go index bbaa788b0..4115a29a5 100644 --- a/protocol/encryption/encryptor.go +++ b/protocol/encryption/encryptor.go @@ -13,6 +13,7 @@ import ( "github.com/status-im/status-go/eth-node/crypto" "github.com/status-im/status-go/eth-node/crypto/ecies" + "github.com/status-im/status-go/eth-node/types" "github.com/status-im/status-go/protocol/encryption/multidevice" ) @@ -244,9 +245,14 @@ func (s *encryptor) DecryptPayload(myIdentityKey *ecdsa.PrivateKey, theirIdentit // We should not be sending a signal if it's coming from us, as we receive our own messages if msg == nil && !samePublicKeys(*theirIdentityKey, myIdentityKey.PublicKey) { + s.logger.Debug("message is coming from someone else, but not targeting our installation id") return nil, ErrDeviceNotFound - } else if msg == nil { + } else if msg == nil && theirInstallationID != s.config.InstallationID { + s.logger.Debug("message is coming from same public key, but different installation id") return nil, ErrNotPairedDevice + } else if msg == nil && theirInstallationID == s.config.InstallationID { + s.logger.Debug("message is coming from us and is nil") + return nil, nil } payload := msg.GetPayload() @@ -461,9 +467,8 @@ func (s *encryptor) GetPublicBundle(theirIdentityKey *ecdsa.PublicKey, installat func (s *encryptor) EncryptPayload(theirIdentityKey *ecdsa.PublicKey, myIdentityKey *ecdsa.PrivateKey, installations []*multidevice.Installation, payload []byte) (map[string]*DirectMessageProtocol, []*multidevice.Installation, error) { logger := s.logger.With( zap.String("site", "EncryptPayload"), - zap.Binary("their-identity-key", crypto.FromECDSAPub(theirIdentityKey))) + zap.String("their-identity-key", types.EncodeHex(crypto.FromECDSAPub(theirIdentityKey)))) - logger.Debug("encrypting payload") // Which installations we are sending the message to var targetedInstallations []*multidevice.Installation diff --git a/protocol/encryption/protocol.go b/protocol/encryption/protocol.go index 603e68319..8ef81b7fc 100644 --- a/protocol/encryption/protocol.go +++ b/protocol/encryption/protocol.go @@ -11,6 +11,7 @@ import ( "github.com/pkg/errors" "github.com/status-im/status-go/eth-node/crypto" + "github.com/status-im/status-go/eth-node/types" "github.com/status-im/status-go/protocol/encryption/multidevice" "github.com/status-im/status-go/protocol/encryption/publisher" @@ -146,18 +147,12 @@ func (p *Protocol) Stop() error { } func (p *Protocol) addBundle(myIdentityKey *ecdsa.PrivateKey, msg *ProtocolMessage) error { - logger := p.logger.With(zap.String("site", "addBundle")) - // Get a bundle installations, err := p.multidevice.GetOurActiveInstallations(&myIdentityKey.PublicKey) if err != nil { return err } - logger.Info("adding bundle to the message", - zap.Any("installations", installations), - ) - bundle, err := p.encryptor.CreateBundle(myIdentityKey, installations) if err != nil { return err @@ -186,12 +181,6 @@ func (p *Protocol) BuildPublicMessage(myIdentityKey *ecdsa.PrivateKey, payload [ // BuildDirectMessage returns a 1:1 chat message and optionally a negotiated topic given the user identity private key, the recipient's public key, and a payload func (p *Protocol) BuildDirectMessage(myIdentityKey *ecdsa.PrivateKey, publicKey *ecdsa.PublicKey, payload []byte) (*ProtocolMessageSpec, error) { - logger := p.logger.With( - zap.String("site", "BuildDirectMessage"), - zap.Binary("public-key", crypto.FromECDSAPub(publicKey)), - ) - - logger.Debug("building direct message") // Get recipients installations. activeInstallations, err := p.multidevice.GetActiveInstallations(publicKey) @@ -230,10 +219,6 @@ func (p *Protocol) BuildDirectMessage(myIdentityKey *ecdsa.PrivateKey, publicKey return nil, err } - logger.Debug("shared secret agreement", - zap.Bool("has-shared-secret", sharedSecret != nil), - zap.Bool("agreed", agreed)) - spec := &ProtocolMessageSpec{ SharedSecret: sharedSecret, AgreedSecret: agreed, @@ -269,8 +254,6 @@ func (p *Protocol) BuildDHMessage(myIdentityKey *ecdsa.PrivateKey, destination * func (p *Protocol) ProcessPublicBundle(myIdentityKey *ecdsa.PrivateKey, bundle *Bundle) ([]*multidevice.Installation, error) { logger := p.logger.With(zap.String("site", "ProcessPublicBundle")) - logger.Debug("processing public bundle") - if err := p.encryptor.ProcessPublicBundle(myIdentityKey, bundle); err != nil { return nil, err } @@ -280,10 +263,6 @@ func (p *Protocol) ProcessPublicBundle(myIdentityKey *ecdsa.PrivateKey, bundle * return nil, err } - logger.Debug("recovered installations", - zap.Int("installations", len(installations)), - zap.Bool("enabled", enabled)) - // TODO(adam): why do we add installations using identity obtained from GetIdentity() // instead of the output of crypto.CompressPubkey()? I tried the second option // and the unit tests TestTopic and TestMaxDevices fail. @@ -311,8 +290,6 @@ func (p *Protocol) recoverInstallationsFromBundle(myIdentityKey *ecdsa.PrivateKe return nil, false, err } - logger := p.logger.With(zap.String("site", "recoverInstallationsFromBundle")) - myIdentityStr := fmt.Sprintf("0x%x", crypto.FromECDSAPub(&myIdentityKey.PublicKey)) theirIdentityStr := fmt.Sprintf("0x%x", crypto.FromECDSAPub(theirIdentity)) // Any device from other peers will be considered enabled, ours needs to @@ -321,7 +298,6 @@ func (p *Protocol) recoverInstallationsFromBundle(myIdentityKey *ecdsa.PrivateKe signedPreKeys := bundle.GetSignedPreKeys() for installationID, signedPreKey := range signedPreKeys { - logger.Info("recovered installation", zap.String("installation-id", installationID)) if installationID != p.multidevice.InstallationID() { installations = append(installations, &multidevice.Installation{ Identity: theirIdentityStr, @@ -401,7 +377,11 @@ func (p *Protocol) HandleMessage( logger := p.logger.With(zap.String("site", "HandleMessage")) response := &DecryptMessageResponse{} - logger.Debug("received a protocol message", zap.Binary("sender-public-key", crypto.FromECDSAPub(theirPublicKey)), zap.Binary("message-id", messageID)) + logger.Debug("received a protocol message", + zap.String("sender-public-key", + types.EncodeHex(crypto.FromECDSAPub(theirPublicKey))), + zap.String("my-installation-id", p.encryptor.config.InstallationID), + zap.String("message-id", types.EncodeHex(messageID))) if p.encryptor == nil { return nil, errors.New("encryption service not initialized") @@ -419,7 +399,6 @@ func (p *Protocol) HandleMessage( // Check if it's a public message if publicMessage := protocolMessage.GetPublicMessage(); publicMessage != nil { - logger.Debug("received a public message in direct message") // Nothing to do, as already in cleartext response.DecryptedMessage = publicMessage return response, nil @@ -427,7 +406,6 @@ func (p *Protocol) HandleMessage( // Decrypt message if directMessage := protocolMessage.GetDirectMessage(); directMessage != nil { - logger.Debug("processing direct message") message, err := p.encryptor.DecryptPayload( myIdentityKey, theirPublicKey, @@ -441,10 +419,7 @@ func (p *Protocol) HandleMessage( bundles := protocolMessage.GetBundles() version := getProtocolVersion(bundles, protocolMessage.GetInstallationId()) - logger.Debug("direct message version", zap.Uint32("version", version)) if version >= sharedSecretNegotiationVersion { - logger.Debug("negotiating shared secret", - zap.Binary("public-key", crypto.FromECDSAPub(theirPublicKey))) sharedSecret, err := p.secret.Generate(myIdentityKey, theirPublicKey, protocolMessage.GetInstallationId()) if err != nil { return nil, err diff --git a/protocol/encryption/sharedsecret/sharedsecret.go b/protocol/encryption/sharedsecret/sharedsecret.go index d170f5b65..f85af1474 100644 --- a/protocol/encryption/sharedsecret/sharedsecret.go +++ b/protocol/encryption/sharedsecret/sharedsecret.go @@ -49,14 +49,6 @@ func (s *SharedSecret) generate(myPrivateKey *ecdsa.PrivateKey, theirPublicKey * return nil, err } - logger := s.logger.With(zap.String("site", "generate")) - - logger.Debug( - "saving a shared key", - zap.Binary("their-public-key", crypto.FromECDSAPub(theirPublicKey)), - zap.String("installation-id", installationID), - ) - theirIdentity := crypto.CompressPubkey(theirPublicKey) if err = s.persistence.Add(theirIdentity, sharedKey, installationID); err != nil { return nil, err @@ -72,14 +64,6 @@ func (s *SharedSecret) Generate(myPrivateKey *ecdsa.PrivateKey, theirPublicKey * // Agreed returns true if a secret has been acknowledged by all the installationIDs. func (s *SharedSecret) Agreed(myPrivateKey *ecdsa.PrivateKey, myInstallationID string, theirPublicKey *ecdsa.PublicKey, theirInstallationIDs []string) (*Secret, bool, error) { - logger := s.logger.With(zap.String("site", "Agreed")) - - logger.Debug( - "checking if shared secret is acknowledged", - zap.Binary("their-public-key", crypto.FromECDSAPub(theirPublicKey)), - zap.Strings("their-installation-ids", theirInstallationIDs), - ) - secret, err := s.generate(myPrivateKey, theirPublicKey, myInstallationID) if err != nil { return nil, false, err @@ -97,7 +81,6 @@ func (s *SharedSecret) Agreed(myPrivateKey *ecdsa.PrivateKey, myInstallationID s for _, installationID := range theirInstallationIDs { if !response.installationIDs[installationID] { - logger.Debug("no shared secret for installation", zap.String("installation-id", installationID)) return secret, false, nil } } diff --git a/protocol/messenger.go b/protocol/messenger.go index a258c28c5..ea622e904 100644 --- a/protocol/messenger.go +++ b/protocol/messenger.go @@ -379,10 +379,8 @@ func (m *Messenger) handleSendContactCode() error { // handleSharedSecrets process the negotiated secrets received from the encryption layer func (m *Messenger) handleSharedSecrets(secrets []*sharedsecret.Secret) error { - logger := m.logger.With(zap.String("site", "handleSharedSecrets")) var result []*transport.Filter for _, secret := range secrets { - logger.Debug("received shared secret", zap.Binary("identity", crypto.FromECDSAPub(secret.Identity))) fSecret := types.NegotiatedSecret{ PublicKey: secret.Identity, Key: secret.Key, diff --git a/protocol/messenger_test.go b/protocol/messenger_test.go index fc0949642..affea705e 100644 --- a/protocol/messenger_test.go +++ b/protocol/messenger_test.go @@ -950,6 +950,15 @@ func (s *MessengerSuite) TestReInvitedToGroupChat() { s.Require().Len(response.Chats, 1) s.Require().False(response.Chats[0].Active) + // Retrieve messages so user is removed + _, err = WaitOnMessengerResponse( + s.m, + func(r *MessengerResponse) bool { return len(r.Chats) > 0 && len(r.Chats[0].Members) == 1 }, + "leave group chat not received", + ) + + s.Require().NoError(err) + // And we get re-invited _, err = s.m.AddMembersToGroupChat(context.Background(), ourChat.ID, members) s.NoError(err) diff --git a/protocol/pushnotificationclient/client.go b/protocol/pushnotificationclient/client.go index bd91c856f..d472261dd 100644 --- a/protocol/pushnotificationclient/client.go +++ b/protocol/pushnotificationclient/client.go @@ -818,11 +818,8 @@ func (c *Client) queryNotificationInfo(publicKey *ecdsa.PublicKey, force bool) e // handleMessageSent is called every time a message is sent func (c *Client) handleMessageSent(sentMessage *common.SentMessage) error { - c.config.Logger.Debug("sent messages", zap.Any("messageIDs", sentMessage.MessageIDs)) - // Ignore if we are not sending notifications if !c.config.SendEnabled { - c.config.Logger.Debug("send not enabled, ignoring") return nil }