Opened 6 months ago

Closed 5 months ago

#2739 closed defect (fixed)

Streaming pushBackRTO() error

Reported by: zzz Owned by: Zlatin Balevsky
Priority: minor Milestone: 0.9.46
Component: streaming Version: 0.9.45
Keywords: Cc:
Parent Tickets: Sensitive: no

Description

05/14 14:14:36.382 ERROR [t.i2p #17754] ient.streaming.impl.Connection: [Connection uCSoGQ/zK7AkQ from bjfsu2qpwozhynhwgwdq7i3bdmvjsxeiapedqmqd2k7xiaipwrca.b32.i2p up 4073ms wsize: 8 cwin: 6 rtt: 1738 rto: 4218 unacked out: 2 unacked in: 0 close sent 1818ms ago sent: 8 rcvd: 1 ackThru 5 ssThresh 64 minRTT 2253 maxWin 128 MTU 1730] timer was not scheduled
     java.lang.Exception
     at net.i2p.client.streaming.impl.Connection$RetransmitEvent.pushBackRTO(Connection.java:1461)
     at net.i2p.client.streaming.impl.Connection.ackPackets(Connection.java:588)
     at net.i2p.client.streaming.impl.ConnectionPacketHandler.ack(ConnectionPacketHandler.java:328)
     at net.i2p.client.streaming.impl.ConnectionPacketHandler.receivePacket(ConnectionPacketHandler.java:265)
     at net.i2p.client.streaming.impl.PacketHandler.receiveKnownCon(PacketHandler.java:163)
     at net.i2p.client.streaming.impl.PacketHandler.receivePacketDirect(PacketHandler.java:109)
     at net.i2p.client.streaming.impl.PacketHandler.receivePacket(PacketHandler.java:96)
     at net.i2p.client.streaming.impl.MessageHandler.messageAvailable(MessageHandler.java:80)
     at net.i2p.client.impl.I2PSessionDemultiplexer.messageAvailable(I2PSessionDemultiplexer.java:44)
     at net.i2p.client.impl.I2PSessionMuxedImpl$MuxedAvailabilityNotifier.run(I2PSessionMuxedImpl.java:411)
     at java.base/java.lang.Thread.run(Thread.java:834)
     at net.i2p.util.I2PThread.run(I2PThread.java:103)

79 occurrences in 11 days. Reduced to WARN in 0.9.45-21-rc but still needs investigating.

Subtickets

Change History (6)

comment:1 Changed 6 months ago by zzz

Owner: set to zlatinb
Status: newassigned

comment:2 Changed 6 months ago by Zlatin Balevsky

Owner: changed from zlatinb to Zlatin Balevsky

I will investigate, but if you still happen to have logs - are the stacktraces all the same? There are two possible paths to that method, and if the problem happens only on one of those it will point me in the right direction

comment:3 Changed 6 months ago by zzz

Approx. 68 were as in the OP;

however, 11 were as follows:

05/04 14:19:56.013 ERROR [mer xzpd 4/4] ient.streaming.impl.Connection: [Connection 0odYWw/Lk9Ejg from 5ysmpm4bw2cf3sdyss6eprumyj3jj7xzuh3runt2svbzn7a5nkqa.b32.i2p up 15s wsize: 13 cwin: 13 rtt: 3366 rto: 27340 unacked out: 1 unacked in: 1 close sent 14s ago close rcvd 13s ago sent: 8 rcvd: 2 ackThru 6 ssThresh 64 minRTT 859 maxWin 128 MTU 1730] timer was not scheduled
java.lang.Exception
	at net.i2p.client.streaming.impl.Connection$RetransmitEvent.pushBackRTO(Connection.java:1461)
	at net.i2p.client.streaming.impl.Connection$RetransmitEvent.timeReached(Connection.java:1482)
	at net.i2p.util.SimpleTimer2$TimedEvent.run2(SimpleTimer2.java:473)
	at net.i2p.util.SimpleTimer2$TimedEvent.run(SimpleTimer2.java:412)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	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:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)
Last edited 6 months ago by zzz (previous) (diff)

comment:4 Changed 6 months ago by Zlatin Balevsky

I was able to reproduce this. Seems like a textbook case of a race condition between receiving an ACK and sending a new packet at the same time.

The only fix I can think of is coarsening the lock on _outboundPackets to cover the operations over the _retransmitEvent. Below is a patch I'm currently testing, indentation not included for clarity.

diff --git a/apps/streaming/java/src/net/i2p/client/streaming/impl/Connection.java b/apps/streaming/java/src/net/i2p/client/streaming/impl/Connection.java
index 151ce2399..ea5c241c9 100644
--- a/apps/streaming/java/src/net/i2p/client/streaming/impl/Connection.java
+++ b/apps/streaming/java/src/net/i2p/client/streaming/impl/Connection.java
@@ -402,7 +402,6 @@ class Connection {
                 windowSize = _options.getWindowSize();
                 remaining = windowSize - _outboundPackets.size() ;
                 _outboundPackets.notifyAll();
-            }
 
             if (_isChoking) {
                 packet.setOptionalDelay(Packet.SEND_DELAY_CHOKE);
@@ -446,6 +445,7 @@ class Connection {
             }
 
             packet.setTimeout(timeout);
+            }
         }
 
         // warning, getStatLog() can be null
@@ -578,7 +578,6 @@ class Connection {
             }
             anyLeft = !_outboundPackets.isEmpty();
             _outboundPackets.notifyAll();
-        }
         if ((acked != null) && (!acked.isEmpty()) ) {
             _ackSinceCongestion.set(true);
             _bwEstimator.addSample(acked.size());
@@ -597,6 +596,7 @@ class Connection {
                 _retransmitEvent.cancel();
             }
         }
+        }
         return acked;
     }

comment:5 Changed 5 months ago by Zlatin Balevsky

After several hours of running with this patch I have only two occurrences of this log statement, both after the connection had been closed. There is a check against running the rtx event after _finalDisconnect.get() returns true, so it's not something to worry about.

comment:6 Changed 5 months ago by zzz

Milestone: undecided0.9.46
Resolution: fixed
Status: assignedclosed

run for 24 hours here on the same server as OP, zero occurrences

in d158ab09a79fe5c9b72040f6fb9a12c7bdb35dc7 0.9.45-24-rc

Note: See TracTickets for help on using tickets.