As suggested here: #6278 (comment)
This should be functionally identical to what's in place now. It was built from https://github.com/theuni/bitcoinj/commit/be0eef774462409df277b2a83d71c30451f107c5
That commit is the same as this pruned commit in TheBlueMatt's repo: https://github.com/TheBlueMatt/bitcoinj/commit/0f7b5d8
Now we'll be able to trust the line numbers in the stack traces.
While there are no other builds in the queue, I'll force-push a few times to try to trigger the NPE
This should be functionally identical to what's in place now. It was built from
https://github.com/theuni/bitcoinj/commit/be0eef774462409df277b2a83d71c30451f107c5
That commit is the same as this pruned commit in TheBlueMatt's repo:
https://github.com/TheBlueMatt/bitcoinj/commit/0f7b5d8
Now we'll be able to trust the line numbers in the stack traces.
Grr, 7 forced rebuilds and no errors. I'm not sure if that's a good thing or not :)
Well it tends to happen in droves, as if it depends on the load on the Travis server. I wouldn't applaud yet :)
Going ahead and merging this for troubleshooting improvement.
The issue is still present. I looped it locally, until it failed (took around 30 min):
06:34:40 15 BitcoindComparisonTool$1.onPreMessageReceived: Requested 230386124745549b4a14cb801c16c308568fcc5679b5afd9df0d8601cf938f7e
06:34:40 15 Peer.processMessage: Received unhandled message: Reject: block 0f863347c378794f3a04e2899158a2f952c3720159fe71b6e13d23cca538f4d2 for reason 'bad-txns-inputs-missingorspent' (16)
06:34:40 15 Peer.processMessage: Received unhandled message: Reject: block 230386124745549b4a14cb801c16c308568fcc5679b5afd9df0d8601cf938f7e for reason 'bad-blk-sigops' (16)
06:34:40 1 BitcoindComparisonTool.main: Sent inv with block 0f863347c378794f3a04e2899158a2f952c3720159fe71b6e13d23cca538f4d2
06:34:40 15 BitcoindComparisonTool$1.onPreMessageReceived: Got empty header message from bitcoind
Exception in thread "main" java.lang.NullPointerException
at com.google.bitcoin.core.BitcoindComparisonTool.main(BitcoindComparisonTool.java:311)
debug.log:
2015-06-19 16:34:40 received: getheaders (69 bytes) peer=1
2015-06-19 16:34:40 getheaders -1 to 0000000000000000000000000000000000000000000000000000000000000000 from peer=1
2015-06-19 16:34:40 sending: headers (1 bytes) peer=1
2015-06-19 16:34:40 received: ping (8 bytes) peer=1
2015-06-19 16:34:40 sending: pong (8 bytes) peer=1
2015-06-19 16:34:41 trying connection 0.0.0.0 lastseen=0.0hrs
It's caused by BitcoindComparisonTool.java#L311:
bitcoind.ping().get();
More specifically, because future of PendingPing (Peer.java#L1424) was null, which was returned by ping(), presumably because a pong was received, and processed via PendingPing#complete() (Peer.java#L1383), before it went through:
/**
* Sends the peer a ping message and returns a future that will be invoked when the pong is received back.
* The future provides a number which is the number of milliseconds elapsed between the ping and the pong.
* Once the pong is received the value returned by {@link com.google.bitcoin.core.Peer#getLastPingTime()} is
* updated.
* [@throws](/bitcoin-bitcoin/contributor/throws/) ProtocolException if the peer version is too low to support measurable pings.
*/
public ListenableFuture<Long> ping()
@dexX7 Thanks for having a look. The line numbers didn't change, so it's the same as before.
I came to the same conclusion when I looked into it last time, but @mikehearn was confident that the issue couldn't be here. My guess was that it could be caused by a non-so-random PRNG causing ping lookups to race. In that case, replacing the bitcoind.ping().get() with bitcoind.ping(counter++).get() would avoid the issue I think. @mikehearn Mind having another look, now that we're sure the line#s are good? Even better, since @dexX7 can reproduce locally, maybe he'll be able to test proposed changes more easily.
My guess was that it could be caused by a non-so-random PRNG causing ping lookups to race.
Ah, just to clarify: I'm not sure, how it's caused, and this was just a guess.
But regarding the nonce lookup "collision": I gave it a try and it looks like the nonce can be anything, there always seems to be only one ping in the pending pings list (at least in these tests, for what I saw).
I quickly created a stripped ping-pong only version of the tool with additional log output, and when running via:
qa/pull-tester/run-bitcoind-for-test.sh /usr/bin/java -jar /path/to/bitcoinj/core/target/pull-tests.jar qa/tmp/compTool 0 2>&1
Then the flipped created/clearing log entries further indicate the pong was indeed processed, before ping() finished:
09:44:37 1 Peer.ping: created ping with nonce: 1102
09:44:37 11 Peer.processPong: clearing pong with nonce: 1102 (pending: 1)
09:44:37 1 Peer.ping: created ping with nonce: 1103
09:44:37 11 Peer.processPong: clearing pong with nonce: 1103 (pending: 1)
09:44:37 1 Peer.ping: created ping with nonce: 1104
09:44:37 11 Peer.processPong: clearing pong with nonce: 1104 (pending: 1)
09:44:37 11 Peer.processPong: clearing pong with nonce: 1105 (pending: 1) <-- uh oh
09:44:37 1 Peer.ping: created ping with nonce: 1105
09:44:37 1 BitcoindComparisonTool.main: ERROR: ping() with nonce 1105 returned null
@dexX7 Thanks! The race is fixed in this commit:
https://github.com/bitcoinj/bitcoinj/commit/ce50e0b7558d623481c4bb5c18d136de85268b2e
Running "mvn package" inside a git master checkout of bitcoinj should create a file core/target/pull-tests.jar that contains a fresh pull tester.