diff --git a/auth/confirm.go b/auth/confirm.go index 492e758a38c55fb0cda1aed0feedcb8fcce66f73..f0f7ba84975ae9f8e261c68014fabe8f347bc2d7 100644 --- a/auth/confirm.go +++ b/auth/confirm.go @@ -168,6 +168,7 @@ func ConfirmRequestAuth(partner contact.Contact, rng io.Reader, param := params.GetDefaultCMIX() param.IdentityPreimage = preimg + param.DebugTag = "auth.Confirm" /*send message*/ round, _, err := net.SendCMIX(cmixMsg, partner.ID, param) if err != nil { diff --git a/auth/request.go b/auth/request.go index 1f63d7e157caa9cb360d66f0fd3ec82c51ab7d69..7148cf5a4b0dc1d171da6eb62178cd08c60620b7 100644 --- a/auth/request.go +++ b/auth/request.go @@ -173,6 +173,7 @@ func RequestAuth(partner, me contact.Contact, rng io.Reader, /*send message*/ p := params.GetDefaultCMIX() p.IdentityPreimage = preimage.GenerateRequest(partner.ID) + p.DebugTag = "auth.Request" round, _, err := net.SendCMIX(cmixMsg, partner.ID, p) if err != nil { // if the send fails just set it to failed, it will diff --git a/dummy/send.go b/dummy/send.go index 2ae9d92888b5960bee25687f1b9a4f4078a2cd2b..a01f6ba69cc1940fda4735a9278cf460fbd3b7a9 100644 --- a/dummy/send.go +++ b/dummy/send.go @@ -102,7 +102,7 @@ func (m *Manager) sendMessages(msgs map[id.ID]format.Message) error { "preimage in e2e send: %+v", err) } rng.Close() - + p.DebugTag = "dummy" _, _, err := m.net.SendCMIX(msg, &recipient, p) if err != nil { jww.WARN.Printf("Failed to send dummy message %d/%d via "+ diff --git a/fileTransfer/send.go b/fileTransfer/send.go index daeca373c1cba813f000840f39f747049db6262d..0ae1bdfae8e58456395d4cc5cbc300fd13f7040a 100644 --- a/fileTransfer/send.go +++ b/fileTransfer/send.go @@ -247,6 +247,7 @@ func (m *Manager) sendParts(partList []queuedPart, p := params.GetDefaultCMIX() p.SendTimeout = m.p.SendTimeout p.ExcludedRounds = sentRounds + p.DebugTag = "ft.Part" // Send parts rid, _, err := m.net.SendManyCMIX(messages, p) @@ -477,6 +478,7 @@ func (m *Manager) sendEndE2eMessage(recipient *id.ID) error { // Send the message under file transfer preimage e2eParams := params.GetDefaultE2E() e2eParams.IdentityPreimage = partner.GetFileTransferPreimage() + e2eParams.DebugTag = "ft.End" // Store the message in the critical messages buffer first to ensure it is // present if the send fails diff --git a/fileTransfer/sendNew.go b/fileTransfer/sendNew.go index 99a935b737a6d0cfff495cc4e458ab1314fd3414..b28fe263958c3ff5b95455faee9f3623f44267b1 100644 --- a/fileTransfer/sendNew.go +++ b/fileTransfer/sendNew.go @@ -43,6 +43,7 @@ func (m *Manager) sendNewFileTransfer(recipient *id.ID, fileName, // Sends as a silent message to avoid a notification p := params.GetDefaultE2E() p.CMIX.IdentityPreimage = relationship.GetSilentPreimage() + p.DebugTag = "ft.New" // Send E2E message rounds, _, _, err := m.net.SendE2E(sendMsg, p, nil) diff --git a/groupChat/send.go b/groupChat/send.go index 868d420134b6ebb79c0687f58648311af6445559..f00f4669e615096295404a835b5a5b46b16f9ecf 100644 --- a/groupChat/send.go +++ b/groupChat/send.go @@ -50,6 +50,7 @@ func (m *Manager) Send(groupID *id.ID, message []byte) (id.Round, time.Time, param := params.GetDefaultCMIX() param.IdentityPreimage = groupID[:] + param.DebugTag = "group.Message" rid, _, err := m.net.SendManyCMIX(messages, param) if err != nil { diff --git a/groupChat/sendRequests.go b/groupChat/sendRequests.go index b48335911b5ff2d193a070dc62455b5378f769fb..555fd2c5e0cfc891ba8cf37877e6dc72353aebf3 100644 --- a/groupChat/sendRequests.go +++ b/groupChat/sendRequests.go @@ -126,6 +126,7 @@ func (m Manager) sendRequest(memberID *id.ID, request []byte) ([]id.Round, error p := params.GetDefaultE2E() p.IdentityPreimage = recipent.GetGroupRequestPreimage() + p.DebugTag = "group.Request" rounds, _, _, err := m.net.SendE2E(sendMsg, p, nil) if err != nil { diff --git a/interfaces/params/CMIX.go b/interfaces/params/CMIX.go index 5e772d0360a94350ff6b99b6db33d22934e5410d..db2bfa655906d3b07d98ca54ea1f1539cd2fb9ed 100644 --- a/interfaces/params/CMIX.go +++ b/interfaces/params/CMIX.go @@ -27,6 +27,10 @@ type CMIX struct { // an alternate identity preimage to use on send. If not set, the default // for the sending identity will be used IdentityPreimage []byte + + // Tag which prints with sending logs to help localize the source + // All internal sends are tagged, so the default tag is "External" + DebugTag string } func GetDefaultCMIX() CMIX { @@ -35,6 +39,7 @@ func GetDefaultCMIX() CMIX { Timeout: 25 * time.Second, RetryDelay: 1 * time.Second, SendTimeout: 3 * time.Second, + DebugTag: "External", } } diff --git a/keyExchange/rekey.go b/keyExchange/rekey.go index 773a8544c5a1d614f8b5ab1bbaab14035d3488f3..04bb31413af965f621884a01ab0f557c632ec504 100644 --- a/keyExchange/rekey.go +++ b/keyExchange/rekey.go @@ -8,6 +8,7 @@ package keyExchange import ( + "fmt" "github.com/golang/protobuf/proto" "github.com/pkg/errors" jww "github.com/spf13/jwalterweatherman" @@ -24,7 +25,6 @@ import ( "gitlab.com/elixxir/crypto/diffieHellman" "gitlab.com/elixxir/primitives/states" "time" - "fmt" ) func CheckKeyExchanges(instance *network.Instance, sendE2E interfaces.SendE2E, @@ -121,6 +121,7 @@ func negotiate(instance *network.Instance, sendE2E interfaces.SendE2E, e2eParams := params.GetDefaultE2E() e2eParams.Type = params.KeyExchange e2eParams.IdentityPreimage = rekeyPreimage + e2eParams.DebugTag = "kx.Request" rounds, msgID, _, err := sendE2E(m, e2eParams, stop) // If the send fails, returns the error so it can be handled. The caller diff --git a/keyExchange/trigger.go b/keyExchange/trigger.go index 9e3bf66a3a7b596478f35be48cb3e88415c184c6..fcdb71aa93fc535ac879696ebe36a86d6045de87 100644 --- a/keyExchange/trigger.go +++ b/keyExchange/trigger.go @@ -125,6 +125,7 @@ func handleTrigger(sess *storage.Session, net interfaces.NetworkManager, //send the message under the key exchange e2eParams := params.GetDefaultE2E() e2eParams.IdentityPreimage = partner.GetSilentPreimage() + e2eParams.DebugTag = "kx.Confirm" // store in critical messages buffer first to ensure it is resent if the // send fails diff --git a/network/message/sendCmix.go b/network/message/sendCmix.go index e0b127542041623ba3437e289d872632c36184a5..342e781c9a7ff737c8473305a8c2c3c210a6bfc8 100644 --- a/network/message/sendCmix.go +++ b/network/message/sendCmix.go @@ -85,8 +85,8 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, attempted = excludedRounds.NewSet() } - jww.INFO.Printf("Looking for round to send cMix message to %s "+ - "(msgDigest: %s)", recipient, msg.Digest()) + jww.INFO.Printf("[SendCMIX-%s]Looking for round to send cMix message to %s "+ + "(msgDigest: %s)", cmixParams.DebugTag, recipient, msg.Digest()) stream := rng.GetStream() defer stream.Close() @@ -98,18 +98,18 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, for numRoundTries := uint(0); numRoundTries < cmixParams.RoundTries; numRoundTries++ { elapsed := netTime.Since(timeStart) - jww.TRACE.Printf("[SendCMIX] try %d, elapsed: %s", - numRoundTries, elapsed) + jww.TRACE.Printf("[SendCMIX-%s] try %d, elapsed: %s", + cmixParams.DebugTag, numRoundTries, elapsed) if elapsed > cmixParams.Timeout { - jww.INFO.Printf("No rounds to send to %s (msgDigest: %s) "+ - "were found before timeout %s", recipient, msg.Digest(), + jww.INFO.Printf("[SendCMIX-%s] No rounds to send to %s (msgDigest: %s) "+ + "were found before timeout %s", cmixParams.DebugTag, recipient, msg.Digest(), cmixParams.Timeout) return 0, ephemeral.Id{}, errors.New("Sending cmix message timed out") } if numRoundTries > 0 { - jww.INFO.Printf("Attempt %d to find round to send message "+ - "to %s (msgDigest: %s)", numRoundTries+1, recipient, + jww.INFO.Printf("[SendCMIX-%s] Attempt %d to find round to send message "+ + "to %s (msgDigest: %s)", cmixParams.DebugTag, numRoundTries+1, recipient, msg.Digest()) } @@ -117,13 +117,14 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, remainingTime := cmixParams.Timeout - elapsed bestRound, err := instance.GetWaitingRounds().GetUpcomingRealtime(remainingTime, attempted, sendTimeBuffer) if err != nil { - jww.WARN.Printf("Failed to GetUpcomingRealtime (msgDigest: %s): %+v", msg.Digest(), err) + jww.WARN.Printf("[SendCMIX-%s] Failed to GetUpcomingRealtime " + + "(msgDigest: %s): %+v", cmixParams.DebugTag, msg.Digest(), err) } if bestRound == nil { - jww.WARN.Printf("Best round on send is nil") + jww.WARN.Printf("[SendCMIX-%s], Best round on send is nil", cmixParams.DebugTag) continue } - jww.TRACE.Printf("[sendCMIX] bestRound: %v", bestRound) + jww.TRACE.Printf("[SendCMIX-%s] bestRound: %v", cmixParams.DebugTag, bestRound) // add the round on to the list of attempted, so it is not tried again attempted.Insert(bestRound.GetRoundId()) @@ -138,19 +139,21 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, } } if containsBlacklisted { - jww.WARN.Printf("Round %d contains blacklisted node, skipping...", bestRound.ID) + jww.WARN.Printf("[SendCMIX-%s]Round %d contains blacklisted node, " + + "skipping...", cmixParams.DebugTag, bestRound.ID) continue } // Retrieve host and key information from round firstGateway, roundKeys, err := processRound(instance, session, nodeRegistration, bestRound, recipient.String(), msg.Digest()) if err != nil { - jww.WARN.Printf("SendCmix failed to process round (will retry): %v", err) + jww.WARN.Printf("[SendCMIX-%s]SendCmix failed to process round" + + " (will retry): %v", cmixParams.DebugTag, err) continue } - jww.TRACE.Printf("[sendCMIX] round %v processed, firstGW: %s", - bestRound, firstGateway) + jww.TRACE.Printf("[SendCMIX-%s]round %v processed, firstGW: %s", + cmixParams.DebugTag, bestRound, firstGateway) // Build the messages to send @@ -160,9 +163,9 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, return 0, ephemeral.Id{}, err } - jww.INFO.Printf("[sendCMIX] Sending to EphID %d (%s), "+ + jww.INFO.Printf("[SendCMIX-%s] Sending to EphID %d (%s), "+ "on round %d (msgDigest: %s, ecrMsgDigest: %s) "+ - "via gateway %s", + "via gateway %s", cmixParams.DebugTag, ephID.Int64(), recipient, bestRound.ID, msg.Digest(), encMsg.Digest(), firstGateway.String()) @@ -171,7 +174,7 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, timeout time.Duration) (interface{}, error) { wrappedMsg.Target = target.Marshal() - jww.TRACE.Printf("[sendCMIX] sendFunc %s", host) + jww.TRACE.Printf("[SendCMIX-%s]sendFunc %s", cmixParams.DebugTag, host) timeout = calculateSendTimeout(bestRound, maxTimeout) // Use the smaller of the two timeout durations calculatedTimeout := calculateSendTimeout(bestRound, maxTimeout) @@ -182,24 +185,24 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, //send the message result, err := comms.SendPutMessage(host, wrappedMsg, timeout) - jww.TRACE.Printf("[sendCMIX] sendFunc %s putmsg", host) + jww.TRACE.Printf("[SendCMIX-%s]sendFunc %s putmsg", cmixParams.DebugTag, host) if err != nil { // fixme: should we provide as a slice the whole topology? err := handlePutMessageError(firstGateway, instance, session, nodeRegistration, recipient.String(), bestRound, err) - jww.TRACE.Printf("[sendCMIX] sendFunc %s err %+v", - host, err) + jww.TRACE.Printf("[SendCMIX-%s] sendFunc %s err %+v", + cmixParams.DebugTag, host, err) return result, errors.WithMessagef(err, "SendCmix %s", unrecoverableError) } return result, err } - jww.TRACE.Printf("[sendCMIX] sendToPreferred %s", firstGateway) + jww.TRACE.Printf("[SendCMIX-%s] sendToPreferred %s", firstGateway) result, err := sender.SendToPreferred( []*id.ID{firstGateway}, sendFunc, stop, cmixParams.SendTimeout) - jww.DEBUG.Printf("[sendCMIX] sendToPreferred %s returned", + jww.DEBUG.Printf("[SendCMIX-%s] sendToPreferred %s returned", firstGateway) // Exit if the thread has been stopped @@ -209,8 +212,8 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, // if the comm errors or the message fails to send, continue retrying. if err != nil { - jww.ERROR.Printf("SendCmix failed to send to EphID %d (%s) on "+ - "round %d, trying a new round: %+v", ephID.Int64(), recipient, + jww.ERROR.Printf("[SendCMIX-%s] SendCmix failed to send to EphID %d (%s) on "+ + "round %d, trying a new round: %+v", cmixParams.DebugTag, ephID.Int64(), recipient, bestRound.ID, err) continue } @@ -218,9 +221,9 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, // Return if it sends properly gwSlotResp := result.(*pb.GatewaySlotResponse) if gwSlotResp.Accepted { - m := fmt.Sprintf("Successfully sent to EphID %v "+ + m := fmt.Sprintf("[SendCMIX-%s] Successfully sent to EphID %v "+ "(source: %s) in round %d (msgDigest: %s), "+ - "elapsed: %s numRoundTries: %d", ephID.Int64(), + "elapsed: %s numRoundTries: %d", cmixParams.DebugTag, ephID.Int64(), recipient, bestRound.ID, msg.Digest(), elapsed, numRoundTries) jww.INFO.Print(m) @@ -228,9 +231,9 @@ func sendCmixHelper(sender *gateway.Sender, msg format.Message, onSend(1, session) return id.Round(bestRound.ID), ephID, nil } else { - jww.FATAL.Panicf("Gateway %s returned no error, but failed "+ + jww.FATAL.Panicf("[SendCMIX-%s] Gateway %s returned no error, but failed "+ "to accept message when sending to EphID %d (%s) on round %d", - firstGateway, ephID.Int64(), recipient, bestRound.ID) + cmixParams.DebugTag, firstGateway, ephID.Int64(), recipient, bestRound.ID) } } diff --git a/network/message/sendManyCmix.go b/network/message/sendManyCmix.go index 58edff8076be9e365f0c4873281c78141136f68c..09e9a4c59db138adc86b28f7800ff46c512abbd2 100644 --- a/network/message/sendManyCmix.go +++ b/network/message/sendManyCmix.go @@ -75,22 +75,22 @@ func sendManyCmixHelper(sender *gateway.Sender, recipientString, msgDigests := messageListToStrings(msgs) - jww.INFO.Printf("Looking for round to send cMix messages to [%s] "+ + jww.INFO.Printf("[SendManyCMIX-%s]Looking for round to send cMix messages to [%s] "+ "(msgDigest: %s)", recipientString, msgDigests) for numRoundTries := uint(0); numRoundTries < param.RoundTries; numRoundTries++ { elapsed := netTime.Since(timeStart) if elapsed > param.Timeout { - jww.INFO.Printf("No rounds to send to %s (msgDigest: %s) were found "+ - "before timeout %s", recipientString, msgDigests, param.Timeout) + jww.INFO.Printf("[SendManyCMIX-%s]No rounds to send to %s (msgDigest: %s) were found "+ + "before timeout %s", param.DebugTag, recipientString, msgDigests, param.Timeout) return 0, []ephemeral.Id{}, errors.New("sending cMix message timed out") } if numRoundTries > 0 { - jww.INFO.Printf("Attempt %d to find round to send message to %s "+ - "(msgDigest: %s)", numRoundTries+1, recipientString, msgDigests) + jww.INFO.Printf("[SendManyCMIX-%s]Attempt %d to find round to send message to %s "+ + "(msgDigest: %s)", param.DebugTag, numRoundTries+1, recipientString, msgDigests) } remainingTime := param.Timeout - elapsed @@ -116,8 +116,8 @@ func sendManyCmixHelper(sender *gateway.Sender, } } if containsBlacklisted { - jww.WARN.Printf("Round %d contains blacklisted node, skipping...", - bestRound.ID) + jww.WARN.Printf("[SendManyCMIX-%s]Round %d contains blacklisted node, skipping...", + param.DebugTag, bestRound.ID) continue } @@ -125,9 +125,9 @@ func sendManyCmixHelper(sender *gateway.Sender, firstGateway, roundKeys, err := processRound(instance, session, nodeRegistration, bestRound, recipientString, msgDigests) if err != nil { - jww.INFO.Printf("error processing round: %v", err) - jww.WARN.Printf("SendManyCMIX failed to process round %d "+ - "(will retry): %+v", bestRound.ID, err) + jww.INFO.Printf("[SendManyCMIX-%s]error processing round: %v", param.DebugTag, err) + jww.WARN.Printf("[SendManyCMIX-%s]SendManyCMIX failed to process round %d "+ + "(will retry): %+v", param.DebugTag, bestRound.ID, err) continue } @@ -142,7 +142,7 @@ func sendManyCmixHelper(sender *gateway.Sender, bestRound, roundKeys, param) if err != nil { stream.Close() - jww.INFO.Printf("error building slot received: %v", err) + jww.INFO.Printf("[SendManyCMIX-%s]error building slot received: %v", param.DebugTag, err) return 0, []ephemeral.Id{}, errors.Errorf("failed to build "+ "slot message for %s: %+v", msg.Recipient, err) } @@ -154,8 +154,8 @@ func sendManyCmixHelper(sender *gateway.Sender, ephemeralIDsString := ephemeralIdListToString(ephemeralIDs) encMsgsDigest := messagesToDigestString(encMsgs) - jww.INFO.Printf("Sending to EphIDs [%s] (%s) on round %d, "+ - "(msgDigest: %s, ecrMsgDigest: %s) via gateway %s", + jww.INFO.Printf("[SendManyCMIX-%s]Sending to EphIDs [%s] (%s) on round %d, "+ + "(msgDigest: %s, ecrMsgDigest: %s) via gateway %s", param.DebugTag, ephemeralIDsString, recipientString, bestRound.ID, msgDigests, encMsgsDigest, firstGateway) @@ -198,10 +198,10 @@ func sendManyCmixHelper(sender *gateway.Sender, // If the comm errors or the message fails to send, continue retrying if err != nil { if !strings.Contains(err.Error(), unrecoverableError) { - jww.ERROR.Printf("SendManyCMIX failed to send to EphIDs [%s] "+ + jww.ERROR.Printf("[SendManyCMIX-%s]SendManyCMIX failed to send to EphIDs [%s] "+ "(sources: %s) on round %d, trying a new round %+v", - ephemeralIDsString, recipientString, bestRound.ID, err) - jww.INFO.Printf("error received, continuing: %v", err) + param.DebugTag, ephemeralIDsString, recipientString, bestRound.ID, err) + jww.INFO.Printf("[SendManyCMIX-%s]error received, continuing: %v", param.DebugTag, err) continue } jww.INFO.Printf("error received: %v", err) @@ -211,8 +211,8 @@ func sendManyCmixHelper(sender *gateway.Sender, // Return if it sends properly gwSlotResp := result.(*pb.GatewaySlotResponse) if gwSlotResp.Accepted { - m := fmt.Sprintf("Successfully sent to EphIDs %s (sources: [%s]) "+ - "in round %d", ephemeralIDsString, recipientString, bestRound.ID) + m := fmt.Sprintf("[SendManyCMIX-%s]Successfully sent to EphIDs %s (sources: [%s]) "+ + "in round %d", param.DebugTag, ephemeralIDsString, recipientString, bestRound.ID) jww.INFO.Print(m) events.Report(1, "MessageSendMany", "Metric", m) onSend(uint32(len(msgs)), session) @@ -220,7 +220,7 @@ func sendManyCmixHelper(sender *gateway.Sender, } else { jww.FATAL.Panicf("Gateway %s returned no error, but failed to "+ "accept message when sending to EphIDs [%s] (%s) on round %d", - firstGateway, ephemeralIDsString, recipientString, bestRound.ID) + param.DebugTag, firstGateway, ephemeralIDsString, recipientString, bestRound.ID) } } diff --git a/single/response.go b/single/response.go index a5ab3cdb1baee704b214ff694b783c10182471ac..4486690e78e29185443d9bfd1642be78b2064b39 100644 --- a/single/response.go +++ b/single/response.go @@ -74,7 +74,9 @@ func (m *Manager) respondSingleUse(partner Contact, payload []byte, go func() { defer wg.Done() // Send Message - round, ephID, err := m.net.SendCMIX(cmixMsgFunc, partner.partner, params.GetDefaultCMIX()) + p := params.GetDefaultCMIX() + p.DebugTag = "single.Response" + round, ephID, err := m.net.SendCMIX(cmixMsgFunc, partner.partner, p) if err != nil { jww.ERROR.Printf("Failed to send single-use response CMIX "+ "message part %d: %+v", j, err) diff --git a/single/transmission.go b/single/transmission.go index 30f2f6c90a3cc5e5e8f6ece6cb459fc15ec1aa57..eb03345d769c4a3174407b2eb7e877dcbd4b5c20 100644 --- a/single/transmission.go +++ b/single/transmission.go @@ -116,7 +116,9 @@ func (m *Manager) transmitSingleUse(partner contact2.Contact, payload []byte, // Send Message jww.DEBUG.Printf("Sending single-use transmission CMIX "+ "message to %s.", partner.ID) - round, _, err := m.net.SendCMIX(cmixMsg, partner.ID, params.GetDefaultCMIX()) + p := params.GetDefaultCMIX() + p.DebugTag = "single.Transmit" + round, _, err := m.net.SendCMIX(cmixMsg, partner.ID,p) if err != nil { errorString := fmt.Sprintf("failed to send single-use transmission "+ "CMIX message: %+v", err)