diff --git a/router/java/src/net/i2p/router/transport/ntcp/InboundEstablishState.java b/router/java/src/net/i2p/router/transport/ntcp/InboundEstablishState.java index dd8e3d14f9071e499b928f14c9e962964f6e4d75..3531d3e0c25c9d7c79f4ade0671ea3a41fb3579f 100644 --- a/router/java/src/net/i2p/router/transport/ntcp/InboundEstablishState.java +++ b/router/java/src/net/i2p/router/transport/ntcp/InboundEstablishState.java @@ -646,8 +646,8 @@ class InboundEstablishState extends EstablishBase implements NTCP2Payload.Payloa byte options[] = new byte[OPTIONS1_SIZE]; try { _handshakeState.start(); - if (_log.shouldWarn()) - _log.warn("After start: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After start: " + _handshakeState.toString()); _handshakeState.readMessage(_X, 0, MSG1_SIZE, options, 0); } catch (GeneralSecurityException gse) { // Read a random number of bytes, store wanted in _padlen1 @@ -668,8 +668,8 @@ class InboundEstablishState extends EstablishBase implements NTCP2Payload.Payloa fail("Bad msg 1, X = " + Base64.encode(_X, 0, KEY_SIZE), re); return; } - if (_log.shouldWarn()) - _log.warn("After msg 1: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After msg 1: " + _handshakeState.toString()); int v = options[1] & 0xff; if (v != NTCPTransport.NTCP2_INT_VERSION) { fail("Bad version: " + v); @@ -738,8 +738,8 @@ class InboundEstablishState extends EstablishBase implements NTCP2Payload.Payloa return; changeState(State.IB_NTCP2_GOT_PADDING); _handshakeState.mixHash(_X, 0, _padlen1); - if (_log.shouldWarn()) - _log.warn("After mixhash padding " + _padlen1 + " msg 1: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After mixhash padding " + _padlen1 + " msg 1: " + _handshakeState.toString()); _received = 0; if (src.hasRemaining()) { // Inbound conn can never have extra data after msg 1 @@ -778,8 +778,8 @@ class InboundEstablishState extends EstablishBase implements NTCP2Payload.Payloa fail("Bad msg 3", re); return; } - if (_log.shouldWarn()) - _log.warn("After msg 3: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After msg 3: " + _handshakeState.toString()); try { // calls callbacks below NTCP2Payload.processPayload(_context, this, payload, 0, _msg3p2len - MAC_SIZE, true); @@ -840,16 +840,16 @@ class InboundEstablishState extends EstablishBase implements NTCP2Payload.Payloa fail("Bad msg 2 out", re); return; } - if (_log.shouldWarn()) - _log.warn("After msg 2: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After msg 2: " + _handshakeState.toString()); Hash h = _context.routerHash(); SessionKey bobHash = new SessionKey(h.getData()); _context.aes().encrypt(tmp, 0, tmp, 0, bobHash, _prevEncrypted, KEY_SIZE); if (padlen2 > 0) { _context.random().nextBytes(tmp, MSG2_SIZE, padlen2); _handshakeState.mixHash(tmp, MSG2_SIZE, padlen2); - if (_log.shouldWarn()) - _log.warn("After mixhash padding " + padlen2 + " msg 2: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After mixhash padding " + padlen2 + " msg 2: " + _handshakeState.toString()); } changeState(State.IB_NTCP2_SENT_Y); @@ -872,6 +872,7 @@ class InboundEstablishState extends EstablishBase implements NTCP2Payload.Payloa CipherStatePair ckp = _handshakeState.split(); CipherState rcvr = ckp.getReceiver(); CipherState sender = ckp.getSender(); + // debug, to be removed byte[] k_ab = rcvr.getKey(); byte[] k_ba = sender.getKey(); @@ -885,8 +886,8 @@ class InboundEstablishState extends EstablishBase implements NTCP2Payload.Payloa _log.warn("Failed msg3p2, code " + _msg3p2FailReason + " for " + this); _con.failInboundEstablishment(sender, sip_ba, _msg3p2FailReason); } else { - if (_log.shouldWarn()) { - _log.warn("Finished establishment for " + this + + if (_log.shouldDebug()) { + _log.debug("Finished establishment for " + this + "\nGenerated ChaCha key for A->B: " + Base64.encode(k_ab) + "\nGenerated ChaCha key for B->A: " + Base64.encode(k_ba) + "\nGenerated SipHash key for A->B: " + Base64.encode(sip_ab) + @@ -963,11 +964,11 @@ class InboundEstablishState extends EstablishBase implements NTCP2Payload.Payloa if (flood && !ri.equals(old)) { FloodfillNetworkDatabaseFacade fndf = (FloodfillNetworkDatabaseFacade) _context.netDb(); if (fndf.floodConditional(ri)) { - if (_log.shouldLog(Log.WARN)) - _log.warn("Flooded the RI: " + h); + if (_log.shouldDebug()) + _log.debug("Flooded the RI: " + h); } else { - if (_log.shouldLog(Log.WARN)) - _log.warn("Flood request but we didn't: " + h); + if (_log.shouldInfo()) + _log.info("Flood request but we didn't: " + h); } } } catch (IllegalArgumentException iae) { diff --git a/router/java/src/net/i2p/router/transport/ntcp/NTCPConnection.java b/router/java/src/net/i2p/router/transport/ntcp/NTCPConnection.java index 908c0ce0b5ca610c7f548ca957d833aa5570d96b..d8ef7d04e5d3fc3814fbf17271dac537f5d3253d 100644 --- a/router/java/src/net/i2p/router/transport/ntcp/NTCPConnection.java +++ b/router/java/src/net/i2p/router/transport/ntcp/NTCPConnection.java @@ -892,8 +892,8 @@ public class NTCPConnection implements Closeable { blocks.add(block); size += sz; _nextInfoTime = now + (INFO_FREQUENCY / 2) + _context.random().nextInt(INFO_FREQUENCY); - if (_log.shouldLog(Log.INFO)) - _log.info("SENDING NTCP2 RI block"); + if (_log.shouldDebug()) + _log.debug("SENDING NTCP2 RI block"); } // else wait until next time } int availForPad = BUFFER_SIZE - (size + NTCP2Payload.BLOCK_HEADER_SIZE); @@ -936,8 +936,8 @@ public class NTCPConnection implements Closeable { int padlen = min; if (range > 0) padlen += _context.random().nextInt(1 + range); - if (_log.shouldWarn()) - _log.warn("Padding params:" + + if (_log.shouldDebug()) + _log.debug("Padding params:" + " data size: " + dataSize + " avail: " + availForPad + " minSend: " + minSend + @@ -968,8 +968,8 @@ public class NTCPConnection implements Closeable { */ private void sendRouterInfo(RouterInfo ri, boolean shouldFlood) { // no synch needed, sendNTCP2() is synched - if (_log.shouldWarn()) - _log.warn("Sending router info for: " + ri.getHash() + " flood? " + shouldFlood); + if (_log.shouldDebug()) + _log.debug("Sending router info for: " + ri.getHash() + " flood? " + shouldFlood); List<Block> blocks = new ArrayList<Block>(2); Block block = new NTCP2Payload.RIBlock(ri, shouldFlood); int size = block.getTotalLength(); @@ -1002,8 +1002,8 @@ public class NTCPConnection implements Closeable { private void sendTermination(int reason, int validFramesRcvd) { // TODO add param to clear queues? // no synch needed, sendNTCP2() is synched - if (_log.shouldWarn()) - _log.warn("Sending termination, reason: " + reason + ", vaild frames rcvd: " + validFramesRcvd); + if (_log.shouldInfo()) + _log.info("Sending termination, reason: " + reason + ", vaild frames rcvd: " + validFramesRcvd); List<Block> blocks = new ArrayList<Block>(2); Block block = new NTCP2Payload.TerminationBlock(reason, validFramesRcvd); int plen = block.getTotalLength(); @@ -1033,8 +1033,8 @@ public class NTCPConnection implements Closeable { */ private synchronized void sendNTCP2(byte[] tmp, List<Block> blocks) { if (_sender == null) { - if (_log.shouldWarn()) - _log.warn("sender gone", new Exception()); + if (_log.shouldInfo()) + _log.info("sender gone", new Exception()); return; } int payloadlen = NTCP2Payload.writePayload(tmp, 0, blocks); @@ -1053,7 +1053,7 @@ public class NTCPConnection implements Closeable { long sipIV = SipHashInline.hash24(_sendSipk1, _sendSipk2, _sendSipIV); enc[0] = (byte) ((framelen >> 8) ^ (sipIV >> 8)); enc[1] = (byte) (framelen ^ sipIV); - if (_log.shouldWarn()) { + if (_log.shouldDebug()) { StringBuilder buf = new StringBuilder(256); buf.append("Sending ").append(blocks.size()) .append(" blocks in ").append(framelen) @@ -1061,7 +1061,7 @@ public class NTCPConnection implements Closeable { for (int i = 0; i < blocks.size(); i++) { buf.append("\n ").append(i).append(": ").append(blocks.get(i).toString()); } - _log.warn(buf.toString()); + _log.debug(buf.toString()); } _transport.getPumper().wantsWrite(this, enc); toLong8LE(_sendSipIV, 0, sipIV); @@ -1816,8 +1816,6 @@ public class NTCPConnection implements Closeable { _sendSipk2 = fromLong8LE(sip_ba, 8); _sendSipIV = new byte[SIP_IV_LENGTH]; System.arraycopy(sip_ba, 16, _sendSipIV, 0, SIP_IV_LENGTH); - if (_log.shouldWarn()) - _log.warn("Send SipHash keys: " + _sendSipk1 + ' ' + _sendSipk2 + ' ' + Base64.encode(_sendSipIV)); _establishState = EstablishBase.VERIFIED; _establishedOn = _context.clock().now(); _nextMetaTime = Long.MAX_VALUE; @@ -1849,8 +1847,8 @@ public class NTCPConnection implements Closeable { _sendSipk2 = fromLong8LE(sip_send, 8); _sendSipIV = new byte[SIP_IV_LENGTH]; System.arraycopy(sip_send, 16, _sendSipIV, 0, SIP_IV_LENGTH); - if (_log.shouldWarn()) - _log.warn("Send SipHash keys: " + _sendSipk1 + ' ' + _sendSipk2 + ' ' + Base64.encode(_sendSipIV)); + if (_log.shouldDebug()) + _log.debug("Send SipHash keys: " + _sendSipk1 + ' ' + _sendSipk2 + ' ' + Base64.encode(_sendSipIV)); _clockSkew = clockSkew; _establishState = EstablishBase.VERIFIED; _establishedOn = _context.clock().now(); @@ -1892,8 +1890,8 @@ public class NTCPConnection implements Closeable { _sipk1 = fromLong8LE(keyData, 0); _sipk2 = fromLong8LE(keyData, 8); System.arraycopy(keyData, 16, _sipIV, 0, SIP_IV_LENGTH); - if (_log.shouldWarn()) - _log.warn("Recv SipHash keys: " + _sipk1 + ' ' + _sipk2 + ' ' + Base64.encode(_sipIV)); + if (_log.shouldDebug()) + _log.debug("Recv SipHash keys: " + _sipk1 + ' ' + _sipk2 + ' ' + Base64.encode(_sipIV)); } public void receive(ByteBuffer buf) { @@ -1949,8 +1947,8 @@ public class NTCPConnection implements Closeable { if (_dataBuf != null && _dataBuf.getData().length == BUFFER_SIZE) releaseReadBuf(_dataBuf); if (_framelen > BUFFER_SIZE) { - if (_log.shouldWarn()) - _log.warn("Allocating big ByteArray: " + _framelen); + if (_log.shouldInfo()) + _log.info("Allocating big ByteArray: " + _framelen); byte[] data = new byte[_framelen]; _dataBuf = new ByteArray(data); } else { @@ -1995,8 +1993,8 @@ public class NTCPConnection implements Closeable { * @return success, false for fatal error (AEAD) only */ private boolean decryptAndProcess(byte[] data, int off) { - if (_log.shouldWarn()) - _log.warn("Decrypting frame " + _frameCount + " with " + _framelen + " bytes"); + if (_log.shouldDebug()) + _log.debug("Decrypting frame " + _frameCount + " with " + _framelen + " bytes"); try { _rcvr.decryptWithAd(null, data, off, data, off, _framelen); } catch (GeneralSecurityException gse) { @@ -2008,8 +2006,8 @@ public class NTCPConnection implements Closeable { try { int blocks = NTCP2Payload.processPayload(_context, this, data, off, _framelen - OutboundNTCP2State.MAC_SIZE, false); - if (_log.shouldWarn()) - _log.warn("Processed " + blocks + " blocks in frame"); + if (_log.shouldDebug()) + _log.debug("Processed " + blocks + " blocks in frame"); _blockCount += blocks; } catch (IOException ioe) { if (_log.shouldWarn()) @@ -2038,8 +2036,8 @@ public class NTCPConnection implements Closeable { //// PayloadCallbacks public void gotRI(RouterInfo ri, boolean isHandshake, boolean flood) throws DataFormatException { - if (_log.shouldWarn()) - _log.warn("Got updated RI"); + if (_log.shouldDebug()) + _log.debug("Got updated RI"); _messagesRead.incrementAndGet(); try { Hash h = ri.getHash(); @@ -2047,11 +2045,11 @@ public class NTCPConnection implements Closeable { if (flood && !ri.equals(old)) { FloodfillNetworkDatabaseFacade fndf = (FloodfillNetworkDatabaseFacade) _context.netDb(); if (fndf.floodConditional(ri)) { - if (_log.shouldLog(Log.WARN)) - _log.warn("Flooded the RI: " + h); + if (_log.shouldDebug()) + _log.debug("Flooded the RI: " + h); } else { - if (_log.shouldLog(Log.WARN)) - _log.warn("Flood request but we didn't: " + h); + if (_log.shouldInfo()) + _log.info("Flood request but we didn't: " + h); } } } catch (IllegalArgumentException iae) { @@ -2060,15 +2058,15 @@ public class NTCPConnection implements Closeable { } public void gotDateTime(long time) { - if (_log.shouldWarn()) - _log.warn("Got updated datetime block"); + if (_log.shouldDebug()) + _log.debug("Got updated datetime block"); receiveTimestamp((time + 500) / 1000); // update skew } public void gotI2NP(I2NPMessage msg) { - if (_log.shouldWarn()) - _log.warn("Got I2NP msg: " + msg); + if (_log.shouldDebug()) + _log.debug("Got I2NP msg: " + msg); long timeToRecv = 0; // _context.clock().now() - _stateBegin; int size = 100; // FIXME _transport.messageReceived(msg, _remotePeer, null, timeToRecv, size); @@ -2093,16 +2091,16 @@ public class NTCPConnection implements Closeable { NTCP2Options hisPadding = new NTCP2Options(tmin, tmax, rmin, rmax, tdummy, rdummy, tdelay, rdelay); _paddingConfig = OUR_PADDING.merge(hisPadding); - if (_log.shouldWarn()) - _log.warn("Got padding options:" + + if (_log.shouldDebug()) + _log.debug("Got padding options:" + "\nhis padding options: " + hisPadding + "\nour padding options: " + OUR_PADDING + "\nmerged config is: " + _paddingConfig); } public void gotTermination(int reason, long lastReceived) { - if (_log.shouldWarn()) - _log.warn("Got Termination: " + reason + " total rcvd: " + lastReceived); + if (_log.shouldInfo()) + _log.info("Got Termination: " + reason + " total rcvd: " + lastReceived); _terminated = true; close(); } @@ -2113,8 +2111,8 @@ public class NTCPConnection implements Closeable { } public void gotPadding(int paddingLength, int frameLength) { - if (_log.shouldWarn()) - _log.warn("Got " + paddingLength + + if (_log.shouldDebug()) + _log.debug("Got " + paddingLength + " bytes padding in " + frameLength + " byte frame; ratio: " + (((float) paddingLength) / ((float) frameLength)) + " configured min: " + _paddingConfig.getRecvMin() + diff --git a/router/java/src/net/i2p/router/transport/ntcp/OutboundNTCP2State.java b/router/java/src/net/i2p/router/transport/ntcp/OutboundNTCP2State.java index 5295cf2e97fff6c42cbb3ab780719f9e37ecfaa8..56d50f74f2441476b3adf91a931b09a765ed53f1 100644 --- a/router/java/src/net/i2p/router/transport/ntcp/OutboundNTCP2State.java +++ b/router/java/src/net/i2p/router/transport/ntcp/OutboundNTCP2State.java @@ -216,8 +216,8 @@ class OutboundNTCP2State implements EstablishState { // output to _tmp try { _handshakeState.start(); - if (_log.shouldWarn()) - _log.warn("After start: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After start: " + _handshakeState.toString()); _handshakeState.writeMessage(_tmp, 0, options, 0, OPTIONS1_SIZE); } catch (GeneralSecurityException gse) { // buffer length error @@ -231,8 +231,8 @@ class OutboundNTCP2State implements EstablishState { fail("Bad msg 1 out", re); return; } - if (_log.shouldWarn()) - _log.warn("After msg 1: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After msg 1: " + _handshakeState.toString()); // encrypt key before writing _context.aes().encrypt(_tmp, 0, _tmp, 0, _bobHash, _bobIV, KEY_SIZE); @@ -242,8 +242,8 @@ class OutboundNTCP2State implements EstablishState { if (padlen1 > 0) { _context.random().nextBytes(_tmp, MSG1_SIZE, padlen1); _handshakeState.mixHash(_tmp, MSG1_SIZE, padlen1); - if (_log.shouldWarn()) - _log.warn("After mixhash padding " + padlen1 + " msg 1: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After mixhash padding " + padlen1 + " msg 1: " + _handshakeState.toString()); } changeState(State.OB_SENT_X); @@ -285,8 +285,8 @@ class OutboundNTCP2State implements EstablishState { fail("Bad msg 2, Y = " + Base64.encode(_tmp, 0, KEY_SIZE), re); return; } - if (_log.shouldWarn()) - _log.warn("After msg 2: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After msg 2: " + _handshakeState.toString()); _padlen2 = (int) DataHelper.fromLong(options2, 2, 2); long tsB = DataHelper.fromLong(options2, 8, 4); long now = _context.clock().now(); @@ -310,8 +310,8 @@ class OutboundNTCP2State implements EstablishState { return; if (_padlen2 > 0) { _handshakeState.mixHash(_tmp, 0, _padlen2); - if (_log.shouldWarn()) - _log.warn("After mixhash padding " + _padlen2 + " msg 2: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After mixhash padding " + _padlen2 + " msg 2: " + _handshakeState.toString()); } changeState(State.OB_GOT_PADDING); if (src.hasRemaining()) { @@ -384,11 +384,11 @@ class OutboundNTCP2State implements EstablishState { return; } // send it all at once - if (_log.shouldWarn()) - _log.warn("Sending msg3, part 1 is:\n" + net.i2p.util.HexDump.dump(tmp, 0, MSG3P1_SIZE)); + if (_log.shouldDebug()) + _log.debug("Sending msg3, part 1 is:\n" + net.i2p.util.HexDump.dump(tmp, 0, MSG3P1_SIZE)); _transport.getPumper().wantsWrite(_con, tmp); - if (_log.shouldWarn()) - _log.warn("After msg 3: " + _handshakeState.toString()); + if (_log.shouldDebug()) + _log.debug("After msg 3: " + _handshakeState.toString()); setDataPhase(); } @@ -404,6 +404,7 @@ class OutboundNTCP2State implements EstablishState { CipherStatePair ckp = _handshakeState.split(); CipherState rcvr = ckp.getReceiver(); CipherState sender = ckp.getSender(); + // debug, to be removed byte[] k_ab = sender.getKey(); byte[] k_ba = rcvr.getKey(); @@ -412,8 +413,8 @@ class OutboundNTCP2State implements EstablishState { byte[] sip_ab = sipkeys[0]; byte[] sip_ba = sipkeys[1]; - if (_log.shouldWarn()) { - _log.warn("Finished establishment for " + this + + if (_log.shouldDebug()) { + _log.debug("Finished establishment for " + this + "\nGenerated ChaCha key for A->B: " + Base64.encode(k_ab) + "\nGenerated ChaCha key for B->A: " + Base64.encode(k_ba) + "\nGenerated SipHash key for A->B: " + Base64.encode(sip_ab) +