internal error on message publish: KotlinNullPointerException

[benjaminion]

2020-07-27 07:58:53.526+00:00 | P2PService-event-thread-0 | WARN  | AbstractRouter | AbstractRouter internal error on message publish {
  from: "\000%\b\002\022!\002\275\243\233\326$\027,\312\002\003f\\\361\344h\316c\351\021b\230\347\277\212\370\32681\2026\216\235"
  data: "\200\r\364i\001d\000\000\000\201\b\216\314\202^L\020D\221\023y\n_\3549\364\037\"\2368(\201#6D\201\v\227\215\345B\344\220\300uG3\235\337\215Wx:O\313\000\033\n/\245\200\247\303\005\210h0\330\311\250\351\210\242\213\037\273\016\004_+\307\263\324\242\370N\036\036\377\367[\277b\'\232\351\302\024\036PY\032,\327G\264\r\003\000\000\000\000\000\340\024\000\000\000\000\000\000\226?\364\336\354\037\356M\302\230I\036\023t`\366\017]t~\376\340\006\nf\312\266\376\262\031\024\213\322\232\\(\235\373V\321\204@z\260\344\341\212\035\265\360\334\342a$\243\243\257m\264k\372*\210\262T\000\000\000\212\253{\242\364\025\311\225s\001\225\303\006\363g\246dA\247Q\376\315G\201\363\343\207wx\316Efe\203[M\024\032;EL\253\224U\232d\234Y\031-z}zN\332\332\252:b\t;Bm/\242\322\026\237N\242\223\275\006\017\b\021\316\2505l/4\307\222*Irn\230\314\'`\236\376\316D\032N\251A[A6T\227\247;\275\366\264A\021\267VuhU\252T\371\034F\'\224\352O\2440\305\027\000\000\000\000\000\000U\352\2144\334k\021U\244<\231\265\221MVw\342mH\nn\b\324\371\216\370iix_sK\000\000\000\000\000\000\000\000\000\000\t\374>\001\000\b\334\000\000\025\004\b\310\005\000\005\004d\024\000\000\000\f\001\000\000\004\002\000\000\374\002\000\000\364\003\000\000\344\000\000\000\257\r)H\021\001\210\210\256\243cM\217\225\233\275\321j#XG9\375\020v\227\376\373\243k&\306m\001\303fH\215\304g\030\000\005+\200u\370\234\322x%N\337m\231\026\225\023)d\340\302 \331\203\264\245B\320\371\371{\230o,|\bm\r(\360\201x\316i\230\024)\375\332@\344\t\301\'\332\354\313m\240\311d\362\331)\374\276\274\266\267\374\032\320\253\250\356\302jw\254r\rL\344\347\036\375\005\031\a\001aw\211]\355\006\321\317g\277\257Z\223I\2122?Z\267\302\365$\353B\035b\312F[=B\b\3211\265ZC\256\"%\255\002zE\334.\256\300EA\250\314\327\300~\341\306W\bI\227\3706u\315\250[H\260\253\"\330o \244\236\034Eh\000\000\001\257\b\020\000\000\005\004\005\001\000 \001\370\000\263:\370\000\004\226?v@\002\376\370\000>\370\000\360}\241\232\357vC\355\033\005\224\036\216$K\034\355\250EOMg0\215\235\006\356=<\331\006\365\350\271\001\250\337\323\376\330J4\204*<\216\233\030\'\316\024\334\n\250\016v\245\206\366\002c\r*$\340\272\374\261\332 a\027\335\3451\261\217\350d\333\343XpjBM\330h\245\310\232\307\031\361^\372\257\363\353\373\275\221\3247/\357\2226\277\307\327\265$\251\335\302F1\344\000\000\000\263\r\003\000\000\000%\b\005\001\376\370\000\276\370\000\360a\204C\264\316J\3010\263\004Z@^\344\305R\300\367]\345\372\362\305qQ\261:Q\240z5\265\335\342%\271\033F~\027|K\265\300\354\222\242\2430\f\260\367\354qg\254\n\321\267\023\252w\t\276\361u\274$\322\003=\260uL\224-\316\236q\370$[\277C\031W\240\212x\f\220\367\311\303u\027\002\004\000\005\327.\001\000\376\360\001\376\360\001%\360\360i\270\254\006\311f\2264\347wX\315\364\222\3152\302\017\247\026\362~\215ZU\247\272\201F\257\270\321\030&\326\264E\235\3562/\003%\223\260I\336B\246\006\247\253\f\231\350\350j\023\020\b\375B\370{0\363\251\034;\327\330guP\247| A\002\226\375G\326\314\343j\376@\262a;\245\375VL\001*\000\000\000\000\000\000\200\000\000\000\001\b\005\001\005\370\000\262:\350\002|+\274\235(E\260\021\340\315\00235\311\222\313\027?\373\226\237h,mn1,d\330ttFg\376\350\002>\350\002\360s\210\356\201U\252\227\030\037\v\310\235Pn?\217\253Sm\204\300M\301\245\023Kbc\225ds\"\201,,\201GAxN\323\224\266\341?\271\336w\376\023\023l\016\226\357\344\204\373.\220\026H\2432\233v\333\241\272\205\342\303R\366\272\244+e\315\"\aI\340\306\207\034U\032\376V\206\261\255\372aau\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\000\000\000\000 "
  seqno: "\026$\211v\352<K\343"
  topicIDs: "/eth2/fdca39b0/beacon_block/ssz_snappy"
}

The publish element is repeated for a total of 64 times with different data and seqnos.

Version: teku/v0.12.2-dev-43e04799/linux-x86_64/-privatebuild-openjdk64bitservervm-java-13
Network: Altona

No stack trace is recorded.

[ajsutton]

The code appears to log a full exception - it may only display in the log file and not on the console though. Is it possible this message came from the console and there's a full stack trace in the log file?

Without the stack trace I don't think there's anything we can go on to make further progress.

[ajsutton]

Actually if the exception had been omitted by our default logging it would have included a note that the stack trace was available in the log file, and the date format would have been different. Do you have a custom log4j config that's omitting the stack trace by any chance?

[benjaminion]

Ah - I found this (at the end of about 100 screenfuls of error output):

 from peer PeerHandler(peerId=16Uiu2HAm8BwjNFxDRVbWVVYFFHHCVzZVpikGAtbGf4KguU7ABTnc, stream=P2PChannelOverNetty(nettyChannel=[id: 0x5c90ea02/16/true, L:Mux[/192.168.1.203:9000-5c90ea02/16/true] - R:Mux[/45.48.225.109:13000-5c90ea02/16/true]], isInitiator=true))
kotlin.KotlinNullPointerException: null
        at io.libp2p.pubsub.AbstractRouter.onInbound(AbstractRouter.kt:189) [jvm-libp2p-minimal-0.5.3-RELEASE.jar:?]
        at io.libp2p.etc.util.P2PService.streamInbound(P2PService.kt:171) ~[jvm-libp2p-minimal-0.5.3-RELEASE.jar:?]
        at io.libp2p.etc.util.P2PService$StreamHandler$channelRead$1.invoke(P2PService.kt:51) ~[jvm-libp2p-minimal-0.5.3-RELEASE.jar:?]
        at io.libp2p.etc.util.P2PService$StreamHandler$channelRead$1.invoke(P2PService.kt:36) ~[jvm-libp2p-minimal-0.5.3-RELEASE.jar:?]
        at io.libp2p.etc.util.P2PService$runOnEventThread$1.run(P2PService.kt:231) [jvm-libp2p-minimal-0.5.3-RELEASE.jar:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:830) [?:?]

[ajsutton]

I think the problem here boils down to these lines in jvm-libp2p:

        val msgUnseen = msgSubscribed
            .filter { !seenMessages.containsKey(getMessageId(it)) }

        msgUnseen.forEach { seenMessages[getMessageId(it)] = Optional.empty() }

        msgUnseen.forEach { notifyUnseenMessage(peer, it) }
        (msgSubscribed - msgUnseen).forEach { notifySeenMessage(peer, it, seenMessages[getMessageId(it)]!!) }

seenMessages is an LRU map so it automatically removes items when new ones are added to stay below some maximum size. So we could wind up with a message in msgSubscribed which is present in seenMessages when we first create msgUnseen but is then evicted when we we add the unseen messages on the second line. Then when we get to the last line seenMessages[getMessageId(it)] returns null because the message has now been dropped from seenMessages.

We essentially need to combine those lines into one pass through msgSubscribed so we only lookup seenMessages once and hold that result until we're done.