diff --git a/bindings/group.go b/bindings/group.go index e47cd9fc91c9631a2504bc88f68fec3eb2bfb07d..c5908b30790d24585ec1e9b6881f1989a461edd0 100644 --- a/bindings/group.go +++ b/bindings/group.go @@ -9,6 +9,7 @@ package bindings import ( "github.com/pkg/errors" + jww "github.com/spf13/jwalterweatherman" gc "gitlab.com/elixxir/client/groupChat" gs "gitlab.com/elixxir/client/groupChat/groupStore" "gitlab.com/elixxir/crypto/group" @@ -198,6 +199,10 @@ func (gsr *GroupSendReport) GetTimestampNano() int64 { // GetTimestampMS returns the timestamp of the send in milliseconds. func (gsr *GroupSendReport) GetTimestampMS() int64 { ts := uint64(gsr.timestamp.UnixNano()) / uint64(time.Millisecond) + + // TODO: remove the print below once debugging is done. + jww.DEBUG.Printf("Sent group message timestamp: %s", gsr.timestamp) + jww.DEBUG.Printf("Sent group message timestamp MS: %d", ts) return int64(ts) } @@ -329,7 +334,11 @@ func (gmr *GroupMessageReceive) GetTimestampNano() int64 { // GetTimestampMS returns the message timestamp in milliseconds. func (gmr *GroupMessageReceive) GetTimestampMS() int64 { + ts := uint64(gmr.Timestamp.UnixNano()) / uint64(time.Millisecond) + // TODO: remove the print below once debugging is done. + jww.DEBUG.Printf("Received group message timestamp: %s", gmr.Timestamp) + jww.DEBUG.Printf("Received group message timestamp MS: %d", ts) return int64(ts) } @@ -348,5 +357,8 @@ func (gmr *GroupMessageReceive) GetRoundTimestampNano() int64 { // message was sent on. func (gmr *GroupMessageReceive) GetRoundTimestampMS() int64 { ts := uint64(gmr.RoundTimestamp.UnixNano()) / uint64(time.Millisecond) + // TODO: remove the print below once debugging is done. + jww.DEBUG.Printf("Received group message round timestamp: %s", gmr.RoundTimestamp) + jww.DEBUG.Printf("Received group message round timestamp MS: %d", ts) return int64(ts) } diff --git a/groupChat/makeGroup.go b/groupChat/makeGroup.go index f3c5544c9e6b46a6a747e6ef96d1f7bc870e7aae..4f6a44c6e81ac1afc26a447095a91e33641ddc5d 100644 --- a/groupChat/makeGroup.go +++ b/groupChat/makeGroup.go @@ -81,8 +81,8 @@ func (m Manager) MakeGroup(membership []*id.ID, name, msg []byte) (gs.Group, return gs.Group{}, nil, NotSent, errors.Errorf(addGroupErr, err) } - jww.DEBUG.Printf("Created new group %q with ID %s and members %s", - g.Name, g.ID, g.Members) + jww.DEBUG.Printf("Created new group %q with ID %s and %d members %s", + g.Name, g.ID, len(g.Members), g.Members) // Send all group requests roundIDs, status, err := m.sendRequests(g) diff --git a/groupChat/manager.go b/groupChat/manager.go index 92081c060859f180e08c34693d80668b159f3f60..c8615b45fbd452121842f36d76c6848fc7f5cb49 100644 --- a/groupChat/manager.go +++ b/groupChat/manager.go @@ -129,7 +129,7 @@ func (m Manager) JoinGroup(g gs.Group) error { return errors.Errorf(joinGroupErr, g.ID, err) } - jww.DEBUG.Printf("Joined group %s.", g.ID) + jww.DEBUG.Printf("Joined group %q with ID %s.", g.Name, g.ID) return nil } @@ -140,7 +140,7 @@ func (m Manager) LeaveGroup(groupID *id.ID) error { return errors.Errorf(leaveGroupErr, groupID, err) } - jww.DEBUG.Printf("Left group %s.", groupID) + jww.DEBUG.Printf("Left group with ID %s.", groupID) return nil } diff --git a/groupChat/receive.go b/groupChat/receive.go index a708a83becd4d1d33fd8dddf459d0562852e5fd1..54de12de422a0b680b23fcf852bc04dbc8a5af4e 100644 --- a/groupChat/receive.go +++ b/groupChat/receive.go @@ -25,7 +25,7 @@ const ( unmarshalInternalMsgErr = "failed to unmarshal group internal message: %+v" unmarshalSenderIdErr = "failed to unmarshal sender ID: %+v" unmarshalPublicMsgErr = "failed to unmarshal group cMix message contents: %+v" - findGroupKeyFpErr = "failed to find group with key fingerprint matching %s" + findGroupKeyFpErr = "no group with key fingerprint %s" genCryptKeyMacErr = "failed to generate encryption key for group " + "cMix message because MAC verification failed (epoch %d could be off)" ) @@ -45,13 +45,23 @@ func (m Manager) receive(rawMsgs chan message.Receive, stop *stoppable.Single) { jww.DEBUG.Print("Group message reception received cMix message.") // Attempt to read the message - g, msgID, timestamp, senderID, msg, err := m.readMessage(receiveMsg) + g, msgID, timestamp, senderID, msg, noFpMatch, err := + m.readMessage(receiveMsg) if err != nil { - jww.WARN.Printf("Group message reception failed to read cMix "+ - "message: %+v", err) + if noFpMatch { + jww.DEBUG.Printf("Received message not for group chat: %+v", + err) + } else { + jww.WARN.Printf("Group message reception failed to read "+ + "cMix message: %+v", err) + } continue } + jww.DEBUG.Printf("Received group message with ID %s from sender "+ + "%s in group %s with ID %s at %s.", msgID, senderID, g.Name, + g.ID, timestamp) + // If the message was read correctly, send it to the callback go m.receiveFunc(MessageReceive{ GroupID: g.ID, @@ -72,31 +82,32 @@ func (m Manager) receive(rawMsgs chan message.Receive, stop *stoppable.Single) { // of a group message. The encrypted group message data is unmarshalled from a // cMix message in the message.Receive and then decrypted and the MAC is // verified. The group is found by finding the group with a matching key -// fingerprint. +// fingerprint. Returns true if the key fingerprint cannot be found; in this +// case no warning or error should be printed. func (m *Manager) readMessage(msg message.Receive) (gs.Group, group.MessageID, - time.Time, *id.ID, []byte, error) { + time.Time, *id.ID, []byte, bool, error) { // Unmarshal payload into cMix message cMixMsg := format.Unmarshal(msg.Payload) // Unmarshal cMix message contents to get public message format - publicMsg, err := unmarshalPublicMsg(cMixMsg.GetContents()) + pubMsg, err := unmarshalPublicMsg(cMixMsg.GetContents()) if err != nil { - return gs.Group{}, group.MessageID{}, time.Time{}, nil, nil, + return gs.Group{}, group.MessageID{}, time.Time{}, nil, nil, false, errors.Errorf(unmarshalPublicMsgErr, err) } // Get the group from storage via key fingerprint lookup - g, exists := m.gs.GetByKeyFp(cMixMsg.GetKeyFP(), publicMsg.GetSalt()) + g, exists := m.gs.GetByKeyFp(cMixMsg.GetKeyFP(), pubMsg.GetSalt()) if !exists { - return gs.Group{}, group.MessageID{}, time.Time{}, nil, nil, + return gs.Group{}, group.MessageID{}, time.Time{}, nil, nil, true, errors.Errorf(findGroupKeyFpErr, cMixMsg.GetKeyFP()) } // Decrypt the payload and return the messages timestamp, sender ID, and // message contents messageID, timestamp, senderID, contents, err := m.decryptMessage( - g, cMixMsg, publicMsg, msg.RoundTimestamp) - return g, messageID, timestamp, senderID, contents, err + g, cMixMsg, pubMsg, msg.RoundTimestamp) + return g, messageID, timestamp, senderID, contents, false, err } // decryptMessage decrypts the group message payload and returns its message ID, diff --git a/groupChat/receiveRequest.go b/groupChat/receiveRequest.go index 76018cc4ae50ece4128510a0221013f9845b411d..bb5b520cc22215c3e0ff060ea10ea08ad935a79f 100644 --- a/groupChat/receiveRequest.go +++ b/groupChat/receiveRequest.go @@ -37,7 +37,7 @@ func (m Manager) receiveRequest(rawMsgs chan message.Receive, stop.ToStopped() return case sendMsg := <-rawMsgs: - jww.DEBUG.Print("Group message request received send message.") + jww.DEBUG.Print("Group message request received message.") // Generate the group from the request message g, err := m.readRequest(sendMsg) @@ -50,6 +50,9 @@ func (m Manager) receiveRequest(rawMsgs chan message.Receive, // Call request callback with the new group if it does not already // exist if _, exists := m.GetGroup(g.ID); !exists { + jww.DEBUG.Printf("Received group request from sender %s for "+ + "group %s with ID %s.", sendMsg.Sender, g.Name, g.ID) + go m.requestFunc(g) } } diff --git a/groupChat/receive_test.go b/groupChat/receive_test.go index 125e34815ee64282df2a546e1a3e001c575ea266..1592f19f2185852de918a76ba17f5dd767f62018 100644 --- a/groupChat/receive_test.go +++ b/groupChat/receive_test.go @@ -165,11 +165,16 @@ func TestManager_readMessage(t *testing.T) { } m.gs.SetUser(expectedGrp.Members[4], t) - g, messageID, timestamp, senderID, contents, err := m.readMessage(receiveMsg) + g, messageID, timestamp, senderID, contents, noFpMatch, err := + m.readMessage(receiveMsg) if err != nil { t.Errorf("readMessage() returned an error: %+v", err) } + if noFpMatch { + t.Error("Fingerprint did not match when it should have.") + } + if !reflect.DeepEqual(expectedGrp, g) { t.Errorf("readMessage() returned incorrect group."+ "\nexpected: %#v\nreceived: %#v", expectedGrp, g) @@ -226,7 +231,7 @@ func TestManager_readMessage_FindGroupKpError(t *testing.T) { expectedErr := strings.SplitN(findGroupKeyFpErr, "%", 2)[0] m.gs.SetUser(g.Members[4], t) - _, _, _, _, _, err = m.readMessage(receiveMsg) + _, _, _, _, _, _, err = m.readMessage(receiveMsg) if err == nil || !strings.Contains(err.Error(), expectedErr) { t.Errorf("readMessage() failed to return the expected error."+ "\nexpected: %s\nreceived: %+v", expectedErr, err) diff --git a/groupChat/send.go b/groupChat/send.go index 0ac72527b60e535b07fd553f4d7a2b386e578d32..1a6e1f3e5ce11edf2a55b5dfc16e28666e0c807b 100644 --- a/groupChat/send.go +++ b/groupChat/send.go @@ -52,7 +52,8 @@ func (m *Manager) Send(groupID *id.ID, message []byte) (id.Round, time.Time, errors.Errorf(sendManyCmixErr, m.gs.GetUser().ID, groupID, err) } - jww.DEBUG.Printf("Sent message to group %s.", groupID) + jww.DEBUG.Printf("Sent message to %d members in group %s at %s.", + len(messages), groupID, timeNow) return rid, timeNow, nil } diff --git a/groupChat/sendRequests.go b/groupChat/sendRequests.go index cd7913fcf9488d1a5927d4171f7677e99cf245c6..59c4f85226a2f33887e4b771fc0b81f6d52bb692 100644 --- a/groupChat/sendRequests.go +++ b/groupChat/sendRequests.go @@ -101,6 +101,9 @@ func (m Manager) sendRequests(g gs.Group) ([]id.Round, RequestStatus, error) { strings.Join(errs, "\n")) } + jww.DEBUG.Printf("Sent group request to %d members in group %q with ID %s.", + len(g.Members), g.Name, g.ID) + // If all sends succeeded, return a list of roundIDs return roundIdMap2List(roundIDs), AllSent, nil }