Opened 6 years ago

Closed 4 years ago

#1094 closed defect (no response)

Error in the ntcp reader: java.lang.NullPointerException

Reported by: xmz Owned by: Zlatin Balevsky
Priority: minor Milestone:
Component: router/transport Version: 0.9.8.1
Keywords: bsd ntcp race Cc: Zlatin Balevsky, zzz
Parent Tickets: Sensitive: no

Description

As reported in #i2p:

I2P version: 0.9.8.1-0
Java version: Sun Microsystems Inc. 1.6.0_32 (OpenJDK Runtime Environment 1.6.0_32-b27)
Wrapper version: 3.5.19
Server version: 7.6.12.v20130726
Servlet version: Jasper JSP 2.1 Engine
Platform: FreeBSD amd64 9.1-RELEASE
Processor: uninitialized (pentiummmx)
Jbigi: Locally optimized native BigInteger? library loaded from file
Encoding: ISO8859-1
Charset: ISO-8859-1

<xmz> so my i2p relay has been sitting underutilized ever since uprading to 0.9.8.1. it was near full capacity before the upgrade
<xmz> it has been running for 3 weeks
<+eche|on> when did ypu upgrade?
<xmz> 3 weeks ago
<+eche|on> uhh
<+dg> xmz: build more tunnels
<+dg> snark, etc
<+eche|on> it should run fine, anything in the logs? restarted?
<+dg> it needs to reintegrate 
<xmz> pre upgrade bandwidth utilization was 100kb/s+ with thousands of participating tunnels. now it rarely passes 100kb/s with less than 100 tunnels
    10/19/13 2:54:30 PM CRIT [P reader 1/4] p.router.transport.ntcp.Reader: Error in the ntcp reader
         java.lang.NullPointerException
         at net.i2p.router.transport.ntcp.EstablishState.toString(EstablishState.java:731)
         at java.lang.String.valueOf(String.java:2838)
         at java.lang.StringBuilder.append(StringBuilder.java:132)
         at net.i2p.router.transport.ntcp.Reader.processRead(Reader.java:151)
         at net.i2p.router.transport.ntcp.Reader.access$400(Reader.java:21)
         at net.i2p.router.transport.ntcp.Reader$Runner.run(Reader.java:118)
         at java.lang.Thread.run(Thread.java:679)
         at net.i2p.util.I2PThread.run(I2PThread.java:85)
    10/17/13 11:21:51 PM CRIT [uterWatchdog] et.i2p.router.tasks.ThreadDump: Threads dumped to wrapper log
    10/17/13 11:21:51 PM CRIT [uterWatchdog] 2p.router.tasks.RouterWatchdog: Router appears hung, or there is severe network congestion. Watchdog starts barking!
    10/17/13 11:21:51 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Memory: 35.32M/910.25M
    10/17/13 11:21:51 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Outbound send rate: 38206.35333160073 Bps
    10/17/13 11:21:51 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: 1minute send processing time: 389.6830631734273
    10/17/13 11:21:51 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Participating tunnel count: 19
    10/17/13 11:21:51 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Job lag: 0
    10/17/13 11:21:51 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Ready and waiting jobs: 0
    10/17/13 11:21:51 PM ERROR [uterWatchdog] client.ClientManagerFacadeImpl: Client cf5HCD has a leaseSet that expired 10m
    10/11/13 8:10:18 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Memory: 40.12M/910.25M
    10/11/13 8:10:18 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Outbound send rate: 26006.33676824819 Bps
    10/11/13 8:10:18 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: 1minute send processing time: 176.0735426154657
    10/11/13 8:10:18 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Participating tunnel count: 39
    10/11/13 8:10:18 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Job lag: 0
    10/11/13 8:10:18 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Ready and waiting jobs: 0
    10/11/13 8:10:18 PM ERROR [uterWatchdog] client.ClientManagerFacadeImpl: Client cf5HCD has a leaseSet that expired 13m
    10/11/13 8:09:18 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Memory: 42.94M/910.25M
    10/11/13 8:09:18 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: Outbound send rate: 25042.330951072017 Bps
    10/11/13 8:09:18 PM ERROR [uterWatchdog] 2p.router.tasks.RouterWatchdog: 1minute send processing time: 273.68117247671444

Also http://pastethis.i2p/show/6083/
http://pastethis.i2p/show/6084/
http://pastethis.i2p/show/6085/

Subtickets

Change History (8)

comment:1 Changed 6 years ago by zzz

Owner: changed from zzz to Zlatin Balevsky
Priority: minormajor
Status: newassigned

comment:2 Changed 6 years ago by zzz

Priority: majorminor

actually, the exception is caught in the Reader run loop, so changing it back to minor. I don't think it's related to any tunnel issues. But I didn't look at the pastethis pastes…

comment:3 Changed 6 years ago by Zlatin Balevsky

Cc: Zlatin Balevsky zzz added
Keywords: NTCP added

Revision 78e62d4bb94b82cd611eae4d8ca5b45f28e68ee3 will cure the NPE; however the underlying problem is a race condition of some kind. NTCPConnection.isEstablished() vs. EstablishState.isComplete(). Finding out exactly what is going on will require further research.

comment:4 Changed 6 years ago by killyourtv

Reporter: changed from killyourtv to xmz

Setting reporter to xmz since that account now exists.

comment:5 Changed 6 years ago by Gendalph

Running on Raspbian @Java 8
Logs: http://trac.i2p2.i2p/ticket/1094

It looks like this causes significant increase in CPU load - the day before (uptime - 4d) this happening LA was around 0.4-0.7 and now, the day after (uptime - 6d), it's 1.8-2

comment:6 in reply to:  5 Changed 6 years ago by killyourtv

Replying to Gendalph:

Running on Raspbian @Java 8
Logs: http://trac.i2p2.i2p/ticket/1094

Do you have logs from when you had the problem?

comment:7 Changed 5 years ago by str4d

Keywords: bsd ntcp race added; FreeBSD NTCP removed
Milestone: 0.9.9
Status: assignedinfoneeded

comment:8 Changed 4 years ago by zzz

Resolution: no response
Status: infoneededclosed
Note: See TracTickets for help on using tickets.