Ratchet: Error handling fixes, log tweaks

This commit is contained in:
zzz
2020-04-30 11:29:08 +00:00
parent 4cf8bfbe0d
commit 9e233b42a5
3 changed files with 56 additions and 38 deletions

View File

@ -358,8 +358,10 @@ public final class ECIESAEADEngine {
byte xx31 = xx[KEYLEN - 1]; byte xx31 = xx[KEYLEN - 1];
PublicKey pk = Elligator2.decode(xx); PublicKey pk = Elligator2.decode(xx);
if (pk == null) { if (pk == null) {
if (_log.shouldWarn()) // very unlikely
_log.warn("Elg2 decode fail NS"); if (_log.shouldDebug())
_log.debug("Elg2 decode fail NS");
data[KEYLEN - 1] = xx31;
return null; return null;
} }
// rewrite in place, must restore below on failure // rewrite in place, must restore below on failure
@ -370,8 +372,9 @@ public final class ECIESAEADEngine {
try { try {
state.readMessage(data, 0, data.length, payload, 0); state.readMessage(data, 0, data.length, payload, 0);
} catch (GeneralSecurityException gse) { } catch (GeneralSecurityException gse) {
if (_log.shouldWarn()) { // we'll get this a lot on muxed SKM
_log.warn("Decrypt fail NS", gse); if (_log.shouldInfo()) {
_log.info("Decrypt fail NS", gse);
if (_log.shouldDebug()) if (_log.shouldDebug())
_log.debug("State at failure: " + state); _log.debug("State at failure: " + state);
} }
@ -405,6 +408,7 @@ public final class ECIESAEADEngine {
// payload // payload
if (payloadlen == 0) { if (payloadlen == 0) {
// disallowed, datetime block required
if (_log.shouldWarn()) if (_log.shouldWarn())
_log.warn("Zero length payload in NS"); _log.warn("Zero length payload in NS");
return NO_CLOVES; return NO_CLOVES;
@ -421,6 +425,7 @@ public final class ECIESAEADEngine {
} }
if (pc.datetime == 0) { if (pc.datetime == 0) {
// disallowed, datetime block required
if (_log.shouldWarn()) if (_log.shouldWarn())
_log.warn("No datetime block in IB NS"); _log.warn("No datetime block in IB NS");
return NO_CLOVES; return NO_CLOVES;
@ -431,11 +436,12 @@ public final class ECIESAEADEngine {
keyManager.createSession(bob, state, null); keyManager.createSession(bob, state, null);
if (pc.cloveSet.isEmpty()) { if (pc.cloveSet.isEmpty()) {
if (_log.shouldWarn()) // this is legal
_log.warn("No garlic block in NS payload"); if (_log.shouldDebug())
_log.debug("No garlic block in NS payload");
return NO_CLOVES;
} }
int num = pc.cloveSet.size(); int num = pc.cloveSet.size();
// return non-null even if zero cloves
GarlicClove[] arr = new GarlicClove[num]; GarlicClove[] arr = new GarlicClove[num];
// msg id and expiration not checked in GarlicMessageReceiver // msg id and expiration not checked in GarlicMessageReceiver
CloveSet rv = new CloveSet(pc.cloveSet.toArray(arr), Certificate.NULL_CERT, 0, pc.datetime); CloveSet rv = new CloveSet(pc.cloveSet.toArray(arr), Certificate.NULL_CERT, 0, pc.datetime);
@ -480,8 +486,10 @@ public final class ECIESAEADEngine {
byte yy31 = yy[KEYLEN - 1]; byte yy31 = yy[KEYLEN - 1];
PublicKey k = Elligator2.decode(yy); PublicKey k = Elligator2.decode(yy);
if (k == null) { if (k == null) {
if (_log.shouldWarn()) // very unlikely
_log.warn("Elg2 decode fail NSR"); if (_log.shouldDebug())
_log.debug("Elg2 decode fail NSR");
data[TAGLEN + KEYLEN - 1] = yy31;
return null; return null;
} }
if (_log.shouldDebug()) if (_log.shouldDebug())
@ -530,12 +538,15 @@ public final class ECIESAEADEngine {
} }
return NO_CLOVES; return NO_CLOVES;
} }
PLCallback pc;
if (payload.length == 0) { if (payload.length == 0) {
if (_log.shouldWarn()) // this is legal
_log.warn("Zero length payload in NSR"); pc = null;
return NO_CLOVES; if (_log.shouldDebug())
} _log.debug("Zero length payload in IB NSR");
PLCallback pc = new PLCallback(); } else {
pc = new PLCallback();
try { try {
int blocks = RatchetPayload.processPayload(_context, pc, payload, 0, payload.length, false); int blocks = RatchetPayload.processPayload(_context, pc, payload, 0, payload.length, false);
if (_log.shouldDebug()) if (_log.shouldDebug())
@ -545,6 +556,7 @@ public final class ECIESAEADEngine {
} catch (Exception e) { } catch (Exception e) {
throw new DataFormatException("NSR payload error", e); throw new DataFormatException("NSR payload error", e);
} }
}
byte[] bobPK = new byte[KEYLEN]; byte[] bobPK = new byte[KEYLEN];
state.getRemotePublicKey().getPublicKey(bobPK, 0); state.getRemotePublicKey().getPublicKey(bobPK, 0);
@ -561,12 +573,15 @@ public final class ECIESAEADEngine {
PublicKey bob = new PublicKey(EncType.ECIES_X25519, bobPK); PublicKey bob = new PublicKey(EncType.ECIES_X25519, bobPK);
keyManager.updateSession(bob, oldState, state, null, split); keyManager.updateSession(bob, oldState, state, null, split);
if (pc == null)
return NO_CLOVES;
if (pc.cloveSet.isEmpty()) { if (pc.cloveSet.isEmpty()) {
if (_log.shouldWarn()) // this is legal
_log.warn("No garlic block in NSR payload"); if (_log.shouldDebug())
_log.debug("No garlic block in NSR payload");
return NO_CLOVES;
} }
int num = pc.cloveSet.size(); int num = pc.cloveSet.size();
// return non-null even if zero cloves
GarlicClove[] arr = new GarlicClove[num]; GarlicClove[] arr = new GarlicClove[num];
// msg id and expiration not checked in GarlicMessageReceiver // msg id and expiration not checked in GarlicMessageReceiver
CloveSet rv = new CloveSet(pc.cloveSet.toArray(arr), Certificate.NULL_CERT, 0, pc.datetime); CloveSet rv = new CloveSet(pc.cloveSet.toArray(arr), Certificate.NULL_CERT, 0, pc.datetime);
@ -602,9 +617,10 @@ public final class ECIESAEADEngine {
return null; return null;
} }
if (data.length == TAGLEN + MACLEN) { if (data.length == TAGLEN + MACLEN) {
// legal?
if (_log.shouldWarn()) if (_log.shouldWarn())
_log.warn("Zero length payload in ES"); _log.warn("Zero length payload in ES");
return null; return NO_CLOVES;
} }
PublicKey remote = key.getRemoteKey(); PublicKey remote = key.getRemoteKey();
PLCallback pc = new PLCallback(keyManager, remote); PLCallback pc = new PLCallback(keyManager, remote);
@ -617,10 +633,6 @@ public final class ECIESAEADEngine {
} catch (Exception e) { } catch (Exception e) {
throw new DataFormatException("ES payload error", e); throw new DataFormatException("ES payload error", e);
} }
if (pc.cloveSet.isEmpty()) {
if (_log.shouldWarn())
_log.warn("No garlic block in ES payload");
}
if (pc.nextKeys != null) { if (pc.nextKeys != null) {
for (NextSessionKey nextKey : pc.nextKeys) { for (NextSessionKey nextKey : pc.nextKeys) {
keyManager.nextKeyReceived(remote, nextKey); keyManager.nextKeyReceived(remote, nextKey);
@ -629,8 +641,13 @@ public final class ECIESAEADEngine {
if (pc.ackRequested) { if (pc.ackRequested) {
keyManager.ackRequested(remote, key.getID(), nonce); keyManager.ackRequested(remote, key.getID(), nonce);
} }
if (pc.cloveSet.isEmpty()) {
// this is legal
if (_log.shouldDebug())
_log.debug("No garlic block in ES payload");
return NO_CLOVES;
}
int num = pc.cloveSet.size(); int num = pc.cloveSet.size();
// return non-null even if zero cloves
GarlicClove[] arr = new GarlicClove[num]; GarlicClove[] arr = new GarlicClove[num];
// msg id and expiration not checked in GarlicMessageReceiver // msg id and expiration not checked in GarlicMessageReceiver
CloveSet rv = new CloveSet(pc.cloveSet.toArray(arr), Certificate.NULL_CERT, 0, pc.datetime); CloveSet rv = new CloveSet(pc.cloveSet.toArray(arr), Certificate.NULL_CERT, 0, pc.datetime);

View File

@ -33,6 +33,7 @@ final class MuxedEngine {
if (elgKey.getType() != EncType.ELGAMAL_2048 || if (elgKey.getType() != EncType.ELGAMAL_2048 ||
ecKey.getType() != EncType.ECIES_X25519) ecKey.getType() != EncType.ECIES_X25519)
throw new IllegalArgumentException(); throw new IllegalArgumentException();
final boolean debug = _log.shouldDebug();
CloveSet rv = null; CloveSet rv = null;
// Try in-order from fastest to slowest // Try in-order from fastest to slowest
boolean preferRatchet = keyManager.preferRatchet(); boolean preferRatchet = keyManager.preferRatchet();
@ -41,7 +42,7 @@ final class MuxedEngine {
rv = _context.eciesEngine().decryptFast(data, ecKey, keyManager.getECSKM()); rv = _context.eciesEngine().decryptFast(data, ecKey, keyManager.getECSKM());
if (rv != null) if (rv != null)
return rv; return rv;
if (_log.shouldDebug()) if (debug)
_log.debug("Ratchet tag not found before AES"); _log.debug("Ratchet tag not found before AES");
} }
// AES Tag // AES Tag
@ -58,7 +59,7 @@ final class MuxedEngine {
} }
return rv; return rv;
} else { } else {
if (_log.shouldDebug()) if (debug)
_log.debug("AES tag not found after ratchet? " + preferRatchet); _log.debug("AES tag not found after ratchet? " + preferRatchet);
} }
} }
@ -67,7 +68,7 @@ final class MuxedEngine {
rv = _context.eciesEngine().decryptFast(data, ecKey, keyManager.getECSKM()); rv = _context.eciesEngine().decryptFast(data, ecKey, keyManager.getECSKM());
if (rv != null) if (rv != null)
return rv; return rv;
if (_log.shouldDebug()) if (debug)
_log.debug("Ratchet tag not found after AES"); _log.debug("Ratchet tag not found after AES");
} }
@ -78,7 +79,7 @@ final class MuxedEngine {
keyManager.reportDecryptResult(true, ok); keyManager.reportDecryptResult(true, ok);
if (ok) if (ok)
return rv; return rv;
if (_log.shouldDebug()) if (debug)
_log.debug("Ratchet NS decrypt failed before ElG"); _log.debug("Ratchet NS decrypt failed before ElG");
} }
// ElG DH // ElG DH
@ -108,7 +109,7 @@ final class MuxedEngine {
rv = _context.eciesEngine().decryptSlow(data, ecKey, keyManager.getECSKM()); rv = _context.eciesEngine().decryptSlow(data, ecKey, keyManager.getECSKM());
boolean ok = rv != null; boolean ok = rv != null;
keyManager.reportDecryptResult(true, ok); keyManager.reportDecryptResult(true, ok);
if (!ok && _log.shouldDebug()) if (!ok && debug)
_log.debug("Ratchet NS decrypt failed after ElG"); _log.debug("Ratchet NS decrypt failed after ElG");
} }
return rv; return rv;

View File

@ -335,14 +335,14 @@ public class RatchetSKM extends SessionKeyManager implements SessionTagListener
public RatchetEntry consumeNextAvailableTag(PublicKey target) { public RatchetEntry consumeNextAvailableTag(PublicKey target) {
OutboundSession sess = getSession(target); OutboundSession sess = getSession(target);
if (sess == null) { if (sess == null) {
if (_log.shouldDebug()) //if (_log.shouldDebug())
_log.debug("No OB session to " + toString(target)); // _log.debug("No OB session to " + toString(target));
return null; return null;
} }
RatchetEntry rv = sess.consumeNext(); RatchetEntry rv = sess.consumeNext();
if (_log.shouldDebug()) { if (_log.shouldDebug()) {
if (rv != null) if (rv != null)
_log.debug("Using next key/tag " + rv + " to " + toString(target)); _log.debug("Using tag " + rv + " to " + toString(target));
else else
_log.debug("No more tags in OB session to " + toString(target)); _log.debug("No more tags in OB session to " + toString(target));
} }