Opened 6 years ago

Closed 3 years ago

#996 closed defect (fixed)

java.lang.NullPointerException: invalid args to aes

Reported by: tyro Owned by: zzz
Priority: major Milestone: 0.9.29
Component: router/transport Version: 0.9.7
Keywords: Cc: zab@…
Parent Tickets: Sensitive: no

Description

I2P version: 0.9.7-16
Java version: Oracle Corporation 1.8.0-ea (Java™ SE Runtime Environment 1.8.0-ea-b100)
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

Using latest JVM (ARM preview for Pi).

02/08/13 07:58:40 CRIT [P writer 4/4] p.router.transport.ntcp.Writer: Error in the ntcp writer

java.lang.NullPointerException?: invalid args to aes
at net.i2p.crypto.CryptixAESEngine.encrypt(CryptixAESEngine.java:86)
at net.i2p.router.transport.ntcp.NTCPConnection.sendMeta(NTCPConnection.java:1294)
at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:699)
at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:578)
at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:122)
at java.lang.Thread.run(Thread.java:724)
at net.i2p.util.I2PThread.run(I2PThread.java:85)

Subtickets

Change History (23)

comment:1 Changed 6 years ago by zzz

Component: unspecifiedrouter/transport
Owner: set to Zlatin Balevsky
Priority: minormajor
Status: newassigned

Hmm. Haven't seen this before. Could be the RPi ARM Java chaos monkey…

_meta and encrypted can't be null, so that leaves _sessionKey and _prevWriteEnd.

Those are set in synchronized methods finishInboundEstablishment() and finishOutboundEstablishment(). Perhaps block in sendMeta() should be synched on this instead of _meta? Or both? But I don't think sendMeta() could be called before finishXXXEstablishment() is called? So maybe could be fixed by volatile or synch.

Or is it somehow related to VerifiedEstablishState????

Hoping zab can continue the chase from here.

comment:2 Changed 6 years ago by Zlatin Balevsky

NTCPConnection.prepareNextWrite(..) is already synchronized on NTCPConnection. The only way this stack trace is possible is if finish{Inbound,Outbound}Establishment is not yet called. Or there is indeed something wrong with the ARM jvm.

comment:3 Changed 6 years ago by Zlatin Balevsky

Cc: zab@… added

comment:4 Changed 6 years ago by DISABLED

Resolution: worksforme
Status: assignedclosed

comment:5 Changed 6 years ago by str4d

Resolution: worksforme
Status: closedreopened

comment:6 Changed 6 years ago by DISABLED

Resolution: not a bug
Status: reopenedclosed

comment:7 Changed 6 years ago by str4d

Resolution: not a bug
Status: closedreopened

comment:8 Changed 6 years ago by zzz

Milestone: 0.9.8
Resolution: worksforme
Status: reopenedclosed

assuming a JVM issue

comment:9 Changed 6 years ago by killyourtv

FWIW, I've also (finally) gotten this.

I2P version: 0.9.8.1-0
Java version: Oracle Corporation 1.8.0-ea (Java(TM) SE Runtime Environment 1.8.0-ea-b109)
Wrapper version: 3.5.20
Server version: 7.6.12.v20130726
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
23/10/13 15:07:44 CRIT [P writer 1/4] p.router.transport.ntcp.Writer: Error in the ntcp writer
     java.lang.NullPointerException: invalid args to aes
     at net.i2p.crypto.CryptixAESEngine.encrypt(CryptixAESEngine.java:86)
     at net.i2p.router.transport.ntcp.NTCPConnection.sendMeta(NTCPConnection.java:1321)
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:728)
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:607)
     at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:122)
     at java.lang.Thread.run(Thread.java:724)
     at net.i2p.util.I2PThread.run(I2PThread.java:85)

Raspberry Pi, Model B w/ 512 MB of RAM

comment:10 Changed 6 years ago by zzz

Resolution: worksforme
Status: closedreopened

Also on RPI. hmm.

Reopening, worth another look.

comment:11 Changed 6 years ago by killyourtv

That error was logged once more on the 3rd with an identical traceback. At this point that RaPI router has been up for ~27 days.

comment:12 Changed 6 years ago by zzz

Again reported in #1225, again on RPi.

comment:13 Changed 6 years ago by zzz

Tweaked the logging in 0.9.12-5 to help get to the bottom of this

comment:14 Changed 5 years ago by zzz

Milestone: 0.9.13
Owner: changed from Zlatin Balevsky to zzz
Status: reopenedaccepted

Unrelated ticket #1271 has this NPE on -15 on x86. see 3rd line of wrapper log there. The null parameter is the Session Key. The meta is being sent before the session is established. The fix will be to initialize _nextMetaTime to Long.MAX_VALUE.

comment:15 Changed 5 years ago by zzz

Status: acceptedtesting

Hopefully fixed in da96b33d4dd0fbda966d594ac591f7cd97f76d21 to be 0.9.12-16

comment:16 Changed 5 years ago by killyourtv

Status: testingneeds_work

On my Raspberry Pi:

I2P version: 0.9.13-0
Java version: Oracle Corporation 1.7.0_40 (Java(TM) SE Runtime Environment 1.7.0_40-b43)
Wrapper version: 3.5.22
Server version: 8.1.14.v20131031
Servlet version: Jasper JSP 2.1 Engine
Platform: Linux arm 3.10.30+
Processor: uninitialized (arm)
Jbigi: Locally optimized native BigInteger library loaded from file
Encoding: UTF-8
Charset: UTF-8
01/06/14 22:29:05 CRIT [P writer 3/4] p.router.transport.ntcp.Writer: Error in the ntcp writer on NTCP conn to DhZWxZ created 3018ms ago, last send 3018ms ago, last recv 3018ms ago, sent 0, rcvd 0
     java.lang.NullPointerException: invalid args to aes - sessionKey
     at net.i2p.crypto.CryptixAESEngine.encrypt(CryptixAESEngine.java:89)
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:796)
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:622)
     at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:129)
     at java.lang.Thread.run(Thread.java:724)
     at net.i2p.util.I2PThread.run(I2PThread.java:84)

comment:17 Changed 5 years ago by zzz

Milestone: 0.9.130.9.14
Status: needs_workaccepted

Interesting. A different case that wasn't fixed, as it's coming from prepareNextWriteFast(), not sendMeta().

comment:18 Changed 5 years ago by killyourtv

I2P version: 0.9.14.1-0
Java version: Oracle Corporation 1.7.0_40 (Java(TM) SE Runtime Environment 1.7.0_40-b43)
Wrapper version: 3.5.25
Server version: 8.1.15.v20140411
Servlet version: Jasper JSP 2.1 Engine
Platform: Linux arm 3.12.26+
Processor: uninitialized (arm)
Jbigi: Locally optimized native BigInteger library loaded from file
Encoding: UTF-8
Charset: UTF-8
14/09/14 05:56:11 CRIT [P writer 2/4] p.router.transport.ntcp.Writer: Error in the ntcp writer on NTCP conn to 98tQvZ created 1939ms ago, last send 1939ms ago, last recv 1939ms ago, sent 0, rcvd 0
     java.lang.NullPointerException: invalid args to aes - sessionKey
     at net.i2p.crypto.CryptixAESEngine.encrypt(CryptixAESEngine.java:115)
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:796)
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:622)
     at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:129)
     at java.lang.Thread.run(Thread.java:724)
     at net.i2p.util.I2PThread.run(I2PThread.java:84)

comment:19 Changed 5 years ago by str4d

I2P version: 0.9.15-0
Java version: Oracle Corporation 1.7.0_65 (OpenJDK Runtime Environment 1.7.0_65-b32)
Wrapper version: 3.1.1
Server version: 8.1.15.v20140411
Servlet version: Jasper JSP 2.1 Engine
Platform: Linux i386 3.15.4-x86_64-linode45
Processor: uninitialized (unrecognized)
Jbigi: Locally optimized native BigInteger library loaded from file
Encoding: ANSI_X3.4-1968
Charset: US-ASCII
23:49:51 | CRIT  [P writer 1/4] p.router.transport.ntcp.Writer: Error in the ntcp writer on NTCP conn to pby3Rs created 6s ago, last send 6s ago, last recv 10ms ago, sent 0, rcvd 1
23:49:51 | java.lang.NullPointerException: invalid args to aes - sessionKey
23:49:51 | 	at net.i2p.crypto.CryptixAESEngine.encrypt(CryptixAESEngine.java:115)
23:49:51 | 	at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:796)
23:49:51 | 	at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:622)
23:49:51 | 	at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:129)
23:49:51 | 	at java.lang.Thread.run(Thread.java:745)
23:49:51 | 	at net.i2p.util.I2PThread.run(I2PThread.java:84)
00:40:42 | CRIT  [P writer 4/4] p.router.transport.ntcp.Writer: Error in the ntcp writer on NTCP conn to j9ukcz created 2256ms ago, last send 2256ms ago, last recv 2256ms ago, sent 0, rcvd 0
00:40:42 | java.lang.NullPointerException: invalid args to aes - sessionKey
00:40:42 | 	at net.i2p.crypto.CryptixAESEngine.encrypt(CryptixAESEngine.java:115)
00:40:42 | 	at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:796)
00:40:42 | 	at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:622)
00:40:42 | 	at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:129)
00:40:42 | 	at java.lang.Thread.run(Thread.java:745)
00:40:42 | 	at net.i2p.util.I2PThread.run(I2PThread.java:84)
01:24:20 | JVM appears hung: Timed out waiting for signal from JVM.
01:24:21 | JVM did not exit on request, terminated
01:24:35 | Launching a JVM...
01:24:36 | OpenJDK Server VM warning: You have loaded library /home/i2p/bin/i2p/lib/libwrapper.so which might have disabled stack guard. The VM will try to fix the stack guard now.
01:24:36 | It's highly recommended that you fix the library with 'execstack -c <libfile>', or link it with '-z noexecstack'.
01:24:36 | Wrapper (Version 3.1.1) http://wrapper.tanukisoftware.org

comment:20 Changed 5 years ago by dg

Observed on 0.9.15. Not RPi. x86_64.

CRIT [P writer 1/4] p.router.transport.ntcp.Writer: Error in the ntcp writer on NTCP conn to REMOVED created 138ms ago, last send 138ms ago, last recv 138ms ago, sent 0, rcvd 0
     java.lang.NullPointerException: invalid args to aes - sessionKey
     at net.i2p.crypto.CryptixAESEngine.encrypt(CryptixAESEngine.java:115)
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWriteFast(NTCPConnection.java:796)
     at net.i2p.router.transport.ntcp.NTCPConnection.prepareNextWrite(NTCPConnection.java:622)
     at net.i2p.router.transport.ntcp.Writer$Runner.run(Writer.java:129)
     at java.lang.Thread.run(Thread.java:745)
     at net.i2p.util.I2PThread.run(I2PThread.java:84)
Last edited 5 years ago by dg (previous) (diff)

comment:21 Changed 5 years ago by str4d

Milestone: 0.9.14

comment:22 Changed 3 years ago by zzz

Milestone: 0.9.29

NTCPConnection.prepareNextWriteFast() only checks for !isEstablished() for outbound conns. But we don't have a session key unless established, either for inbound or outbound. Looks like a race. Will test checking for established for inbound conns too.

comment:23 Changed 3 years ago by zzz

Resolution: fixed
Status: acceptedclosed
Note: See TracTickets for help on using tickets.