Opened 6 years ago

Closed 5 years ago

Last modified 5 years ago

#983 closed defect (fixed)

[I2PSnark]: client.streaming.PacketHandler: Received a packet on the wrong stream

Reported by: guest Owned by:
Priority: minor Milestone: 0.9.12
Component: streaming Version: 0.9.7
Keywords: Cc: zab
Parent Tickets:

Description (last modified by zzz)

Hi!

I am running I2P and I2PSnark on a Raspberry Pi using the Java 8 ARM preview. After adding a torrent (though I am not sure this problem happened as a result), I noticed peers were unable to be reached in Snark (0/1 peers, 0 peers, etc). Following this occurrence with a few torrents, I checked out /logs and noticed the errors pasted below.

I think I've XXXX'd out everything of any importance (maybe it was all safe anyway; I'm cautious.) Hopefully none was left & none of it was required. If it is, let me know and I'll see what I can do. I will gladly answer any other questions you may have which could help.

/logs, version etc:

I2P version: 0.9.7-0
Java version: Oracle Corporation 1.8.0-ea (Java(TM) SE Runtime Environment 1.8.0-ea-b36e)
Wrapper version: 3.5.17
Server version: 7.6.11.v20130520
Servlet version: Jasper JSP 2.1 Engine
Platform: Linux arm 3.6.11+
Processor: uninitialized (arm)
Jbigi: Locally optimized native BigInteger? library loaded from file
Encoding: UTF-8
Charset: UTF-8

I am running with this setting in wrapper.config:
wrapper.java.additional.5=-Di2p.streaming.initialRTT=3000

/logs output:

19/07/13 14:39:46 ERROR [[I2PSnark]: ] client.streaming.PacketHandler: Received a packet on the wrong stream: XXXXXXXXXXXXXXX: #2 CLOSE DELAY 0 SIG ACK 0
     this connection:
     [Connection XXXXXXXXXXXXXXXXX to XXXX up 26s wsize: 1 cwin: 1 rtt: 4558 rto: 21522 unacked out: 1 unacked in: 0 close sent 9s ago close received 3180ms ago sent: 2 rcvd: 3 ackThru 0 maxWin 128 MTU 1730]
     all connections:
     [Connection XXXXXXX/XXXXXXX from XXXX up 83m wsize: 4 cwin: 2 rtt: 12204 rto: 34524 unacked out: 1 unacked in: 0 sent: 293 rcvd: 243 ackThru 291 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 7h wsize: 6 cwin: 6 rtt: 4444 rto: 14728 unacked out: 1 unacked in: 0 sent: 2100 rcvd: 12838 ackThru 2098 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 4h wsize: 2 cwin: 5 rtt: 1594 rto: 2586 unacked out: 3 unacked in: 0 sent: 3977 rcvd: 30667 ackThru 3973 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 10m wsize: 4 cwin: 3 rtt: 19610 rto: 45000 unacked out: 0 unacked in: 0 sent: 46 rcvd: 35 ackThru 45 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 3m wsize: 2 cwin: 1 rtt: 4030 rto: 12430 unacked out: 0 unacked in: 1 close sent 3m ago close received 3m ago sent: 2 rcvd: 2 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 28s wsize: 2 cwin: 1 rtt: 3586 rto: 12074 unacked out: 0 unacked in: 1 close sent 27s ago close received 27s ago sent: 2 rcvd: 2 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 26s wsize: 1 cwin: 1 rtt: 4558 rto: 21522 unacked out: 1 unacked in: 0 close sent 9s ago close received 3227ms ago sent: 2 rcvd: 3 ackThru 0 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 7h wsize: 4 cwin: 2 rtt: 9816 rto: 21040 unacked out: 1 unacked in: 0 sent: 2975 rcvd: 1764 ackThru 2973 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 16h wsize: 1 cwin: 1 rtt: 3333 rto: 7405 unacked out: 5 unacked in: 0 sent: 29303 rcvd: 64761 ackThru 29297 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 9h wsize: 1 cwin: 1 rtt: 4092 rto: 18064 unacked out: 1 unacked in: 0 sent: 13253 rcvd: 22913 ackThru 13251 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 71s wsize: 2 cwin: 1 rtt: 2823 rto: 7411 unacked out: 0 unacked in: 0 reset sent 63s ago sent: 2 rcvd: 2 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 14h wsize: 3 cwin: 2 rtt: 4221 rto: 8281 unacked out: 1 unacked in: 0 sent: 22418 rcvd: 40342 ackThru 22416 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 56s wsize: 2 cwin: 1 rtt: 3736 rto: 11760 unacked out: 0 unacked in: 1 close sent 54s ago close received 54s ago sent: 2 rcvd: 4 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 91m wsize: 2 cwin: 2 rtt: 12992 rto: 45000 unacked out: 1 unacked in: 0 sent: 361 rcvd: 603 ackThru 359 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 72s wsize: 2 cwin: 1 rtt: 3866 rto: 11394 unacked out: 0 unacked in: 1 close sent 71s ago close received 71s ago sent: 2 rcvd: 2 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 16m wsize: 5 cwin: 5 rtt: 3785 rto: 13441 unacked out: 5 unacked in: 0 [1 missing] sent: 1025 rcvd: 715 ackThru 1019 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 7h wsize: 4 cwin: 1 rtt: 6130 rto: 12230 unacked out: 0 unacked in: 0 sent: 1735 rcvd: 9435 ackThru 1734 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 16h wsize: 2 cwin: 2 rtt: 11905 rto: 28309 unacked out: 1 unacked in: 0 sent: 19436 rcvd: 5168 ackThru 19434 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 3m wsize: 2 cwin: 2 rtt: 4443 rto: 12651 unacked out: 0 unacked in: 1 close sent 3m ago close received 3m ago sent: 2 rcvd: 2 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 12h wsize: 14 cwin: 10 rtt: 12551 rto: 34439 unacked out: 0 unacked in: 0 sent: 16624 rcvd: 3793 ackThru 16623 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 12m wsize: 3 cwin: 3 rtt: 12644 rto: 45000 unacked out: 1 unacked in: 0 sent: 125 rcvd: 50 ackThru 123 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 8h wsize: 5 cwin: 3 rtt: 11058 rto: 27890 unacked out: 1 unacked in: 0 sent: 18850 rcvd: 34027 ackThru 18848 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 3m wsize: 2 cwin: 1 rtt: 4032 rto: 11692 unacked out: 0 unacked in: 1 close sent 3m ago close received 3m ago sent: 2 rcvd: 2 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 11h wsize: 3 cwin: 3 rtt: 14234 rto: 45000 unacked out: 1 unacked in: 0 sent: 4347 rcvd: 4426 ackThru 4345 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 65s wsize: 2 cwin: 1 rtt: 2784 rto: 7700 unacked out: 0 unacked in: 0 reset sent 60s ago sent: 2 rcvd: 2 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 142s wsize: 2 cwin: 1 rtt: 4106 rto: 10502 unacked out: 0 unacked in: 1 close sent 140s ago close received 139s ago sent: 2 rcvd: 2 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 4h wsize: 12 cwin: 12 rtt: 11350 rto: 15738 unacked out: 12 unacked in: 0 sent: 9349 rcvd: 1942 ackThru 9336 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 16h wsize: 4 cwin: 3 rtt: 5255 rto: 14703 unacked out: 0 unacked in: 0 sent: 17950 rcvd: 35814 ackThru 17949 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX from XXXX up 86m wsize: 4 cwin: 4 rtt: 3302 rto: 10730 unacked out: 4 unacked in: 0 sent: 854 rcvd: 1038 ackThru 849 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 4m wsize: 1 cwin: 1 rtt: 10786 rto: 38006 unacked out: 0 unacked in: 1 close sent 3m ago close received 3m ago sent: 2 rcvd: 2 ackThru 1 maxWin 128 MTU 1730]
     [Connection XXXXXXX/XXXXXXX to XXXX up 4m wsize: 2 cwin: 2 rtt: 4598 rto: 13062 unacked out: 0 unacked in: 1 close sent 3m ago close received 3m ago sent: 2 rcvd: 3 ackThru 1 maxWin 128 MTU 1730]
     java.lang.Exception: Wrong stream
     at net.i2p.client.streaming.PacketHandler.receiveKnownCon(PacketHandler.java:221)
     at net.i2p.client.streaming.PacketHandler.receivePacketDirect(PacketHandler.java:106)
     at net.i2p.client.streaming.PacketHandler.receivePacket(PacketHandler.java:93)
     at net.i2p.client.streaming.MessageHandler.messageAvailable(MessageHandler.java:67)
     at net.i2p.client.I2PSessionDemultiplexer.messageAvailable(I2PSessionDemultiplexer.java:39)
     at net.i2p.client.I2PSessionMuxedImpl$MuxedAvailabilityNotifier.run(I2PSessionMuxedImpl.java:353)
     at java.lang.Thread.run(Thread.java:722)
     at net.i2p.util.I2PThread.run(I2PThread.java:85)

Subtickets

Change History (5)

comment:1 Changed 6 years ago by zzz

  • Cc zab added
  • Component changed from unspecified to streaming
  • Description modified (diff)

Never ever seen this before.

comment:2 Changed 6 years ago by zzz

We could have races or other bugs with dup SYN handling. The problem could be at this end or the other end. Need to research.

More info from private email, removing some XX:

Received a packet on the wrong stream: 111111/222222: #2 CLOSE DELAY 0 SIG ACK 0

this connection:
[Connection 111111/333333 to XXXX up 26s wsize: 1 cwin: 1 rtt: 4558 rto: 21522 unacked out: 1 unacked in: 0 close sent 9s ago close received 3180ms ago sent: 2 rcvd: 3 ackThru 0 maxWin 128 MTU 1730]

Unfortunately the log doesn't say if the wrong stream packet was from the same place. So don't know if a different party w/ same ID or not. But probably not, since it was a CLOSE.

So looks like one conn with two IDs? For further research.

comment:3 Changed 6 years ago by zzz

Possibly related: #1043

comment:4 Changed 5 years ago by zzz

  • Milestone changed from 0.9.8 to 0.9.12
  • Resolution set to fixed
  • Status changed from new to closed

Hopefully fixed in 0.9.12 (see #1043)

comment:5 Changed 5 years ago by zzz

See dup #1161 for theory on root cause

Note: See TracTickets for help on using tickets.