Disruptive behavior due to handling of SSU2 session termination
This issue is disruptive on my local testing network, but, for reasons explained below, would probably be minor on the real i2p network. But since they were causing noticeable issues on my testing network, I wanted to run the down before the next release.
So, again, this issue is probably minor, but, it has issues that probably need to addressed.
SUMMARY:
On my testing network, when a SSU2 peer terminates a session (such as for idle timeout), there are problems handling the acknowledgements from the terminated peer. The UDP PacketHandler has a component named the _failCache (that only has room for 24 entries), which can act as a short-term ban list. Because of the problems that arise when processing a SSU2 session termination, the terminated peer becomes placed on the _failCache. On small testing networks, where you are usually connected to most of the available peers, entries on the _failCache can be long-lived. So, on a small testing network, the small number of peers you're not connected can accumulate on the _failCache.
This leads to peers concluding they're firewalled because Charlie is only selected from the pool of peers you're not connected to. But incoming connection attempts from Charlie are quietly ploinked because Charlie is often on the PacketHandler _failCache.
On the real I2P network, there is a much bigger pool of Charlies, and the _failCache is probably flushed out faster since it only has 24 members max. So this probably happens much less frequently.
DETAIL:
For reference, I've added the following noisy debugging logging to my testing network to help with identifying the issue.
From: obscuratus <obscuratus@mail.i2p>
Date: Tue, 4 Oct 2022 15:23:46 +0000 (-0500)
Subject: [Transport/UDP] Packet Handler Debugging.
[Transport/UDP] Packet Handler Debugging.
Provide Debugging relevent for resolving issues involving
packet handling failures.
This includes HMAC Validation Debugging, debugging around the
implementation of _failCache in PacketHandler.java, and the
process PacketHandler.java uses for decrypting packets
(especially packets from new hosts).
Signed-off-by: obscuratus <obscuratus@mail.i2p>
---
diff --git a/router/java/src/net/i2p/router/transport/udp/PacketHandler.java b/router/java/src/net/i2p/router/transport/udp/PacketHandler.java
index 165d86fa1..b3efb8a9d 100644
--- a/router/java/src/net/i2p/router/transport/udp/PacketHandler.java
+++ b/router/java/src/net/i2p/router/transport/udp/PacketHandler.java
@@ -100,6 +100,11 @@ class PacketHandler {
_context.statManager().createRateStat("udp.receivePacketSize.dataKnownAck", "Packet size of the given inbound packet type (period is the packet's lifetime)", "udp", UDPTransport.RATES);
_context.statManager().createRateStat("udp.receivePacketSize.dataUnknown", "Packet size of the given inbound packet type (period is the packet's lifetime)", "udp", UDPTransport.RATES);
_context.statManager().createRateStat("udp.receivePacketSize.dataUnknownAck", "Packet size of the given inbound packet type (period is the packet's lifetime)", "udp", UDPTransport.RATES);
+ _context.statManager().createRateStat("udp.HMACValidate.v4good", "How often we successfully HMAC validate an IPv4 packet.", "udp", UDPTransport.RATES);
+ _context.statManager().createRateStat("udp.HMACValidate.v4fail", "How often HMAC validatation fails on an IPv4 packet.", "udp", UDPTransport.RATES);
+ _context.statManager().createRateStat("udp.HMACValidate.v6good", "How often we successfully HMAC validate an IPv6 packet.", "udp", UDPTransport.RATES);
+ _context.statManager().createRateStat("udp.HMACValidate.v6fail", "How often HMAC validatation fails on an IPv6 packet.", "udp", UDPTransport.RATES);
+ _context.statManager().createRateStat("udp.HMACValidate.total", "How often attempt validatation on a packet.", "udp", UDPTransport.RATES);
}
public synchronized void startup() {
@@ -354,13 +359,25 @@ class PacketHandler {
boolean alreadyFailed;
synchronized(_failCache) {
alreadyFailed = _failCache.get(remoteHost) != null;
- }
+ }
+ if (alreadyFailed && _log.shouldDebug())
+ _log.debug("Packet marked as alreadyFailed from host " + remoteHost);
if (!alreadyFailed) {
// For now, try SSU2 Session/Token Request processing here.
// After we've migrated the majority of the network over to SSU2,
// we can try SSU2 first.
+ if (_log.shouldDebug())
+ _log.debug("Evaluating packet: _enableSSU2: " + _enableSSU2
+ + "; (peerType == PeerType.NEW_PEER) is: "
+ + (peerType == PeerType.NEW_PEER)
+ + "; packet length: "
+ + packet.getPacket().getLength()
+ + "; SSU2Util.MIN_TOKEN_REQUEST_LEN: "
+ + SSU2Util.MIN_TOKEN_REQUEST_LEN);
if (_enableSSU2 && peerType == PeerType.NEW_PEER &&
packet.getPacket().getLength() >= SSU2Util.MIN_TOKEN_REQUEST_LEN) {
+ if (_log.shouldDebug())
+ _log.debug("Attempting to handle packet as SSU2...");
boolean handled = receiveSSU2Packet(remoteHost, packet, (InboundEstablishState2) null);
if (handled)
return;
@@ -414,8 +431,10 @@ class PacketHandler {
_log.warn(buf.toString());
}
synchronized(_failCache) {
+ if (_log.shouldLog(Log.DEBUG))
+ _log.debug("Adding host to _failCache(size = " + _failCache.size() + "): " + remoteHost);
_failCache.put(remoteHost, DUMMY);
- }
+ }
}
if (_log.shouldLog(Log.WARN))
_log.warn("Cannot validate rcvd pkt (path) wasCached? " + alreadyFailed + ": " + packet);
@@ -798,6 +817,16 @@ class PacketHandler {
// Session Request, Token Request, Peer Test 5-7, or Hole Punch
k2 = k1;
header = SSU2Header.trialDecryptHandshakeHeader(packet, k1, k2);
+ if (_log.shouldDebug()) {
+ if (header == null)
+ _log.debug("receiveSSU2Packet/trialDecryptHandshakeHeader: header is null.");
+ else
+ _log.debug("receiveSSU2Packet/trialDecryptHandshakeHeader: "
+ + "; getType is SESSION_REQUEST_FLAG_BYTE?: "
+ + (header.getType() == SSU2Util.SESSION_REQUEST_FLAG_BYTE)
+ + "; getVersion: " + header.getVersion()
+ + "; NetID match: " + (header.getNetID() == _networkID));
+ }
if (header == null ||
header.getType() != SSU2Util.SESSION_REQUEST_FLAG_BYTE ||
header.getVersion() != 2 ||
@@ -807,6 +836,14 @@ class PacketHandler {
// The first 32 bytes were fine, but it corrupted the next 32 bytes
// TODO make this more efficient, just take the first 32 bytes
header = SSU2Header.trialDecryptLongHeader(packet, k1, k2);
+ if (_log.shouldDebug()) {
+ if (header == null)
+ _log.debug("receiveSSU2Packet/trialDecryptLongHeader: header is null.");
+ else
+ _log.debug("receiveSSU2Packet/trialDecryptLongHeader: "
+ + " getVersion: " + header.getVersion()
+ + "; NetID match: " + (header.getNetID() == _networkID));
+ }
if (header == null ||
header.getVersion() != 2 ||
header.getNetID() != _networkID) {
diff --git a/router/java/src/net/i2p/router/transport/udp/UDPPacket.java b/router/java/src/net/i2p/router/transport/udp/UDPPacket.java
index 9ba4e512b..b500faedd 100644
--- a/router/java/src/net/i2p/router/transport/udp/UDPPacket.java
+++ b/router/java/src/net/i2p/router/transport/udp/UDPPacket.java
@@ -2,6 +2,7 @@ package net.i2p.router.transport.udp;
import java.net.DatagramPacket;
import java.net.InetAddress;
+import java.net.Inet6Address;
import java.util.Arrays;
import java.util.Queue;
import java.util.concurrent.LinkedBlockingQueue;
@@ -44,6 +45,10 @@ class UDPPacket implements CDPQEntry {
//private long _beforeReceiveFragments;
//private long _afterHandlingTime;
private int _validateCount;
+ private int _validateCountIPv4True;
+ private int _validateCountIPv4False;
+ private int _validateCountIPv6True;
+ private int _validateCountIPv6False;
// private boolean _isInbound;
private FIFOBandwidthLimiter.Request _bandwidthRequest;
private long _seqNum;
@@ -143,6 +148,11 @@ class UDPPacket implements CDPQEntry {
_packet = new DatagramPacket(_data, MAX_PACKET_SIZE);
_validateBuf = new byte[MAX_VALIDATE_SIZE];
_ivBuf = new byte[IV_SIZE];
+ _validateCount = 0;
+ _validateCountIPv4True = 0;
+ _validateCountIPv4False = 0;
+ _validateCountIPv6True = 0;
+ _validateCountIPv6False = 0;
init(ctx);
}
@@ -160,7 +170,6 @@ class UDPPacket implements CDPQEntry {
// _isInbound = inbound;
_initializeTime = _context.clock().now();
_markedType = -1;
- _validateCount = 0;
_remoteHost = null;
_released = false;
// clear out some values to make debugging easier via toString()
@@ -251,11 +260,16 @@ class UDPPacket implements CDPQEntry {
verifyNotReleased();
//_beforeValidate = _context.clock().now();
boolean eq = false;
+ boolean isIPv6 = false;
+ Log log = _context.logManager().getLog(UDPPacket.class);
Arrays.fill(_validateBuf, (byte)0);
// validate by comparing _data[0:15] and
// HMAC(payload + IV + (payloadLength ^ protocolVersion), macKey)
+ InetAddress addr = _packet.getAddress();
+ isIPv6 = (addr instanceof Inet6Address);
+
int payloadLength = _packet.getLength() - MAC_SIZE - IV_SIZE;
if (payloadLength > 0) {
int off = 0;
@@ -277,7 +291,6 @@ class UDPPacket implements CDPQEntry {
if (!eq) {
// this is relatively frequent, as you can get old keys in PacketHandler.
- Log log = _context.logManager().getLog(UDPPacket.class);
if (log.shouldLog(Log.INFO)) {
byte[] calc = new byte[32];
hmac.calculate(macKey, _validateBuf, 0, off, calc, 0);
@@ -286,6 +299,7 @@ class UDPPacket implements CDPQEntry {
str.append(_packet.getLength()).append(" byte pkt, ");
str.append(payloadLength).append(" byte payload");
str.append("\n\tFrom: ").append(getRemoteHost().toString());
+ str.append("\n\tNetworkID: ").append(netid);
str.append("\n\tIV: ").append(Base64.encode(_validateBuf, payloadLength, IV_SIZE));
str.append("\n\tIV2: ").append(Base64.encode(_data, MAC_SIZE, IV_SIZE));
str.append("\n\tGiven Len: ").append(DataHelper.fromLong(_validateBuf, payloadLength + IV_SIZE, 2));
@@ -301,7 +315,6 @@ class UDPPacket implements CDPQEntry {
}
}
} else {
- Log log = _context.logManager().getLog(UDPPacket.class);
if (log.shouldLog(Log.WARN))
log.warn("Payload length is " + payloadLength + ", too short! From: " + getRemoteHost() + '\n' +
net.i2p.util.HexDump.dump(_data, _packet.getOffset(), _packet.getLength()));
@@ -309,6 +322,31 @@ class UDPPacket implements CDPQEntry {
//_afterValidate = _context.clock().now();
_validateCount++;
+ _context.statManager().addRateData("udp.HMACValidate.total", 1);
+ if (eq) {
+ if (isIPv6) {
+ _validateCountIPv6True++;
+ _context.statManager().addRateData("udp.HMACValidate.v6good", 1);
+ } else {
+ _validateCountIPv4True++;
+ _context.statManager().addRateData("udp.HMACValidate.v4good", 1);
+ }
+ } else {
+ if (isIPv6) {
+ _validateCountIPv6False++;
+ _context.statManager().addRateData("udp.HMACValidate.v6fail", 1);
+ } else {
+ _validateCountIPv4False++;
+ _context.statManager().addRateData("udp.HMACValidate.v4fail", 1);
+ }
+ }
+ if (!eq && log.shouldLog(Log.INFO))
+ log.info("Current HMAC validation is invalid, isIPv6: " + isIPv6
+ + "; Overall HMAC validation stats: Good IPv4: " + _validateCountIPv4True
+ + "; Failed IPv4: " + _validateCountIPv4False
+ + "; Good IPv6: " + _validateCountIPv6True
+ + "; Failed IPv6: " + _validateCountIPv6False
+ + "; Total Validated: " + _validateCount);
return eq;
}
Problems with HMAC validation where one of the first symptoms I associated with this issue. As it turns out, Java-I2P is fairly tolerant of problems with HMAC validation, so it's probably not the primary issue.
The main problem can be summarized as follows
- Peer 1, which has a SSU2 session with Peer 2, decides to terminate the session, such as for idle timeout.
- Peer 1 sends a SSU2 termination message to Peer 2.
- Peer 1 terminates the session with Peer 2 without any further delay.
- Peer 2 replies with a SSU2 acknowledgment message.
- Peer 1 sees this as a new incoming message since it's already ended the session with Peer 2.
- Peer 1 fails to decrypt the Peer 2 acknowledgement message.
- Peer 1's PacketHandler places Peer 2 on the _failCache.
- Further incoming SSU2 message attempts from Peer 2 to Peer 1 are dropped by Peer 1, until Peer 2 rotates off the _failCache.
- If Peer 1's _failCache doesn't flush out very often, then Peer 1 may conclude it is firewalled when Peer 2 is selected as Charlie, since Peer 2's attempts to send it's Charlie message are dropped by the packet handler.
Here's an example of the log exchanges I'm seeing related to this issue.
Here's Peer 1's (fd40:39b0:31ab:0:0:0:0:101) log excerpt:
Oct 4, 2022, 12:55:43 PM DEBUG [leTimer2 1/4] ter.transport.udp.UDPTransport: Expiring 1 peers
Oct 4, 2022, 12:55:43 PM DEBUG [leTimer2 1/4] r.transport.udp.PacketBuilder2: Sending termination 2 to : [fd40:39b0:31ab:0:0:0:0:118]:28118 QYusQv OB2 recvAge: 20m sendAge: 20m sendAttemptAge: 20m sendACKAge: 20m lifetime: 20m RTT: 268 RTTdev: 143 RTO: 1000 MTU: 1280 LMTU: 1488 cwin: 3971 acwin: 3971 SST: 524288 FRTX? false consecFail: 0 msgs rcvd: 1 msgs sent: 1 pkts rcvd OK/Dup: 3/0 pkts sent OK/Dup: 1/0 IBM: 0 OBQ: 0 OBL: 0
Oct 4, 2022, 12:55:43 PM DEBUG [leTimer2 1/4] r.transport.udp.PacketBuilder2: Sending acks ACK 2-0 to [fd40:39b0:31ab:0:0:0:0:118]:28118 QYusQv OB2 recvAge: 20m sendAge: 20m sendAttemptAge: 20m sendACKAge: 0ms lifetime: 20m RTT: 268 RTTdev: 143 RTO: 1000 MTU: 1280 LMTU: 1488 cwin: 3971 acwin: 3971 SST: 524288 FRTX? false consecFail: 0 msgs rcvd: 1 msgs sent: 1 pkts rcvd OK/Dup: 3/0 pkts sent OK/Dup: 1/0 IBM: 0 OBQ: 0 OBL: 0
Oct 4, 2022, 12:55:43 PM DEBUG [leTimer2 1/4] ter.transport.udp.UDPTransport: Sending destroy to : [fd40:39b0:31ab:0:0:0:0:118]:28118 QYusQv OB2 recvAge: 20m sendAge: 20m sendAttemptAge: 20m sendACKAge: 0ms lifetime: 20m RTT: 268 RTTdev: 143 RTO: 1000 MTU: 1280 LMTU: 1488 cwin: 3971 acwin: 3971 SST: 524288 FRTX? false consecFail: 0 msgs rcvd: 1 msgs sent: 1 pkts rcvd OK/Dup: 3/0 pkts sent OK/Dup: 1/0 IBM: 0 OBQ: 0 OBL: 0
Oct 4, 2022, 12:55:43 PM DEBUG [leTimer2 1/4] ter.transport.udp.UDPTransport: Sending 71 byte pkt with [fd40:39b0:31ab:0:0:0:0:118]:28118 priority=100 msgType=74 markType=1
Oct 4, 2022, 12:55:43 PM DEBUG [leTimer2 1/4] router.transport.udp.UDPSender: Added the packet onto the queue with a lifetime of 0
Oct 4, 2022, 12:55:43 PM DEBUG [UDPSender 1 ] router.transport.udp.UDPSender: Packet to send known: 71 byte pkt with [fd40:39b0:31ab:0:0:0:0:118]:28118 priority=100 msgType=74 markType=1 sinceEnqueued=0
Oct 4, 2022, 12:55:43 PM DEBUG [UDPSender 1 ] router.transport.udp.UDPSender: Sent the packet 71 byte pkt with [fd40:39b0:31ab:0:0:0:0:118]:28118 priority=100 msgType=74 markType=1 sinceEnqueued=0
Oct 4, 2022, 12:55:43 PM DEBUG [leTimer2 1/4] ter.transport.udp.UDPTransport:
Dropping remote peer: [fd40:39b0:31ab:0:0:0:0:118]:28118 QYusQv
OB2 recvAge: 20m sendAge: 20m sendAttemptAge: 20m sendACKAge: 0ms lifetime: 20m
RTT: 268 RTTdev: 143 RTO: 1000 MTU: 1280 LMTU: 1488 cwin: 3971 acwin: 3971 SST: 524288
FRTX? false consecFail: 0 msgs rcvd: 1 msgs sent: 1 pkts rcvd OK/Dup: 3/0 pkts sent
OK/Dup: 1/0 IBM: 0 OBQ: 0 OBL: 0 banlist? false lifetime: 1200383
time since send/fully/recv/ack: 1200383 / 1200240 / 1200240 / 0 consec failures: 0 cause: idle too long
java.lang.Exception: Dropped by
at net.i2p.router.transport.udp.UDPTransport.dropPeer(UDPTransport.java:1997)
at net.i2p.router.transport.udp.UDPTransport$ExpirePeerEvent.timeReached(UDPTransport.java:3673)
at net.i2p.util.SimpleTimer2$TimedEvent.run2(SimpleTimer2.java:492)
at net.i2p.util.SimpleTimer2$TimedEvent.run(SimpleTimer2.java:431)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Oct 4, 2022, 12:55:43 PM DEBUG [leTimer2 1/4] t.udp.OutboundMessageFragments:
Dropping peer [Hash: QYusQvrl6fuUhRoo2ntCCsbmBef4lQ2P-E7RlwefOX4=]
Oct 4, 2022, 12:55:43 PM INFO [DPReceiver 1] uter.transport.udp.UDPReceiver:
After blocking socket.receive: packet is 58 bytes on 2049582050
Oct 4, 2022, 12:55:43 PM INFO [DPReceiver 1] uter.transport.udp.UDPReceiver:
Received: 58 byte pkt with [fd40:39b0:31ab:0:0:0:0:118]:28118 priority=300
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] er.transport.udp.PacketHandler:
Packet received is not for an inbound or outbound establishment
Oct 4, 2022, 12:55:43 PM INFO [ handler 1/1] router.transport.udp.UDPPacket: Bad HMAC:
58 byte pkt, 26 byte payload
From: [fd40:39b0:31ab:0:0:0:0:118]:28118
NetworkID: 2
IV: DCfiM24BBICh0cPMbLmbWA==
IV2: DCfiM24BBICh0cPMbLmbWA==
Given Len: 26
Calc HMAC: CytnudYGnnaNi~otQn73QQ==
Read HMAC: QxilyEvZTFIY1M3vknNxyw==
Using key: Ejpn~JCwcREkqLRmlTj2TW6Sra12ZOWeZspIUaqDHKI= (Session)
Raw: QxilyEvZTFIY1M3vknNxywwn4jNuAQSAodHDzGy5m1jfawALt0okNBzRB9eVUsQOGpBLBWOdYwkEQw==
java.lang.Exception
at net.i2p.router.transport.udp.UDPPacket.validate(UDPPacket.java:314)
at net.i2p.router.transport.udp.PacketHandler.validate(PacketHandler.java:191)
at net.i2p.router.transport.udp.PacketHandler.access$700(PacketHandler.java:30)
at net.i2p.router.transport.udp.PacketHandler$Handler.receivePacket(PacketHandler.java:348)
at net.i2p.router.transport.udp.PacketHandler$Handler.handlePacket(PacketHandler.java:275)
at net.i2p.router.transport.udp.PacketHandler$Handler.run(PacketHandler.java:219)
at java.base/java.lang.Thread.run(Thread.java:833)
at net.i2p.util.I2PThread.run(I2PThread.java:103)
Oct 4, 2022, 12:55:43 PM INFO [ handler 1/1] router.transport.udp.UDPPacket:
Current HMAC validation is invalid, isIPv6: true;
Overall HMAC validation stats: Good IPv4: 0; Failed IPv4: 39; Good IPv6: 0; Failed IPv6: 9; Total Validated: 48
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] er.transport.udp.PacketHandler: Evaluating packet: _enableSSU2: true; (peerType == PeerType.NEW_PEER) is: true; packet length: 58; SSU2Util.MIN_TOKEN_REQUEST_LEN: 56
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] er.transport.udp.PacketHandler: Attempting to handle packet as SSU2...
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] er.transport.udp.PacketHandler:
receiveSSU2Packet/trialDecryptHandshakeHeader: header is null.
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] er.transport.udp.PacketHandler:
receiveSSU2Packet/trialDecryptLongHeader: getVersion: 76; NetID match: false
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] er.transport.udp.PacketHandler:
Continuing with SSU1 fallback processing, wasn't an SSU2 packet from [fd40:39b0:31ab:0:0:0:0:118]:28118
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] er.transport.udp.PacketHandler:
Adding host to _failCache(size = 4): [fd40:39b0:31ab:0:0:0:0:118]:28118
Oct 4, 2022, 12:55:43 PM WARN [ handler 1/1] er.transport.udp.PacketHandler:
Cannot validate rcvd pkt (path) wasCached? false: 58 byte pkt with [fd40:39b0:31ab:0:0:0:0:118]:28118 priority=300 sinceEnqueued=0 sinceReceived=0
Here's Peer 2's (fd40:39b0:31ab:0:0:0:0:118) log excerpt:
Oct 4, 2022, 12:55:43 PM INFO [DPReceiver 1] uter.transport.udp.UDPReceiver: After blocking socket.receive: packet is 71 bytes on 1756740512
Oct 4, 2022, 12:55:43 PM INFO [DPReceiver 1] uter.transport.udp.UDPReceiver: Received: 71 byte pkt with [fd40:39b0:31ab:0:0:0:0:101]:20101 priority=100
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] outer.transport.udp.PeerState2: New 71 byte pkt 3 rcvd on [fd40:39b0:31ab:0:0:0:0:101]:20101 fcx35P IB2 recvAge: 20m sendAge: 20m sendAttemptAge: 20m sendACKAge: 20m lifetime: 20m RTT: 150 RTTdev: 64 RTO: 1000 MTU: 1280 LMTU: 1488 cwin: 4870 acwin: 4870 SST: 524288 FRTX? false consecFail: 0 msgs rcvd: 1 msgs sent: 1 pkts rcvd OK/Dup: 2/0 pkts sent OK/Dup: 1/0 IBM: 0 OBQ: 0 OBL: 0
Oct 4, 2022, 12:55:43 PM INFO [ handler 1/1] outer.transport.udp.PeerState2:
Got TERMINATION block, reason: 2 count: 2 on [fd40:39b0:31ab:0:0:0:0:101]:20101 fcx35P IB2
recvAge: 20m sendAge: 20m sendAttemptAge: 20m sendACKAge: 20m lifetime: 20m
RTT: 150 RTTdev: 64 RTO: 1000 MTU: 1280 LMTU: 1488 cwin: 4870 acwin: 4870 SST: 524288
FRTX? false consecFail: 0 msgs rcvd: 1 msgs sent: 1 pkts rcvd OK/Dup: 2/0 pkts sent
OK/Dup: 1/0 IBM: 0 OBQ: 0 OBL: 0
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] r.transport.udp.PacketBuilder2:
Sending termination 1 to : [fd40:39b0:31ab:0:0:0:0:101]:20101 fcx35P IB2
recvAge: 20m sendAge: 20m sendAttemptAge: 20m sendACKAge: 20m lifetime: 20m RTT: 150 RTTdev: 64 RTO: 1000
MTU: 1280 LMTU: 1488 cwin: 4870 acwin: 4870 SST: 524288 FRTX? false consecFail: 0 msgs rcvd: 1 msgs sent: 1
pkts rcvd OK/Dup: 2/0 pkts sent OK/Dup: 1/0 IBM: 0 OBQ: 0 OBL: 0
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] r.transport.udp.PacketBuilder2:
Sending acks ACK 3-0 to [fd40:39b0:31ab:0:0:0:0:101]:20101 fcx35P IB2 recvAge: 20m sendAge: 20m
sendAttemptAge: 20m sendACKAge: 0ms lifetime: 20m RTT: 150 RTTdev: 64 RTO: 1000 MTU: 1280 LMTU: 1488
cwin: 4870 acwin: 4870 SST: 524288 FRTX? false consecFail: 0 msgs rcvd: 1 msgs sent: 1 pkts rcvd
OK/Dup: 2/0 pkts sent OK/Dup: 1/0 IBM: 0 OBQ: 0 OBL: 0
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] router.transport.udp.UDPSender:
Added the packet onto the queue with a lifetime of 0
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] sport.udp.EstablishmentManager:
Receive session destroy (EST) from: [fd40:39b0:31ab:0:0:0:0:101]:20101
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] t.udp.OutboundMessageFragments:
Dropping peer [Hash: fcx35PWB14EJqLcpMI~N87zBTZ961nj7RKluAC19iis=]
Oct 4, 2022, 12:55:43 PM DEBUG [UDPSender 1 ] router.transport.udp.UDPSender:
Packet to send known: 58 byte pkt with [fd40:39b0:31ab:0:0:0:0:101]:20101
priority=100 msgType=74 markType=1 sinceEnqueued=0
Oct 4, 2022, 12:55:43 PM DEBUG [UDPSender 1 ] router.transport.udp.UDPSender: Sent the packet 58 byte pkt with [fd40:39b0:31ab:0:0:0:0:101]:20101 priority=100 msgType=74 markType=1 sinceEnqueued=0
Notice here when Peer 1 is attempting to decrypt the incoming acknowledgement:
Oct 4, 2022, 12:55:43 PM DEBUG [ handler 1/1] er.transport.udp.PacketHandler: receiveSSU2Packet/trialDecryptLongHeader: getVersion: 76; NetID match: false
getVersion should be "2". In other examples, I find this value is all over the place, as if the decryption is just generating garbage.
Apologies for the extra long discussion. I hope you can do something with it.