Clean up logging and fix the track results call, which was confusing the...

Clean up logging and fix the track results call, which was confusing the number of failed rounds with the number of timeouts

keyExchange/confirm.go

@@ -34,7 +34,8 @@ func startConfirm(sess *storage.Session, c chan message.Receive,
 func handleConfirm(sess *storage.Session, confirmation message.Receive) {
 	//ensure the message was encrypted properly
 	if confirmation.Encryption != message.E2E {
-		jww.ERROR.Printf("Received non-e2e encrypted Key Exchange "+
+		jww.ERROR.Printf(
+			"[REKEY] Received non-e2e encrypted Key Exchange "+
 			"confirm from partner %s", confirmation.Sender)
 		return
 	}
@@ -42,7 +43,8 @@ func handleConfirm(sess *storage.Session, confirmation message.Receive) {
 	//Get the partner
 	partner, err := sess.E2e().GetPartner(confirmation.Sender)
 	if err != nil {
-		jww.ERROR.Printf("Received Key Exchange Confirmation with unknown "+
+		jww.ERROR.Printf(
+			"[REKEY] Received Key Exchange Confirmation with unknown "+
 			"partner %s", confirmation.Sender)
 		return
 	}
@@ -50,7 +52,7 @@ func handleConfirm(sess *storage.Session, confirmation message.Receive) {
 	//unmarshal the payload
 	confimedSessionID, err := unmarshalConfirm(confirmation.Payload)
 	if err != nil {
-		jww.ERROR.Printf("Failed to unmarshal Key Exchange Trigger with "+
+		jww.ERROR.Printf("[REKEY] Failed to unmarshal Key Exchange Trigger with "+
 			"partner %s: %s", confirmation.Sender, err)
 		return
 	}
@@ -58,7 +60,7 @@ func handleConfirm(sess *storage.Session, confirmation message.Receive) {
 	//get the confirmed session
 	confirmedSession := partner.GetSendSession(confimedSessionID)
 	if confirmedSession == nil {
-		jww.ERROR.Printf("Failed to find confirmed session %s from "+
+		jww.ERROR.Printf("[REKEY] Failed to find confirmed session %s from "+
 			"partner %s: %s", confimedSessionID, confirmation.Sender, err)
 		return
 	}
@@ -68,11 +70,14 @@ func handleConfirm(sess *storage.Session, confirmation message.Receive) {
 	// sends. For example if the sending device runs out of battery after it
 	// sends but before it records the send it will resend on reload
 	if err := confirmedSession.TrySetNegotiationStatus(e2e.Confirmed); err != nil {
-		jww.WARN.Printf("Failed to set the negotiation status for the "+
+		jww.WARN.Printf("[REKEY] Failed to set the negotiation status for the "+
 			"confirmation of session %s from partner %s. This is expected in "+
 			"some edge cases but could be a sign of an issue if it percists: %s",
 			confirmedSession, partner.GetPartnerID(), err)
 	}
+
+	jww.DEBUG.Printf("[REKEY] handled confirmation for session " +
+		"%s from partner %s.", confirmedSession, partner.GetPartnerID())
 }
 
 func unmarshalConfirm(payload []byte) (e2e.SessionID, error) {

keyExchange/rekey.go

@@ -43,7 +43,7 @@ func trigger(instance *network.Instance, sendE2E interfaces.SendE2E,
 	sess *storage.Session, manager *e2e.Manager, session *e2e.Session,
 	sendTimeout time.Duration, stop *stoppable.Single) {
 	var negotiatingSession *e2e.Session
-	jww.INFO.Printf("Negotation triggered for session %s with "+
+	jww.INFO.Printf("[REKEY] Negotiation triggered for session %s with "+
 		"status: %s", session, session.NegotiationStatus())
 	switch session.NegotiationStatus() {
 	// If the passed session is triggering a negotiation on a new session to
@@ -55,11 +55,11 @@ func trigger(instance *network.Instance, sendE2E interfaces.SendE2E,
 		//move the state of the triggering session forward
 		session.SetNegotiationStatus(e2e.NewSessionCreated)
 
-	// If the session is set to send a negotation
+	// If the session is set to send a negotiation
 	case e2e.Sending:
 		negotiatingSession = session
 	default:
-		jww.FATAL.Panicf("Session %s provided invalid e2e "+
+		jww.FATAL.Panicf("[REKEY] Session %s provided invalid e2e "+
 			"negotiating status: %s", session, session.NegotiationStatus())
 	}
 
@@ -70,7 +70,7 @@ func trigger(instance *network.Instance, sendE2E interfaces.SendE2E,
 	// if sending the negotiation fails, revert the state of the session to
 	// unconfirmed so it will be triggered in the future
 	if err != nil {
-		jww.ERROR.Printf("Failed to do Key Negotiation with "+
+		jww.ERROR.Printf("[REKEY] Failed to do Key Negotiation with "+
 			"session %s: %s", session, err)
 	}
 }
@@ -100,8 +100,8 @@ func negotiate(instance *network.Instance, sendE2E interfaces.SendE2E,
 
 	//If the payload cannot be marshaled, panic
 	if err != nil {
-		jww.FATAL.Printf("Failed to marshal payload for Key "+
-			"Negotation Trigger with %s", session.GetPartner())
+		jww.FATAL.Printf("[REKEY] Failed to marshal payload for Key "+
+			"Negotiation Trigger with %s", session.GetPartner())
 	}
 
 	//send session
@@ -121,7 +121,8 @@ func negotiate(instance *network.Instance, sendE2E interfaces.SendE2E,
 	// should ensure the calling session is in a state where the Rekey will
 	// be triggered next time a key is used
 	if err != nil {
-		return errors.Errorf("Failed to send the key negotation message "+
+		return errors.Errorf(
+			"[REKEY] Failed to send the key negotiation message "+
 			"for %s: %s", session, err)
 	}
 
@@ -136,14 +137,15 @@ func negotiate(instance *network.Instance, sendE2E interfaces.SendE2E,
 	}
 
 	//Wait until the result tracking responds
-	success, numTimeOut, numRoundFail := utility.TrackResults(sendResults, len(rounds))
+	success, numRoundFail, numTimeOut := utility.TrackResults(sendResults,
+		len(rounds))
 
 	// If a single partition of the Key Negotiation request does not
 	// transmit, the partner cannot read the result. Log the error and set
 	// the session as unconfirmed so it will re-trigger the negotiation
 	if !success {
 		session.SetNegotiationStatus(e2e.Unconfirmed)
-		return errors.Errorf("Key Negotiation for %s failed to "+
+		return errors.Errorf("[REKEY] Key Negotiation rekey for %s failed to "+
 			"transmit %v/%v paritions: %v round failures, %v timeouts",
 			session, numRoundFail+numTimeOut, len(rounds), numRoundFail,
 			numTimeOut)
@@ -151,7 +153,7 @@ func negotiate(instance *network.Instance, sendE2E interfaces.SendE2E,
 
 	// otherwise, the transmission is a success and this should be denoted
 	// in the session and the log
-	jww.INFO.Printf("Key Negotiation transmission for %s successful",
+	jww.INFO.Printf("[REKEY] Key Negotiation rekey transmission for %s successful",
 		session)
 	session.SetNegotiationStatus(e2e.Sent)
 

keyExchange/trigger.go

@@ -72,7 +72,7 @@ func handleTrigger(sess *storage.Session, net interfaces.NetworkManager,
 	oldSessionID, PartnerPublicKey, PartnerSIDHPublicKey, err := (
 		unmarshalSource(sess.E2e().GetGroup(), request.Payload))
 	if err != nil {
-		jww.ERROR.Printf("could not unmarshal partner %s: %s",
+		jww.ERROR.Printf("[REKEY] could not unmarshal partner %s: %s",
 			request.Sender, err)
 		return err
 	}
@@ -80,7 +80,7 @@ func handleTrigger(sess *storage.Session, net interfaces.NetworkManager,
 	//get the old session which triggered the exchange
 	oldSession := partner.GetSendSession(oldSessionID)
 	if oldSession == nil {
-		err := errors.Errorf("no session %s for partner %s: %s",
+		err := errors.Errorf("[REKEY] no session %s for partner %s: %s",
 			oldSession, request.Sender, err)
 		jww.ERROR.Printf(err.Error())
 		return err
@@ -95,7 +95,7 @@ func handleTrigger(sess *storage.Session, net interfaces.NetworkManager,
 	// creation in this case ignores the new session, but the confirmation
 	// message is still sent so the partner will know the session is confirmed
 	if duplicate {
-		jww.INFO.Printf("New session from Key Exchange Trigger to "+
+		jww.INFO.Printf("[REKEY] New session from Key Exchange Trigger to "+
 			"create session %s for partner %s is a duplicate, request ignored",
 			session.GetID(), request.Sender)
 	} else {
@@ -112,7 +112,7 @@ func handleTrigger(sess *storage.Session, net interfaces.NetworkManager,
 
 	//If the payload cannot be marshaled, panic
 	if err != nil {
-		jww.FATAL.Panicf("Failed to marshal payload for Key "+
+		jww.FATAL.Panicf("[REKEY] Failed to marshal payload for Key "+
 			"Negotation Confirmation with %s", session.GetPartner())
 	}
 
@@ -145,12 +145,12 @@ func handleTrigger(sess *storage.Session, net interfaces.NetworkManager,
 	}
 
 	//Wait until the result tracking responds
-	success, numTimeOut, numRoundFail := utility.TrackResults(sendResults, len(rounds))
+	success, numRoundFail, numTimeOut := utility.TrackResults(sendResults, len(rounds))
 	// If a single partition of the Key Negotiation request does not
 	// transmit, the partner will not be able to read the confirmation. If
 	// such a failure occurs
 	if !success {
-		jww.ERROR.Printf("Key Negotiation for %s failed to "+
+		jww.ERROR.Printf("[REKEY] Key Negotiation trigger for %s failed to "+
 			"transmit %v/%v paritions: %v round failures, %v timeouts",
 			session, numRoundFail+numTimeOut, len(rounds), numRoundFail,
 			numTimeOut)
@@ -161,7 +161,7 @@ func handleTrigger(sess *storage.Session, net interfaces.NetworkManager,
 	// otherwise, the transmission is a success and this should be denoted
 	// in the session and the log
 	sess.GetCriticalMessages().Succeeded(m, e2eParams)
-	jww.INFO.Printf("Key Negotiation transmission for %s successfully",
+	jww.INFO.Printf("[REKEY] Key Negotiation trigger transmission for %s successfully",
 		session)
 
 	return nil