diff --git a/auth/confirm.go b/auth/confirm.go index c2d6c59081876d237459e19d14725bf8252d4bc6..092be519f004024896683617637c3d5aca047262 100644 --- a/auth/confirm.go +++ b/auth/confirm.go @@ -124,16 +124,23 @@ func ConfirmRequestAuth(partner contact.Contact, rng io.Reader, //store the message as a critical message so it will always be sent storage.GetCriticalRawMessages().AddProcessing(cmixMsg, partner.ID) + jww.INFO.Printf("Confirming Auth with %s, msgDigest: %s", + partner.ID, cmixMsg.Digest()) + /*send message*/ round, _, err := net.SendCMIX(cmixMsg, partner.ID, params.GetDefaultCMIX()) if err != nil { // if the send fails just set it to failed, it will but automatically // retried - jww.ERROR.Printf("auth confirm failed to transmit, will be "+ - "handled on reconnect: %+v", err) + jww.INFO.Printf("Auth Confirm with %s (msgDigest: %s) failed " + + "to transmit: %+v", partner.ID, cmixMsg.Digest(), err) storage.GetCriticalRawMessages().Failed(cmixMsg, partner.ID) + return errors.WithMessage(err,"Auth Confirm Failed to transmit") } + jww.INFO.Printf("Confirm Request with %s (msgDigest: %s) sent on round %d", + partner.ID, cmixMsg.Digest(), round) + /*check message delivery*/ sendResults := make(chan ds.EventReturn, 1) roundEvents := net.GetInstance().GetRoundEvents() @@ -141,12 +148,23 @@ func ConfirmRequestAuth(partner contact.Contact, rng io.Reader, roundEvents.AddRoundEventChan(round, sendResults, 1*time.Minute, states.COMPLETED, states.FAILED) - success, _, _ := utility.TrackResults(sendResults, 1) + success, numFailed, _ := utility.TrackResults(sendResults, 1) if !success { + if numFailed > 0{ + jww.INFO.Printf("Auth Confirm with %s (msgDigest: %s) failed " + + "delivery due to round failure, will retry on reconnect", + partner.ID, cmixMsg.Digest()) + }else{ + jww.INFO.Printf("Auth Confirm with %s (msgDigest: %s) failed " + + "delivery due to timeout, will retry on reconnect", + partner.ID, cmixMsg.Digest()) + } jww.ERROR.Printf("auth confirm failed to transmit, will be " + "handled on reconnect") storage.GetCriticalRawMessages().Failed(cmixMsg, partner.ID) } else { + jww.INFO.Printf("Auth Confirm with %s (msgDigest: %s) delivered " + + "sucesfully", partner.ID, cmixMsg.Digest()) storage.GetCriticalRawMessages().Succeeded(cmixMsg, partner.ID) } diff --git a/auth/request.go b/auth/request.go index 369fdf8c4ecb7a289b46378249307a1a04d24d54..7b966249746eb24d37fcd840d8aa1d00f2fa64de 100644 --- a/auth/request.go +++ b/auth/request.go @@ -112,8 +112,8 @@ func RequestAuth(partner, me contact.Contact, message string, rng io.Reader, newPrivKey := diffieHellman.GeneratePrivateKey(256, grp, rng) newPubKey := diffieHellman.GeneratePublicKey(newPrivKey, grp) - jww.INFO.Printf("RequestAuth MYPUBKEY: %v", newPubKey.Bytes()) - jww.INFO.Printf("RequestAuth THEIRPUBKEY: %v", partner.DhPubKey.Bytes()) + jww.TRACE.Printf("RequestAuth MYPUBKEY: %v", newPubKey.Bytes()) + jww.TRACE.Printf("RequestAuth THEIRPUBKEY: %v", partner.DhPubKey.Bytes()) /*encrypt payload*/ requestFmt.SetID(storage.GetUser().ReceptionID) @@ -132,7 +132,6 @@ func RequestAuth(partner, me contact.Contact, message string, rng io.Reader, cmixMsg.SetKeyFP(requestfp) cmixMsg.SetMac(mac) cmixMsg.SetContents(baseFmt.Marshal()) - jww.INFO.Printf("PARTNER ID: %s", partner.ID) /*store state*/ //fixme: channel is bricked if the first store succedes but the second fails @@ -146,21 +145,23 @@ func RequestAuth(partner, me contact.Contact, message string, rng io.Reader, //store the message as a critical message so it will always be sent storage.GetCriticalRawMessages().AddProcessing(cmixMsg, partner.ID) - //jww.INFO.Printf("CMIX MESSAGE 1: %s, %v, %v, %v", cmixMsg.GetRecipientID(), - // cmixMsg.GetKeyFP(), cmixMsg.GetMac(), cmixMsg.GetContents()) - jww.INFO.Printf("CMIX MESSAGE FP: %s, %v", partner.ID, - cmixMsg.GetKeyFP()) + jww.INFO.Printf("Requesting Auth with %s, msgDigest: %s", + partner.ID, cmixMsg.Digest()) /*send message*/ round, _, err := net.SendCMIX(cmixMsg, partner.ID, params.GetDefaultCMIX()) if err != nil { // if the send fails just set it to failed, it will but automatically // retried - jww.ERROR.Printf("auth request failed to transmit, will be "+ - "handled on reconnect: %+v", err) + jww.INFO.Printf("Auth Request with %s (msgDigest: %s) failed " + + "to transmit: %+v", partner.ID, cmixMsg.Digest(), err) storage.GetCriticalRawMessages().Failed(cmixMsg, partner.ID) + return errors.WithMessage(err,"Auth Request Failed to transmit") } + jww.INFO.Printf("Auth Request with %s (msgDigest: %s) sent on round %d", + partner.ID, cmixMsg.Digest(), round) + /*check message delivery*/ sendResults := make(chan ds.EventReturn, 1) roundEvents := net.GetInstance().GetRoundEvents() @@ -168,12 +169,21 @@ func RequestAuth(partner, me contact.Contact, message string, rng io.Reader, roundEvents.AddRoundEventChan(round, sendResults, 1*time.Minute, states.COMPLETED, states.FAILED) - success, _, _ := utility.TrackResults(sendResults, 1) + success, numFailed, _ := utility.TrackResults(sendResults, 1) if !success { - jww.ERROR.Printf("auth request failed to transmit, will be " + - "handled on reconnect") + if numFailed > 0{ + jww.INFO.Printf("Auth Request with %s (msgDigest: %s) failed " + + "delivery due to round failure, will retry on reconnect", + partner.ID, cmixMsg.Digest()) + }else{ + jww.INFO.Printf("Auth Request with %s (msgDigest: %s) failed " + + "delivery due to timeout, will retry on reconnect", + partner.ID, cmixMsg.Digest()) + } storage.GetCriticalRawMessages().Failed(cmixMsg, partner.ID) } else { + jww.INFO.Printf("Auth Request with %s (msgDigest: %s) delivered " + + "sucesfully", partner.ID, cmixMsg.Digest()) storage.GetCriticalRawMessages().Succeeded(cmixMsg, partner.ID) } diff --git a/go.mod b/go.mod index 27971d0f1c7c812a4106d9d8c7692f2b1bf96cd3..6c1c2a6e5eac7b169defafc0591e629db454e3b5 100644 --- a/go.mod +++ b/go.mod @@ -17,10 +17,10 @@ require ( github.com/spf13/jwalterweatherman v1.1.0 github.com/spf13/viper v1.7.1 gitlab.com/elixxir/bloomfilter v0.0.0-20200930191214-10e9ac31b228 - gitlab.com/elixxir/comms v0.0.4-0.20210218234550-f2e03b19bdb2 + gitlab.com/elixxir/comms v0.0.4-0.20210223182501-0b9a9fc80f48 gitlab.com/elixxir/crypto v0.0.7-0.20210216174551-f806f79610eb gitlab.com/elixxir/ekv v0.1.4 - gitlab.com/elixxir/primitives v0.0.3-0.20210216174458-2a23825c1eb1 + gitlab.com/elixxir/primitives v0.0.3-0.20210223180234-8e5d82635c20 gitlab.com/xx_network/comms v0.0.4-0.20210216174438-0790d1f1f225 gitlab.com/xx_network/crypto v0.0.5-0.20210216174356-e81e1ddf8fb7 gitlab.com/xx_network/primitives v0.0.4-0.20210219231511-983054dbee36 diff --git a/go.sum b/go.sum index 287f8dadf43fc313b4686ec4aacb8fe54c36310c..e98dca2edef79fd0d9aa9dcc25ddb549683896d7 100644 --- a/go.sum +++ b/go.sum @@ -257,6 +257,8 @@ gitlab.com/elixxir/comms v0.0.4-0.20210212194414-4c36bb47fa96 h1:66NNOMK9zQqW3xm gitlab.com/elixxir/comms v0.0.4-0.20210212194414-4c36bb47fa96/go.mod h1:ZXv+fpI/kRCzxxX6p4JXlonJVDl49t4+v71kEkBipgM= gitlab.com/elixxir/comms v0.0.4-0.20210218234550-f2e03b19bdb2 h1:p5GunVi5sP9atTw3DKBkgV6k3eR9iTyI6m9GbUr8hhA= gitlab.com/elixxir/comms v0.0.4-0.20210218234550-f2e03b19bdb2/go.mod h1:GCbfPWB7VF5ZeDsLBCwfy0JiquG4OK6gsRjaIS66+yg= +gitlab.com/elixxir/comms v0.0.4-0.20210223182501-0b9a9fc80f48 h1:fV6kL7PVZ+uR+TXGChGkCGdEM/DwThmQMcEhZTORt0w= +gitlab.com/elixxir/comms v0.0.4-0.20210223182501-0b9a9fc80f48/go.mod h1:GCbfPWB7VF5ZeDsLBCwfy0JiquG4OK6gsRjaIS66+yg= gitlab.com/elixxir/crypto v0.0.0-20200804182833-984246dea2c4 h1:28ftZDeYEko7xptCZzeFWS1Iam95dj46TWFVVlKmw6A= gitlab.com/elixxir/crypto v0.0.0-20200804182833-984246dea2c4/go.mod h1:ucm9SFKJo+K0N2GwRRpaNr+tKXMIOVWzmyUD0SbOu2c= gitlab.com/elixxir/crypto v0.0.3 h1:znCt/x2bL4y8czTPaaFkwzdgSgW3BJc/1+dxyf1jqVw= @@ -276,6 +278,8 @@ gitlab.com/elixxir/primitives v0.0.3-0.20210210215643-bf48247248e5 h1:ExAOci0J5i gitlab.com/elixxir/primitives v0.0.3-0.20210210215643-bf48247248e5/go.mod h1:Cz0fCtgUKnVdo2rJgiJ/h3N8a2SPW8tP9tn6cV/+t1s= gitlab.com/elixxir/primitives v0.0.3-0.20210216174458-2a23825c1eb1 h1:BfcaQtKgIbafExdHkeKIJ5XEGe9MvUiv+yg9u7jwqhY= gitlab.com/elixxir/primitives v0.0.3-0.20210216174458-2a23825c1eb1/go.mod h1:Wpz7WGZ/CpO6oHNmVTgTNBETTRXi40arWjom1uwu/1s= +gitlab.com/elixxir/primitives v0.0.3-0.20210223180234-8e5d82635c20 h1:76cC9BusM1hozdeEIosvfTXm/bYa/IVEY8Z9BvCrxq8= +gitlab.com/elixxir/primitives v0.0.3-0.20210223180234-8e5d82635c20/go.mod h1:Wpz7WGZ/CpO6oHNmVTgTNBETTRXi40arWjom1uwu/1s= gitlab.com/xx_network/comms v0.0.0-20200805174823-841427dd5023/go.mod h1:owEcxTRl7gsoM8c3RQ5KAm5GstxrJp5tn+6JfQ4z5Hw= gitlab.com/xx_network/comms v0.0.4-0.20210210215624-622913c0a215 h1:f+cobRegYJH2x6cFkf1RfJEGFnX/vq2hGLltFC+g4Bk= gitlab.com/xx_network/comms v0.0.4-0.20210210215624-622913c0a215/go.mod h1:P81n1Rv0so+uIWGkGDEUt/bEvpksM6yfB0iB22rbFx4= diff --git a/network/follow.go b/network/follow.go index 9bdfbc85969cb8bff8d60ea74848875def5c21dd..2300f06befcbb7315874b9ac10735722038c45d5 100644 --- a/network/follow.go +++ b/network/follow.go @@ -37,6 +37,8 @@ import ( "time" ) +const debugTrackPeriod = 1*time.Minute + //comms interface makes testing easier type followNetworkComms interface { GetHost(hostId *id.ID) (*connect.Host, bool) @@ -47,6 +49,7 @@ type followNetworkComms interface { // round status, and informs the client when messages can be retrieved. func (m *manager) followNetwork(quitCh <-chan struct{}) { ticker := time.NewTicker(m.param.TrackNetworkPeriod) + TrackTicker := time.NewTicker(debugTrackPeriod) rng := m.Rng.GetStream() done := false @@ -57,6 +60,9 @@ func (m *manager) followNetwork(quitCh <-chan struct{}) { done = true case <-ticker.C: m.follow(rng, m.Comms) + case <- TrackTicker.C: + jww.INFO.Println(m.tracker.Report()) + m.tracker = newPollTracker() } } } @@ -66,8 +72,6 @@ var followCnt = 0 // executes each iteration of the follower func (m *manager) follow(rng csprng.Source, comms followNetworkComms) { - jww.TRACE.Printf("follow: %d", followCnt) - followCnt++ //get the identity we will poll for identity, err := m.Session.Reception().GetIdentity(rng) @@ -76,6 +80,8 @@ func (m *manager) follow(rng csprng.Source, comms followNetworkComms) { "impossible: %+v", err) } + m.tracker.Track(identity.EphId, identity.Source) + //randomly select a gateway to poll //TODO: make this more intelligent gwHost, err := gateway.Get(m.Instance.GetPartialNdf().Get(), comms, rng) @@ -94,7 +100,7 @@ func (m *manager) follow(rng csprng.Source, comms followNetworkComms) { StartTimestamp: identity.StartRequest.UnixNano(), EndTimestamp: identity.EndRequest.UnixNano(), } - jww.DEBUG.Printf("Executing poll for %v(%s) range: %s-%s(%s) from %s", + jww.TRACE.Printf("Executing poll for %v(%s) range: %s-%s(%s) from %s", identity.EphId.Int64(), identity.Source, identity.StartRequest, identity.EndRequest, identity.EndRequest.Sub(identity.StartRequest), gwHost.GetId()) @@ -196,8 +202,6 @@ func (m *manager) follow(rng csprng.Source, comms followNetworkComms) { //get the range fo filters which are valid for the identity filtersStart, filtersEnd, outOfBounds := rounds.ValidFilterRange(identity, pollResp.Filters) - jww.INFO.Printf("filtersStart (%d), filtersEnd(%d), oob %v", filtersStart, filtersEnd, outOfBounds) - //check if there are any valid filters returned if outOfBounds { return @@ -220,9 +224,6 @@ func (m *manager) follow(rng csprng.Source, comms followNetworkComms) { } } - jww.INFO.Printf("Bloom filters found in response: %d, num filters used: %d", - len(pollResp.Filters.Filters), len(filterList)) - // check rounds using the round checker function which determines if there // are messages waiting in rounds and then sends signals to the appropriate // handling threads @@ -233,9 +234,6 @@ func (m *manager) follow(rng csprng.Source, comms followNetworkComms) { // get the bit vector of rounds that have been checked checkedRounds := m.Session.GetCheckedRounds() - jww.TRACE.Printf("gwRoundState: %+v", gwRoundsState) - jww.TRACE.Printf("pollResp.KnownRounds: %s", string(pollResp.KnownRounds)) - // loop through all rounds the client does not know about and the gateway // does, checking the bloom filter for the user to see if there are // messages for the user (bloom not implemented yet) diff --git a/network/health/tracker.go b/network/health/tracker.go index d1cac14eaeaa88e026add438ae9aeec2a27b7071..8e9837165a33982f6dcf7387e7c42388b4c276bd 100644 --- a/network/health/tracker.go +++ b/network/health/tracker.go @@ -138,7 +138,6 @@ func (t *Tracker) start(quitCh <-chan struct{}) { // Handle thread kill break case heartbeat = <-t.heartbeat: - jww.DEBUG.Printf("heartbeat: %v", heartbeat) if healthy(heartbeat) { // Stop and reset timer if !timer.Stop() { diff --git a/network/manager.go b/network/manager.go index 5839b66c458599b8573928d9bdd6d433163ea6c6..b2d43c8e6ab50465a1f66fc035b5330ad3eec450 100644 --- a/network/manager.go +++ b/network/manager.go @@ -47,6 +47,9 @@ type manager struct { message *message.Manager //atomic denotes if the network is running running *uint32 + + //map of polls for debugging + tracker *pollTracker } // NewManager builds a new reception manager object using inputted key fields @@ -72,6 +75,7 @@ func NewManager(session *storage.Session, switchboard *switchboard.Switchboard, m := manager{ param: params, running: &running, + tracker: newPollTracker(), } m.Internal = internal.Internal{ diff --git a/network/message/sendCmix.go b/network/message/sendCmix.go index 7330d119035b7b0ab521939e2cab73aee62ce59c..7ae7dd5f6686d5b3addb22ac7e49ba28efb2868f 100644 --- a/network/message/sendCmix.go +++ b/network/message/sendCmix.go @@ -55,15 +55,26 @@ func sendCmixHelper(msg format.Message, recipient *id.ID, param params.CMIX, ins timeStart := time.Now() attempted := set.New() + jww.INFO.Printf("Looking for round to send cMix message to %s " + + "(msgDigest: %s)", recipient, msg.Digest()) + for numRoundTries := uint(0); numRoundTries < param.RoundTries; numRoundTries++ { elapsed := time.Now().Sub(timeStart) - jww.DEBUG.Printf("SendCMIX Send Attempt %d", numRoundTries+1) if elapsed > param.Timeout { + jww.INFO.Printf("No rounds to send to %s (msgDigest: %s) " + + "were found before timeout %s", recipient, msg.Digest(), + 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, recipient, + msg.Digest()) + } + + remainingTime := param.Timeout - elapsed - jww.TRACE.Printf("SendCMIX GetUpcomingRealtime") //find the best round to send to, excluding attempted rounds bestRound, _ := instance.GetWaitingRounds().GetUpcomingRealtime(remainingTime, attempted) if bestRound == nil { @@ -75,10 +86,14 @@ func sendCmixHelper(msg format.Message, recipient *id.ID, param params.CMIX, ins roundCutoffTime.Add(sendTimeBuffer) now := time.Now() + jww.DEBUG.Printf("Found round %d to send to %s (msgDigest: %s)", + bestRound.ID, recipient, msg.Digest()) + if now.After(roundCutoffTime) { - jww.WARN.Printf("Round %d received which has already started"+ - " realtime: \n\t started: %s \n\t now: %s", bestRound.ID, - roundCutoffTime, now) + jww.WARN.Printf("Round %d for sending to %s (msgDigest: %s) " + + "received which has already started realtime: \n\t started: " + + "%s \n\t now: %s", bestRound.ID, recipient, msg.Digest(), + roundCutoffTime, now) attempted.Insert(bestRound) continue } @@ -91,9 +106,6 @@ func sendCmixHelper(msg format.Message, recipient *id.ID, param params.CMIX, ins jww.FATAL.Panicf("Failed to generate ephemeral ID: %+v", err) } - jww.INFO.Printf("Sending to EphID %v (source: %s) in round %d", - ephID.Int64(), recipient, bestRound.ID) - stream := rng.GetStream() ephIdFilled, err := ephID.Fill(uint(bestRound.AddressSpaceSize), stream) if err != nil { @@ -119,7 +131,6 @@ func sendCmixHelper(msg format.Message, recipient *id.ID, param params.CMIX, ins continue } topology := connect.NewCircuit(idList) - jww.TRACE.Printf("SendCMIX GetRoundKeys") //get they keys for the round, reject if any nodes do not have //keying relationships roundKeys, missingKeys := session.Cmix().GetRoundKeys(topology) @@ -174,8 +185,11 @@ func sendCmixHelper(msg format.Message, recipient *id.ID, param params.CMIX, ins //add the round on to the list of attempted so it is not tried again attempted.Insert(bestRound) - jww.DEBUG.Printf("SendCMIX SendPutMessage") - //Send the payload + jww.INFO.Printf("Sending to EphID %d (%s) on round %d, " + + "(msgDigest: %s, ecrMsgDigest: %s) via gateway %s", + ephID.Int64(), recipient, bestRound.ID, msg.Digest(), + encMsg.Digest(), transmitGateway.GetId()) + // //Send the payload gwSlotResp, err := comms.SendPutMessage(transmitGateway, wrappedMsg) //if the comm errors or the message fails to send, continue retrying. //return if it sends properly @@ -186,15 +200,21 @@ func sendCmixHelper(msg format.Message, recipient *id.ID, param params.CMIX, ins err) continue } - jww.ERROR.Printf("Failed to send message to %s: %s", - transmitGateway, err) + jww.ERROR.Printf("Failed to send to EphID %d (%s) on " + + "round %d: %+v", ephID.Int64(), recipient, bestRound.ID, err) + return 0, ephemeral.Id{}, errors.WithMessage(err, "Failed to put cmix message") } else if gwSlotResp.Accepted { jww.INFO.Printf("Sucesfully sent to EphID %v (source: %s) " + "in round %d", ephID.Int64(), recipient, bestRound.ID) return id.Round(bestRound.ID), ephID, nil + } else{ + jww.FATAL.Panicf("Gateway %s returned no error, but failed " + + "to accept message when sending to EphID %d (%s) on round %d", + transmitGateway.GetId(), ephID.Int64(), recipient, bestRound.ID) } } - return 0, ephemeral.Id{}, errors.New("failed to send the message") + return 0, ephemeral.Id{}, errors.New("failed to send the message, " + + "unknown error") } // Signals to the node registration thread to register a node if keys are diff --git a/network/message/sendE2E.go b/network/message/sendE2E.go index 0cee2bdc10536b33505ffc7ddffa09ac8f66de49..15be25b2288d0bf16f77f59b15173c3b351e732b 100644 --- a/network/message/sendE2E.go +++ b/network/message/sendE2E.go @@ -17,6 +17,7 @@ import ( "gitlab.com/xx_network/primitives/id" "sync" "time" + jww "github.com/spf13/jwalterweatherman" ) func (m *Manager) SendE2E(msg message.Send, param params.E2E) ([]id.Round, e2e.MessageID, error) { @@ -47,6 +48,10 @@ func (m *Manager) SendE2E(msg message.Send, param params.E2E) ([]id.Round, e2e.M wg := sync.WaitGroup{} + jww.INFO.Printf("E2E sending %d messages to %s", + len(partitions), msg.Recipient) + + for i, p := range partitions { //create the cmix message msgCmix := format.NewMessage(m.Session.Cmix().GetGroup().GetP().ByteLen()) @@ -62,6 +67,9 @@ func (m *Manager) SendE2E(msg message.Send, param params.E2E) ([]id.Round, e2e.M //end to end encrypt the cmix message msgEnc := key.Encrypt(msgCmix) + jww.INFO.Printf("E2E sending %d/%d to %s with msgDigest: %s", + i+i, len(partitions), msg.Recipient, msgEnc.Digest()) + //send the cmix message, each partition in its own thread wg.Add(1) go func(i int) { @@ -84,8 +92,13 @@ func (m *Manager) SendE2E(msg message.Send, param params.E2E) ([]id.Round, e2e.M //see if any parts failed to send numFail, errRtn := getSendErrors(errCh) if numFail > 0 { + jww.INFO.Printf("Failed to E2E send %d/%d to %s", + numFail, len(partitions), msg.Recipient) return nil, e2e.MessageID{}, errors.Errorf("Failed to E2E send %v/%v sub payloads:"+ " %s", numFail, len(partitions), errRtn) + }else{ + jww.INFO.Printf("Sucesfully E2E sent %d/%d to %s", + numFail, len(partitions), msg.Recipient) } //return the rounds if everything send successfully diff --git a/network/message/sendUnsafe.go b/network/message/sendUnsafe.go index 0a0b588553d6cbfdcbf17f0b30a079e8ac40d455..404e5af74e37972b909e92d31f309183179f7c4f 100644 --- a/network/message/sendUnsafe.go +++ b/network/message/sendUnsafe.go @@ -8,6 +8,7 @@ package message import ( "github.com/pkg/errors" + jww "github.com/spf13/jwalterweatherman" "gitlab.com/elixxir/client/interfaces/message" "gitlab.com/elixxir/client/interfaces/params" "gitlab.com/elixxir/crypto/e2e" @@ -48,11 +49,19 @@ func (m *Manager) SendUnsafe(msg message.Send, param params.Unsafe) ([]id.Round, wg := sync.WaitGroup{} + jww.INFO.Printf("Unsafe sending %d messages to %s", + len(partitions), msg.Recipient) + + for i, p := range partitions { myID := m.Session.User().GetCryptographicIdentity() msgCmix := format.NewMessage(m.Session.Cmix().GetGroup().GetP().ByteLen()) msgCmix.SetContents(p) e2e.SetUnencrypted(msgCmix, myID.GetReceptionID()) + + jww.INFO.Printf("Unsafe sending %d/%d to %s with msgDigest: %s", + i+i, len(partitions), msg.Recipient, msgCmix.Digest()) + wg.Add(1) go func(i int) { var err error @@ -69,8 +78,13 @@ func (m *Manager) SendUnsafe(msg message.Send, param params.Unsafe) ([]id.Round, //see if any parts failed to send numFail, errRtn := getSendErrors(errCh) if numFail > 0 { + jww.INFO.Printf("Failed to Unsafe send %d/%d to %s", + numFail, len(partitions), msg.Recipient) return nil, errors.Errorf("Failed to send %v/%v sub payloads:"+ " %s", numFail, len(partitions), errRtn) + }else{ + jww.INFO.Printf("Sucesfully Unsafe sent %d/%d to %s", + numFail, len(partitions), msg.Recipient) } //return the rounds if everything send successfully diff --git a/network/polltracker.go b/network/polltracker.go new file mode 100644 index 0000000000000000000000000000000000000000..7653ac3400f840890456df7e9f8ce91c5f37abbe --- /dev/null +++ b/network/polltracker.go @@ -0,0 +1,46 @@ +package network + +import ( + "fmt" + "gitlab.com/xx_network/primitives/id" + "gitlab.com/xx_network/primitives/id/ephemeral" +) + +type pollTracker map[id.ID]map[int64]uint + +func newPollTracker()*pollTracker{ + pt := make(pollTracker) + return &pt +} + +//tracks a single poll +func (pt *pollTracker)Track(ephID ephemeral.Id, source *id.ID){ + if _, exists := (*pt)[*source]; !exists{ + (*pt)[*source] = make(map[int64]uint) + (*pt)[*source][ephID.Int64()] = 0 + }else if _, exists := (*pt)[*source][ephID.Int64()]; !exists{ + (*pt)[*source][ephID.Int64()] = 0 + }else{ + (*pt)[*source][ephID.Int64()] = (*pt)[*source][ephID.Int64()] + 1 + } +} + +//reports all resent polls +func (pt *pollTracker)Report()string{ + report := "" + numReports := uint(0) + + for source := range *pt{ + numSubReports := uint(0) + subReport := "" + for ephID, reports := range (*pt)[source]{ + numSubReports += reports + subReport += fmt.Sprintf("\n\t\tEphID %d polled %d times", ephID, reports) + } + subReport = fmt.Sprintf("\n\tID %s polled %d times", &source, numSubReports) + numReports += numSubReports + } + + return fmt.Sprintf("\nPolled the network %d times", numReports) + report +} + diff --git a/network/rounds/check.go b/network/rounds/check.go index 138c754e55643e742dd8174ab5ca24fef4630719..7053d98ea4f8097d299218e7f2dac95dfbe5c6d0 100644 --- a/network/rounds/check.go +++ b/network/rounds/check.go @@ -26,18 +26,18 @@ import ( // sent to Message Retrieval Workers, otherwise it is sent to Historical Round // Retrieval func (m *Manager) Checker(roundID id.Round, filters []*RemoteFilter, identity reception.IdentityUse) bool { - jww.DEBUG.Printf("Checker(roundID: %d)", roundID) // Set round to processing, if we can - processing, count := m.p.Process(roundID) - if !processing { + notProcessing, count := m.p.Process(roundID) + if !notProcessing { // if is already processing, ignore return false } //if the number of times the round has been checked has hit the max, drop it if count == m.params.MaxAttemptsCheckingARound { - jww.ERROR.Printf("Looking up Round %v failed the maximum number "+ - "of times (%v), stopping retrval attempt", roundID, + jww.ERROR.Printf("Looking up Round %v for %d (%s) failed " + + "the maximum number of times (%v), stopping retrval attempt", + roundID, identity.EphId, identity.Source, m.params.MaxAttemptsCheckingARound) m.p.Done(roundID) return true @@ -47,7 +47,8 @@ func (m *Manager) Checker(roundID id.Round, filters []*RemoteFilter, identity re //find filters that could have the round and check them serialRid := serializeRound(roundID) for _, filter := range filters { - if filter != nil && filter.FirstRound() <= roundID && filter.LastRound() >= roundID { + if filter != nil && filter.FirstRound() <= roundID && + filter.LastRound() >= roundID { if filter.GetFilter().Test(serialRid) { hasRound = true break @@ -58,8 +59,8 @@ func (m *Manager) Checker(roundID id.Round, filters []*RemoteFilter, identity re //if it is not present, set the round as checked //that means no messages are available for the user in the round if !hasRound { - jww.DEBUG.Printf("No messages found for round %d, " + - "will not check again", roundID) + jww.DEBUG.Printf("No messages found for %d (%s) in round %d, " + + "will not check again", identity.EphId, identity.Source, roundID) m.p.Done(roundID) return true } @@ -71,14 +72,18 @@ func (m *Manager) Checker(roundID id.Round, filters []*RemoteFilter, identity re jww.WARN.Printf("Forcing use of historical rounds for round ID %d.", roundID) } - jww.DEBUG.Printf("HistoricalRound <- %d", roundID) + jww.INFO.Printf("Messages found in round %d for %d (%s), looking " + + "up messages via historical lookup", roundID, identity.EphId, + identity.Source) // If we didn't find it, send to Historical Rounds Retrieval m.historicalRounds <- historicalRoundRequest{ rid: roundID, identity: identity, } } else { - jww.DEBUG.Printf("lookupRoundMessages <- %d", roundID) + jww.INFO.Printf("Messages found in round %d for %d (%s), looking " + + "up messages via in ram lookup", roundID, identity.EphId, + identity.Source) // If found, send to Message Retrieval Workers m.lookupRoundMessages <- roundLookup{ roundInfo: ri, diff --git a/storage/cmix/roundKeys.go b/storage/cmix/roundKeys.go index 825c1ccfe645472b1769f084d18dacc5d69777bc..c8bf12b5eb8c70565f56250d6bf2ce817b717c96 100644 --- a/storage/cmix/roundKeys.go +++ b/storage/cmix/roundKeys.go @@ -34,7 +34,7 @@ func (rk *RoundKeys) Encrypt(msg format.Message, keys := make([]*cyclic.Int, len(rk.keys)) for i, k := range rk.keys { - jww.INFO.Printf("CMIXKEY: num: %d, key: %s", i, k.Get().Text(16)) + jww.TRACE.Printf("CMIXKEY: num: %d, key: %s", i, k.Get().Text(16)) keys[i] = k.Get() }