Opened 9 years ago

Last modified 6 years ago

#392 assigned defect

] p.router.transport.ntcp.Writer: Error in the ntcp writer

Reported by: Eche|on Owned by: zzz
Priority: minor Milestone:
Component: router/transport Version: 0.8.2
Keywords: NTCP Cc:
Parent Tickets: Sensitive: no

Description

20:19:42.421 CRIT [P writer 2/4] p.router.transport.ntcp.Writer: Error in the ntcp writer

java.lang.RuntimeException?: buf is null for contains *no message* expiring on Sat Jan 22 19:19:51 GMT 2011 failed delivery on transports [NTCP? targetting UudgZDDzFwNSuF0W7AML0x34ijSknCGXDq56AjlNUJg= {timestamps:
}]
at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:631)
at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:461)
at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:115)
at java.lang.Thread.run(Thread.java:619)
at net.i2p.util.I2PThread.run(I2PThread.java:77)

18:17:14.649 CRIT [P writer 2/4] p.router.transport.ntcp.Writer: Error in the ntcp writer

java.lang.RuntimeException?: buf is null for contains *no message* expiring on Sat Jan 22 17:17:24 GMT 2011 failed delivery on transports [NTCP? targetting UudgZDDzFwNSuF0W7AML0x34ijSknCGXDq56AjlNUJg= {timestamps:
}]
at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:631)
at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:461)
at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:115)
at java.lang.Thread.run(Thread.java:619)
at net.i2p.util.I2PThread.run(I2PThread.java:77)

21:48:03.151 CRIT [P writer ¾] p.router.transport.ntcp.Writer: Error in the ntcp writer

java.lang.RuntimeException?: buf is null for contains *no message* expiring on Fri Jan 21 20:48:12 GMT 2011 failed delivery on transports [NTCP? targetting UudgZDDzFwNSuF0W7AML0x34ijSknCGXDq56AjlNUJg= {timestamps:
}]
at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:631)
at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:461)
at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:115)
at java.lang.Thread.run(Thread.java:619)
at net.i2p.util.I2PThread.run(I2PThread.java:77)

Subtickets

Change History (7)

comment:1 Changed 9 years ago by sponge

Seen same here…

CRIT [P writer 4/4] p.router.transport.ntcp.Writer: Error in the ntcp writer
java.lang.RuntimeException?: buf is null for [OutNetMessage? contains *no message* expiring on …
}]

at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:634)
at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:464)
at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:115)
at java.lang.Thread.run(Unknown Source)
at net.i2p.util.I2PThread.run(I2PThread.java:77)

comment:2 Changed 8 years ago by slow

Version: 0.8.20.8.10

Same error on 0.8.10-0.

some_time CRIT [P writer 2/4] p.router.transport.ntcp.Writer: Error in the ntcp writer
     java.lang.RuntimeException: buf is null for [OutNetMessage containing *no message* expiring on Sat Oct 22 03:23:32 GMT 2011 failed delivery on transports [NTCP] targetting abg-vXuZchSR16i-YQ11fFHVSedAwFxxsMTDgg6SA2M=]
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:634)
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:464)
     at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:115)
     at java.lang.Thread.run(Thread.java:619)
     at net.i2p.util.I2PThread.run(I2PThread.java:85)

comment:3 Changed 8 years ago by zzz

Priority: majorminor
Status: newassigned
Version: 0.8.100.8.2

There's some sort of race here. Since the toString is "no message" that means OutNetMessage?.discardData() has been called (from TransportImpl?.afterSend()), which means most likely it was sent on one transport then is being retried in the other.

The other possibility is a race with NTCPConnection.close(), which calls msg.releasePreparationBuffer(), which is not synchronized. Even if it were synchronized, close() calls afterSend() which nulls out the message.

Part of the problem also is the horrible fake priority queue scanning of _outbound just above line 634 which makes some of these races possible.

This definitely needs work. In the meantime changing the log from CRIT to WARN as it only affects the one message. Also changing the version back to 0.8.2 as reported by the OP.

Also changing to minor as it's just one message and very rare.

comment:4 Changed 8 years ago by str4d

Milestone: 0.8.120.8.14

comment:5 Changed 7 years ago by zzz

Milestone: 0.8.14

Milestone 0.8.14 deleted

comment:6 Changed 7 years ago by str4d

Keywords: NTCP added

comment:7 Changed 6 years ago by str4d

Related: #565 (failing on both SSU and NTCP)

Note: See TracTickets for help on using tickets.