Opened 4 years ago

Closed 9 months ago

#1503 closed defect (fixed)

Unhandled error reading I2CP stream java.lang.NullPointerException at net.i2p.router.client.ClientMessageEventListener.handleCreateLeaseSet

Reported by: djjeshk Owned by: zzz
Priority: major Milestone: 0.9.19
Component: api/i2cp Version: 0.9.18
Keywords: Cc:
Parent Tickets:

Description

I2P version: 0.9.18-11-rc
Java version: Oracle Corporation 1.8.0_31 (Java(TM) SE Runtime Environment 1.8.0_31-b13)
Wrapper version: 3.5.25
Server version: 8.1.16.v20140903
Servlet version: Jasper JSP 2.1 Engine
Platform: Windows XP x86 5.1
Processor: Core 2 (45nm) (core2)
Jbigi: Locally optimized native BigInteger? library loaded from file
Encoding: Cp1257
Charset: windows-1257

Error:
15.29.3 01:10:15 CRIT [P Reader 243] 2p.data.i2cp.I2CPMessageReader: Unhandled error reading I2CP stream

java.lang.NullPointerException?
at net.i2p.router.client.ClientMessageEventListener?.handleCreateLeaseSet(ClientMessageEventListener?.java:373)
at net.i2p.router.client.ClientMessageEventListener?.messageReceived(ClientMessageEventListener?.java:122)
at net.i2p.data.i2cp.I2CPMessageReader$I2CPMessageReaderRunner.run(I2CPMessageReader.java:168)
at java.lang.Thread.run(Unknown Source)
at net.i2p.util.I2PThread.run(I2PThread.java:84)

This can be reproduced if external client that uses SAM bridge gets very little part of CPU due to throttling.

Subtickets

Change History (5)

comment:1 Changed 4 years ago by zzz

  • Component changed from router/general to api/i2cp
  • Milestone changed from undecided to 0.9.19
  • Owner set to zzz
  • Priority changed from minor to major
  • Status changed from new to assigned

comment:2 Changed 4 years ago by zzz

  • Status changed from assigned to testing

I don't understand how this happened, as it seems like the session was never created... like a message got dropped before the create leaseset message, or things got out-of-order, don't know how.

Were there any relevant errors before the one above?

Anyway, fixing the symptom in ca6340b50eed6bdd23109f4f7a98388066714230 0.9.18-13-rc even if I don't understand the cause.

comment:3 Changed 4 years ago by djjeshk

There were lot of errors around, see below:

15.28.3 23:41:56 WARN [ole Jetty-55] vlet.filters.XSSRequestWrapper: URL "/configure" Stripped param "dataDir" : "C:\Documents and Settings\All Users\Application Data\i2p\i2psnark"
15.28.3 23:51:33 1 similar message omitted
15.29.3 00:57:57 ERROR 3/5? uter.client.RequestLeaseSetJob?: Failed to receive a leaseSet in the time allotted (61578): leaseSet request asking for [LeaseSet?:

Destination: null
EncryptionKey?: null
SigningKey?: null
Signature: null
Leases: #4

[Lease:

End Date: Sat Mar 28 23:06:54 GMT 2015
Gateway: [Hash: 5UHVubRxnohwp1-MyjPzWQqZ5ypmRK2pMVTWsm~IV00=]
TunnelId?: 2677440854]

[Lease:

End Date: Sat Mar 28 23:05:39 GMT 2015
Gateway: [Hash: mLgNubwXNSDHLohtva8YfoTidf~pQ33O4~lhvWDS32U=]
TunnelId?: 442854283]

[Lease:

End Date: Sat Mar 28 23:00:52 GMT 2015
Gateway: [Hash: 5UHVubRxnohwp1-MyjPzWQqZ5ypmRK2pMVTWsm~IV00=]
TunnelId?: 3647499473]

[Lease:

End Date: Sat Mar 28 22:58:53 GMT 2015
Gateway: [Hash: xwouDzvkTzQVvaWAt6BWkQd61-4mRMT5~90yrJaCLIY=]
TunnelId?: 3558591680]] having received null succeeding? false expiring on 1427583476067 for Z2kW1fGMihu6ZcZIhk8ABvkHVTQRL~ILsMxBYjl8qr4=

15.29.3 00:59:10 1 similar message omitted
15.29.3 01:00:16 2 similar messages omitted
15.29.3 01:01:00 1 similar message omitted
15.29.3 01:01:43 1 similar message omitted
15.29.3 01:02:03 1 similar message omitted
15.29.3 01:02:46 1 similar message omitted
15.29.3 01:03:04 1 similar message omitted
15.29.3 01:03:48 1 similar message omitted
15.29.3 01:04:57 1 similar message omitted
15.29.3 01:05:51 1 similar message omitted
15.29.3 01:06:03 2 similar messages omitted
15.29.3 01:06:54 1 similar message omitted
15.29.3 01:07:08 2 similar messages omitted
15.29.3 01:08:08 3 similar messages omitted
15.29.3 01:08:08 ERROR 1/1? .client.ClientConnectionRunner?: Disconnecting the client - Too many leaseset request fails
15.29.3 01:09:08 ERROR 1/1? uter.client.RequestLeaseSetJob?: Failed to receive a leaseSet in the time allotted (60954): leaseSet request asking for [LeaseSet?:

Destination: null
EncryptionKey?: null
SigningKey?: null
Signature: null
Leases: #4

[Lease:

End Date: Sat Mar 28 23:14:45 GMT 2015
Gateway: [Hash: xwouDzvkTzQVvaWAt6BWkQd61-4mRMT5~90yrJaCLIY=]
TunnelId?: 1885488310]

[Lease:

End Date: Sat Mar 28 23:14:40 GMT 2015
Gateway: [Hash: wt8uAuZLzSWOOe00Tn5HYKVfPEyVYLnnCOxwgFlFvtc=]
TunnelId?: 1148943724]

[Lease:

End Date: Sat Mar 28 23:13:31 GMT 2015
Gateway: [Hash: mLgNubwXNSDHLohtva8YfoTidf~pQ33O4~lhvWDS32U=]
TunnelId?: 1901431845]

[Lease:

End Date: Sat Mar 28 23:08:51 GMT 2015
Gateway: [Hash: wt8uAuZLzSWOOe00Tn5HYKVfPEyVYLnnCOxwgFlFvtc=]
TunnelId?: 2864448585]] having received null succeeding? false expiring on 1427584147534 for Z2kW1fGMihu6ZcZIhk8ABvkHVTQRL~ILsMxBYjl8qr4=

15.29.3 01:09:10 1 similar message omitted
15.29.3 01:10:11 2 similar messages omitted
15.29.3 01:10:15 CRIT [P Reader 243] 2p.data.i2cp.I2CPMessageReader: Unhandled error reading I2CP stream
java.lang.NullPointerException?

at net.i2p.router.client.ClientMessageEventListener?.handleCreateLeaseSet(ClientMessageEventListener?.java:373)
at net.i2p.router.client.ClientMessageEventListener?.messageReceived(ClientMessageEventListener?.java:122)
at net.i2p.data.i2cp.I2CPMessageReader$I2CPMessageReaderRunner.run(I2CPMessageReader.java:168)
at java.lang.Thread.run(Unknown Source)
at net.i2p.util.I2PThread.run(I2PThread.java:84)

15.29.3 01:11:12 ERROR 4/5? uter.client.RequestLeaseSetJob?: Failed to receive a leaseSet in the time allotted (61047): leaseSet request asking for [LeaseSet?:

Destination: null
EncryptionKey?: null
SigningKey?: null
Signature: null
Leases: #4

[Lease:

End Date: Sat Mar 28 23:16:31 GMT 2015
Gateway: [Hash: n-rzL3j7dwtZSPoZKM1LZAufaygCz7xTwbyJncB7NOE=]
TunnelId?: 2081924973]

[Lease:

End Date: Sat Mar 28 23:14:45 GMT 2015
Gateway: [Hash: xwouDzvkTzQVvaWAt6BWkQd61-4mRMT5~90yrJaCLIY=]
TunnelId?: 1885488310]

[Lease:

End Date: Sat Mar 28 23:14:40 GMT 2015
Gateway: [Hash: wt8uAuZLzSWOOe00Tn5HYKVfPEyVYLnnCOxwgFlFvtc=]
TunnelId?: 1148943724]

[Lease:

End Date: Sat Mar 28 23:13:31 GMT 2015
Gateway: [Hash: mLgNubwXNSDHLohtva8YfoTidf~pQ33O4~lhvWDS32U=]
TunnelId?: 1901431845]] having received null succeeding? false expiring on 1427584271488 for Z2kW1fGMihu6ZcZIhk8ABvkHVTQRL~ILsMxBYjl8qr4=

15.29.3 01:11:12 ERROR 4/5? .client.ClientConnectionRunner?: Disconnecting the client - Too many leaseset request fails
15.29.3 01:11:14 ERROR 2/5? uter.client.RequestLeaseSetJob?: Failed to receive a leaseSet in the time allotted (60000): leaseSet request asking for [LeaseSet?:

Destination: null
EncryptionKey?: null
SigningKey?: null
Signature: null
Leases: #4

[Lease:

End Date: Sat Mar 28 23:16:55 GMT 2015
Gateway: [Hash: 9yVbORExIixUdmLzGQ-zzYC9u~MBuJ5BjCp9QNXysgs=]
TunnelId?: 1359631831]

[Lease:

End Date: Sat Mar 28 23:15:29 GMT 2015
Gateway: [Hash: b-niadxx1ebhulV8yu9yTTjyCPISliTma~iF9qb2r5o=]
TunnelId?: 260778947]

[Lease:

End Date: Sat Mar 28 23:14:58 GMT 2015
Gateway: [Hash: ndupg2L6wQ1rjrWygcexKIN1dtafi~Ndoo48n~Zf5A0=]
TunnelId?: 3608876240]

[Lease:

End Date: Sat Mar 28 23:13:05 GMT 2015
Gateway: [Hash: b-niadxx1ebhulV8yu9yTTjyCPISliTma~iF9qb2r5o=]
TunnelId?: 2233413890]] having received null succeeding? false expiring on 1427584274488 for YPWsnUtfxpmq5-6W2682IpRGrQm6j8Z~EFdjR9yO44s=

15.29.3 01:11:14 ERROR 2/5? .client.ClientConnectionRunner?: Disconnecting the client - Too many leaseset request fails
15.29.3 01:11:42 ERROR [P Reader 244] ent.ClientMessageEventListener?: Signature verification failed on a create session message
15.29.3 01:11:42 ERROR [P Reader 244] .client.ClientConnectionRunner?: Disconnecting the client - Invalid signature on CreateSessionMessage?
15.29.3 01:13:12 ERROR [P Reader 246] ent.ClientMessageEventListener?: Signature verification failed on a create session message
15.29.3 01:13:12 ERROR [P Reader 246] .client.ClientConnectionRunner?: Disconnecting the client - Invalid signature on CreateSessionMessage?
15.29.3 01:16:49 CRIT [P Reader 245] 2p.data.i2cp.I2CPMessageReader: Unhandled error reading I2CP stream
java.lang.NullPointerException?

at net.i2p.router.client.ClientMessageEventListener?.handleCreateLeaseSet(ClientMessageEventListener?.java:373)
at net.i2p.router.client.ClientMessageEventListener?.messageReceived(ClientMessageEventListener?.java:122)
at net.i2p.data.i2cp.I2CPMessageReader$I2CPMessageReaderRunner.run(I2CPMessageReader.java:168)
at java.lang.Thread.run(Unknown Source)
at net.i2p.util.I2PThread.run(I2PThread.java:84)

15.29.3 01:18:17 ERROR [P Reader 248] ent.ClientMessageEventListener?: Signature verification failed on a create session message
15.29.3 01:18:17 ERROR [P Reader 248] .client.ClientConnectionRunner?: Disconnecting the client - Invalid signature on CreateSessionMessage?
15.29.3 01:19:12 ERROR [P Reader 250] ent.ClientMessageEventListener?: Signature verification failed on a create session message
15.29.3 01:19:12 ERROR [P Reader 250] .client.ClientConnectionRunner?: Disconnecting the client - Invalid signature on CreateSessionMessage?
15.29.3 01:21:46 ERROR [P Reader 249] ent.ClientMessageEventListener?: Signature verification failed on a create session message
15.29.3 01:21:46 ERROR [P Reader 249] .client.ClientConnectionRunner?: Disconnecting the client - Invalid signature on CreateSessionMessage?
15.29.3 01:23:52 ERROR [P Reader 251] ent.ClientMessageEventListener?: Signature verification failed on a create session message
15.29.3 01:23:52 ERROR [P Reader 251] .client.ClientConnectionRunner?: Disconnecting the client - Invalid signature on CreateSessionMessage?
15.29.3 01:23:52 ERROR [P Reader 254] ent.ClientMessageEventListener?: Signature verification failed on a create session message
15.29.3 01:23:52 ERROR [P Reader 254] .client.ClientConnectionRunner?: Disconnecting the client - Invalid signature on CreateSessionMessage?
15.29.3 01:24:47 ERROR [P Reader 255] ent.ClientMessageEventListener?: Signature verification failed on a create session message
15.29.3 01:24:47 ERROR [P Reader 255] .client.ClientConnectionRunner?: Disconnecting the client - Invalid signature on CreateSessionMessage?
15.29.3 01:26:49 ERROR [P Reader 257] ent.ClientMessageEventListener?: Signature verification failed on a create session message
15.29.3 01:26:49 ERROR [P Reader 257] .client.ClientConnectionRunner?: Disconnecting the client - Invalid signature on CreateSessionMessage?
15.29.3 08:58:47 WARN [e Jetty-9186] vlet.filters.XSSRequestWrapper: URL "/configure" Stripped param "dataDir" : "C:\Documents and Settings\All Users\Application Data\i2p\i2psnark"
15.29.3 23:06:54 WARN [ Jetty-35907] vlet.filters.XSSRequestWrapper: URL "/configure" Stripped param "dataDir" : "C:\Documents and Settings\All Users\Application Data\i2p\i2psnark"
15.29.3 23:16:08 1 similar message omitted
15.29.3 23:31:03 1 similar message omitted
15.29.3 23:33:56 1 similar message omitted
15.29.3 23:36:23 1 similar message omitted
15.29.3 23:45:38 1 similar message omitted
15.30.3 04:03:58 WARN [Timestamper ] net.i2p.util.Clock : Warning - Updating target clock offset to -229ms from -17866ms, Stratum 2
15.30.3 15:02:59 WARN [ Jetty-36346] vlet.filters.XSSRequestWrapper: URL "/configure" Stripped param "dataDir" : "C:\Documents and Settings\All Users\Application Data\i2p\i2psnark"
15.30.3 15:05:33 1 similar message omitted

comment:4 Changed 4 years ago by zzz

Thanks, very helpful.

Unrelated bug on setting i2psnark data directory on Windows fixed in 9eb7ea8670fb2534660144216f4bbcf0de52853e 0.9.18-15-rc

Increase create session message clock skew tolerance and fix message to client in bf7fc6bb213e734788d6527a4a689184ff73d6ad 0.9.18-15-rc

comment:5 Changed 9 months ago by zzz

  • Resolution set to fixed
  • Status changed from testing to closed

presumed fixed, no reports since

Note: See TracTickets for help on using tickets.