diff --git a/keyExchange/rekey.go b/keyExchange/rekey.go
index 55434ea3e14ebf0ba456af32a30d8a2f18cb5e20..2878ef719651c6091b275f5e28350c66e642ef19 100644
--- a/keyExchange/rekey.go
+++ b/keyExchange/rekey.go
@@ -116,7 +116,7 @@ func negotiate(instance *network.Instance, sendE2E interfaces.SendE2E,
e2eParams.Type = params.KeyExchange
e2eParams.IdentityPreimage = rekeyPreimage
- rounds, _, _, err := sendE2E(m, e2eParams, stop)
+ rounds, msgID, _, err := sendE2E(m, e2eParams, stop)
// If the send fails, returns the error so it can be handled. The caller
// should ensure the calling session is in a state where the Rekey will
// be triggered next time a key is used
@@ -146,15 +146,15 @@ func negotiate(instance *network.Instance, sendE2E interfaces.SendE2E,
if !success {
session.SetNegotiationStatus(e2e.Unconfirmed)
return errors.Errorf("[REKEY] Key Negotiation rekey for %s failed to "+
- "transmit %v/%v paritions: %v round failures, %v timeouts",
+ "transmit %v/%v paritions: %v round failures, %v timeouts, msgID: %s",
session, numRoundFail+numTimeOut, len(rounds), numRoundFail,
- numTimeOut)
+ numTimeOut, msgID)
}
// otherwise, the transmission is a success and this should be denoted
// in the session and the log
- jww.INFO.Printf("[REKEY] Key Negotiation rekey transmission for %s successful",
- session)
+ jww.INFO.Printf("[REKEY] Key Negotiation rekey transmission for %s, msgID %s successful",
+ session, msgID)
session.SetNegotiationStatus(e2e.Sent)
return nil
diff --git a/keyExchange/trigger.go b/keyExchange/trigger.go
index e88a3a5d0850ae0eeb21a86fc4699fd01a089af1..4e4fc6fa2b753a0a8961a28da244ab5054b093de 100644
--- a/keyExchange/trigger.go
+++ b/keyExchange/trigger.go
@@ -131,7 +131,7 @@ func handleTrigger(sess *storage.Session, net interfaces.NetworkManager,
// send fails
sess.GetCriticalMessages().AddProcessing(m, e2eParams)
- rounds, _, _, err := net.SendE2E(m, e2eParams, stop)
+ rounds, msgID, _, err := net.SendE2E(m, e2eParams, stop)
if err != nil {
return err
}
@@ -145,15 +145,16 @@ func handleTrigger(sess *storage.Session, net interfaces.NetworkManager,
}
//Wait until the result tracking responds
- success, numRoundFail, numTimeOut := 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("[REKEY] Key Negotiation trigger for %s failed to "+
- "transmit %v/%v paritions: %v round failures, %v timeouts",
+ "transmit %v/%v paritions: %v round failures, %v timeouts, msgID: %s",
session, numRoundFail+numTimeOut, len(rounds), numRoundFail,
- numTimeOut)
+ numTimeOut, msgID)
sess.GetCriticalMessages().Failed(m, e2eParams)
return nil
}
@@ -161,8 +162,8 @@ 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("[REKEY] Key Negotiation trigger transmission for %s successfully",
- session)
+ jww.INFO.Printf("[REKEY] Key Negotiation trigger transmission for %s, msgID: %s successfully",
+ session, msgID)
return nil
}
diff --git a/network/message/garbled.go b/network/message/garbled.go
index 54ca39fa456095b45ba30a1cd63f7f71bdc40db3..9388f4dcfb2c42f3f9c106cc949c893207451ced 100644
--- a/network/message/garbled.go
+++ b/network/message/garbled.go
@@ -60,6 +60,8 @@ func (m *Manager) handleGarbledMessages() {
fingerprint := grbldMsg.GetKeyFP()
// Check if the key is there, process it if it is
if key, isE2E := e2eKv.PopKey(fingerprint); isE2E {
+ jww.INFO.Printf("[GARBLE] Check E2E for %s, KEYFP: %s",
+ grbldMsg.Digest(), grbldMsg.GetKeyFP())
// Decrypt encrypted message
msg, err := key.Decrypt(grbldMsg)
if err == nil {
@@ -68,7 +70,7 @@ func (m *Manager) handleGarbledMessages() {
//remove from the buffer if decryption is successful
garbledMsgs.Remove(grbldMsg)
- jww.INFO.Printf("Garbled message decoded as E2E from "+
+ jww.INFO.Printf("[GARBLE] message decoded as E2E from "+
"%s, msgDigest: %s", sender, grbldMsg.Digest())
//handle the successfully decrypted message
@@ -107,7 +109,7 @@ func (m *Manager) handleGarbledMessages() {
RoundId: 0,
RoundTimestamp: time.Time{},
}
- im := fmt.Sprintf("Garbled/RAW Message reprecessed: keyFP: %v, "+
+ im := fmt.Sprintf("[GARBLE] RAW Message reprecessed: keyFP: %v, "+
"msgDigest: %s", grbldMsg.GetKeyFP(), grbldMsg.Digest())
jww.INFO.Print(im)
m.Internal.Events.Report(1, "MessageReception", "Garbled", im)
diff --git a/network/message/handler.go b/network/message/handler.go
index 838be7875a696a15f3074aee5fae07ce3b1f0679..ecced449eb9f1077311dd26aac3c90851b32c4ac 100644
--- a/network/message/handler.go
+++ b/network/message/handler.go
@@ -127,7 +127,8 @@ func (m *Manager) handleMessage(ecrMsg format.Message, bundle Bundle, edge *edge
}
im := fmt.Sprintf("Received message of type %s from %s in round %d,"+
- " msgDigest: %s", encTy, sender, bundle.Round, msgDigest)
+ " msgDigest: %s, keyFP: %v", encTy, sender, bundle.Round,
+ msgDigest, msg.GetKeyFP())
jww.INFO.Print(im)
m.Internal.Events.Report(2, "MessageReception", "MessagePart", im)
@@ -145,7 +146,7 @@ func (m *Manager) handleMessage(ecrMsg format.Message, bundle Bundle, edge *edge
xxMsg.RoundId = id.Round(bundle.RoundInfo.ID)
xxMsg.RoundTimestamp = time.Unix(0, int64(bundle.RoundInfo.Timestamps[states.QUEUED]))
if xxMsg.MessageType == message.Raw {
- rm := fmt.Sprintf("Recieved a message of type 'Raw' from %s."+
+ rm := fmt.Sprintf("Received a message of type 'Raw' from %s."+
"Message Ignored, 'Raw' is a reserved type. Message supressed.",
xxMsg.ID)
jww.WARN.Print(rm)
diff --git a/network/message/sendE2E.go b/network/message/sendE2E.go
index 52d202393cc8817f2bf9ffd8acace69fb9df72eb..5461d89da9796c4267302db3485cd2de3a9d8c35 100644
--- a/network/message/sendE2E.go
+++ b/network/message/sendE2E.go
@@ -38,6 +38,9 @@ func (m *Manager) SendE2E(msg message.Send, param params.E2E,
return nil, e2e.MessageID{}, time.Time{}, errors.WithMessage(err, "failed to send unsafe message")
}
+ jww.INFO.Printf("E2E sending %d messages to %s",
+ len(partitions), msg.Recipient)
+
//encrypt then send the partitions over cmix
roundIds := make([]id.Round, len(partitions))
errCh := make(chan error, len(partitions))
@@ -50,10 +53,10 @@ func (m *Manager) SendE2E(msg message.Send, param params.E2E,
"message, no relationship found with %s", msg.Recipient)
}
- wg := sync.WaitGroup{}
+ //return the rounds if everything send successfully
+ msgID := e2e.NewMessageID(partner.GetSendRelationshipFingerprint(), internalMsgId)
- jww.INFO.Printf("E2E sending %d messages to %s",
- len(partitions), msg.Recipient)
+ wg := sync.WaitGroup{}
for i, p := range partitions {
@@ -90,8 +93,9 @@ func (m *Manager) SendE2E(msg message.Send, param params.E2E,
//end to end encrypt the cmix message
msgEnc := key.Encrypt(msgCmix)
- jww.INFO.Printf("E2E sending %d/%d to %s with msgDigest: %s, key fp: %s",
- i+i, len(partitions), msg.Recipient, msgEnc.Digest(), key.Fingerprint())
+ jww.INFO.Printf("E2E sending %d/%d to %s with msgDigest: %s, key fp: %s, msgID: %s",
+ i+i, len(partitions), msg.Recipient, msgEnc.Digest(),
+ key.Fingerprint(), msgID)
//set the preimage to the default e2e one if it is not already set
if param.IdentityPreimage == nil {
@@ -126,6 +130,7 @@ func (m *Manager) SendE2E(msg message.Send, param params.E2E,
}
//return the rounds if everything send successfully
- msgID := e2e.NewMessageID(partner.GetSendRelationshipFingerprint(), internalMsgId)
+ jww.INFO.Printf("Successful E2E Send of %d messages to %s with msgID %s",
+ len(partitions), msg.Recipient, msgID)
return roundIds, msgID, ts, nil
}
diff --git a/storage/e2e/relationship.go b/storage/e2e/relationship.go
index b14e15bba8539ef8b85e812a04e19a3df6cf48dc..72342e54bf677c765680a492ce399fc26813477b 100644
--- a/storage/e2e/relationship.go
+++ b/storage/e2e/relationship.go
@@ -338,6 +338,7 @@ func (r *relationship) getNewestRekeyableSession() *Session {
var unconfirmed *Session
for _, s := range r.sessions {
+ jww.TRACE.Printf("[REKEY] Looking at session %s", s)
//fmt.Println(i)
// This looks like it might not be thread safe, I think it is because
// the failure mode is it skips to a lower key to rekey with, which is
@@ -345,12 +346,16 @@ func (r *relationship) getNewestRekeyableSession() *Session {
// accessing the data in the same order it would be written (i think)
if s.Status() != RekeyEmpty {
if s.IsConfirmed() {
+ jww.TRACE.Printf("[REKEY] Selected rekey: %s",
+ s)
return s
} else if unconfirmed == nil {
unconfirmed = s
}
}
}
+ jww.WARN.Printf("[REKEY] Returning unconfirmed session rekey: %s",
+ unconfirmed)
return unconfirmed
}
diff --git a/storage/e2e/session.go b/storage/e2e/session.go
index d9727c942bad0a6efdfe105330113dcce3b36970..96185b32ddea3f1991a734cee28f6291faadbe4e 100644
--- a/storage/e2e/session.go
+++ b/storage/e2e/session.go
@@ -147,8 +147,6 @@ func newSession(ship *relationship, t RelationshipType, myPrivKey, partnerPubKey
grp := session.relationship.manager.ctx.grp
myPubKey := dh.GeneratePublicKey(session.myPrivKey, grp)
- // FIXME: We really don't want to be dumping private keys to a log!
- // This should probably go inside a Session String implementation.
jww.INFO.Printf("New Session with Partner %s:\n\tType: %s"+
"\n\tBaseKey: %s\n\tRelationship Fingerprint: %v\n\tNumKeys: %d"+
"\n\tMy Public Key: %s\n\tPartner Public Key: %s" +
diff --git a/storage/e2e/store.go b/storage/e2e/store.go
index b465a176642e5ce84289ef9266b854a821cb98db..5650c1025727fc9f59b35e5d26d0e08a26359aa5 100644
--- a/storage/e2e/store.go
+++ b/storage/e2e/store.go
@@ -372,6 +372,8 @@ func (f *fingerprints) add(keys []*Key) {
for _, k := range keys {
f.toKey[k.Fingerprint()] = k
+ jww.TRACE.Printf("Added Key Fingerprint: %s",
+ k.Fingerprint())
}
}