Remove unnecessary logs & fix flaky test

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 {

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

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
 

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

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
 		}
 	}

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,

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)

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
 	}