Reorg transactions and blocks intermittently not sent to websocket filter

Bugs
1

I open a websocket connection on the Rinkeby endpoint and send the following two subscription requests;

{“method”:“eth_subscribe”,“params”:[“logs”,{“address”:“0x3d604ca5de7737cec7ae90b27e80daf19b3a0d97”}],“jsonrpc”:“2.0”,“id”:“one”}
{“method”:“eth_subscribe”,“params”:[“newHeads”],“jsonrpc”:“2.0”,“id”:“two”}

Everything works correctly most of the time, that is the (Java/Spring Webflux) client gets notified of all new blocks and of all logged events for the contract at address 0x3d604ca5de7737cec7ae90b27e80daf19b3a0d97. We even see correct output for cases where there is a re-org (we see the second block at the same height and we see three log events for the transaction: (i) the correct TxID in a block(hash) that does not make it into the chain, (ii) a “removed”:true indication for that transaction in the original block (hash), and (iii) The same TxID in a new block/blockhash.

Intermittently we only see the first two log events above (e.g. i and ii, but not iii) – we also don’t get a second new block notification for the final (good) block.

2

Below is an excerpt from the server log with commentary in c-style // comments:

// We get a notification of a new block: #3905349
2019-02-21 00:34:46.275  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : RelayService, got message: {"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x4b0e0215956ab91d4a0060bd0278c0a2","result":{"parentHash":"0x88428ff7ac0a773dda3c618b060dd122e061e1e9ef43904010493d08753a1aeb","sha3Uncles":"0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347","miner":"0x0000000000000000000000000000000000000000","stateRoot":"0x8786d853e9b4ca21368dc3dca65abfa079e9a1097ffae548eb2bd1d6340b9df1","transactionsRoot":"0x40dccb3b7117b152fd81ac203fe056790f5a75f22d9d901d3e0650c309b57183","receiptsRoot":"0x6018ed56d66851f3b9f260093a3a59ea30493898f0f7caa0808957ee69709065","logsBloom":"0x00200000000800000000000200000100000020000000020000200001200000100000100200042000000000002200000002000000080000000000010010000020000000800000000000008008000000003008080000000000000000000040000110001004000000002000000000000000000800000000000000000010000000200000008000000000000000000000000000000000040000000000080000080000200000000000000000008000400000200002000000000000100000000000000000400002000000001012000000000000000000000000200080000000000010000000000000000000000000000000400000000000000000001000080000000000","difficulty":"0x1","number":"0x3b9745","gasLimit":"0x6ac5ac","gasUsed":"0x1aeb75","timestamp":"0x5c6df226","extraData":"0xd883010900846765746888676f312e31312e31856c696e757800000000000000b874882e075825b9b3ccac5c1ad72b3ae183d21f11e989736c8e87b3b860f2b43ae529799e98b65d432fd6039c194026d7e203fe02cc14dcae83c24a577bbfc100","mixHash":"0x0000000000000000000000000000000000000000000000000000000000000000","nonce":"0x0000000000000000","hash":"0xbc17c65c2e4132db38f6ed695bd33ddc4f7bf5340d3deb49bc4c681eadb8acb3"}}}
2019-02-21 00:34:46.275  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : Node is: {"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x4b0e0215956ab91d4a0060bd0278c0a2","result":{"parentHash":"0x88428ff7ac0a773dda3c618b060dd122e061e1e9ef43904010493d08753a1aeb","sha3Uncles":"0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347","miner":"0x0000000000000000000000000000000000000000","stateRoot":"0x8786d853e9b4ca21368dc3dca65abfa079e9a1097ffae548eb2bd1d6340b9df1","transactionsRoot":"0x40dccb3b7117b152fd81ac203fe056790f5a75f22d9d901d3e0650c309b57183","receiptsRoot":"0x6018ed56d66851f3b9f260093a3a59ea30493898f0f7caa0808957ee69709065","logsBloom":"0x00200000000800000000000200000100000020000000020000200001200000100000100200042000000000002200000002000000080000000000010010000020000000800000000000008008000000003008080000000000000000000040000110001004000000002000000000000000000800000000000000000010000000200000008000000000000000000000000000000000040000000000080000080000200000000000000000008000400000200002000000000000100000000000000000400002000000001012000000000000000000000000200080000000000010000000000000000000000000000000400000000000000000001000080000000000","difficulty":"0x1","number":"0x3b9745","gasLimit":"0x6ac5ac","gasUsed":"0x1aeb75","timestamp":"0x5c6df226","extraData":"0xd883010900846765746888676f312e31312e31856c696e757800000000000000b874882e075825b9b3ccac5c1ad72b3ae183d21f11e989736c8e87b3b860f2b43ae529799e98b65d432fd6039c194026d7e203fe02cc14dcae83c24a577bbfc100","mixHash":"0x0000000000000000000000000000000000000000000000000000000000000000","nonce":"0x0000000000000000","hash":"0xbc17c65c2e4132db38f6ed695bd33ddc4f7bf5340d3deb49bc4c681eadb8acb3"}}}
2019-02-21 00:34:46.275  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : It's a notification
2019-02-21 00:34:46.275  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : New block: 3905349

// We get a notification of a new transaction (event): TxID 0x0e38e59d7fa42ac564f407cd072fad9add9d5ac014620b5c149108c924af09f6 in block 0xbc17c65c2e4132db38f6ed695bd33ddc4f7bf5340d3deb49bc4c681eadb8acb3
2019-02-21 00:34:46.275  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : RelayService, got message: {"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x32d884746f22ec3d1350ec0bae228eb","result":{"address":"0x3d604ca5de7737cec7ae90b27e80daf19b3a0d97","topics":["0x17b4c6b77962d1e408810debcc3c6cbeef1236c3f40ea34532480b19acacf165","0x00000000000000000000000000000000000000000000000000000000000000ff","0x000000000000000000000000000000000000000000000000002386f26fc10000"],"data":"0x","blockNumber":"0x3b9745","transactionHash":"0x0e38e59d7fa42ac564f407cd072fad9add9d5ac014620b5c149108c924af09f6","transactionIndex":"0xa","blockHash":"0xbc17c65c2e4132db38f6ed695bd33ddc4f7bf5340d3deb49bc4c681eadb8acb3","logIndex":"0x9","removed":false}}}
2019-02-21 00:34:46.275  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : Node is:
{"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x32d884746f22ec3d1350ec0bae228eb",
"result":{"address":"0x3d604ca5de7737cec7ae90b27e80daf19b3a0d97",
"topics":["0x17b4c6b77962d1e408810debcc3c6cbeef1236c3f40ea34532480b19acacf165","0x00000000000000000000000000000000000000000000000000000000000000ff","0x000000000000000000000000000000000000000000000000002386f26fc10000"],
"data":"0x","blockNumber":"0x3b9745","transactionHash":"0x0e38e59d7fa42ac564f407cd072fad9add9d5ac014620b5c149108c924af09f6","transactionIndex":"0xa","blockHash":"0xbc17c65c2e4132db38f6ed695bd33ddc4f7bf5340d3deb49bc4c681eadb8acb3",
"logIndex":"0x9","removed":false}}}
2019-02-21 00:34:46.275  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : It's a notification

// We successfully relay the Tx to our internal API
2019-02-21 00:34:46.942 DEBUG 15842 --- [or-http-epoll-2] o.s.w.r.f.client.ExchangeFunctions       : [2d8a16b8] HTTP POST (write transaction URL)
2019-02-21 00:34:48.281 DEBUG 15842 --- [or-http-epoll-2] o.s.w.r.f.client.ExchangeFunctions       : [2d8a16b8] Response 200 OK
2019-02-21 00:34:48.282  INFO 15842 --- [or-http-epoll-2] com.rivetz.relay.service.RelayService    : createAndFund done


// We get a notification of a new block: #3905350
2019-02-21 00:35:01.126  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : RelayService, got message: {"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x4b0e0215956ab91d4a0060bd0278c0a2","result":{"parentHash":"0x7afcc0eb3362118ba51aaaa280025ffc519c8fc6f1d2757483f56083048d02c6","sha3Uncles":"0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347","miner":"0x0000000000000000000000000000000000000000","stateRoot":"0xcc5edf548ce18220e10dbdcccf338d9eae2aaa34f4d7414f03fa078cbb530f80","transactionsRoot":"0xfcc7b40dd12082c0cc08cdaa52445e2f346db360c01a51fb22dfc0f54910d78a","receiptsRoot":"0x271653cbaa99ab816081edd4d75bac84f89bbd22d9e324bd77e23d907759d6ce","logsBloom":"0x000000000048000000000000000001000000000000000200002000002000000000000002000400000101000022000020020010000000000000000100100000200000008004000000000000080000000030000800000010010000000000400000100010040000000024000100000000000000040000000000000000100040002000000080000000080400000000000080000000000400000000400a0000080000220000001000000400008000400000002002000000000000100000000000000800000002000000001012000000000000004200000000000080000000000010000000000400080000000000000001400000000000000000201000080000000000","difficulty":"0x2","number":"0x3b9746","gasLimit":"0x6ac132","gasUsed":"0x18b730","timestamp":"0x5c6df235","extraData":"0xd883010900846765746888676f312e31312e31856c696e757800000000000000a33b23b71f3098c6483682bea860373f2ced9bf1b6129bfd2136ec1d8c394bbe4334124d423b0e1da047bc436ab800195b342c123e7a2556c118c374fda64c9001","mixHash":"0x0000000000000000000000000000000000000000000000000000000000000000","nonce":"0x0000000000000000","hash":"0x5a02841b2b19cfb070fcf5c0ebd14c7f5af187fabdcfe32ff1e9b3053edab4f9"}}}
2019-02-21 00:35:01.126  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : Node is: {"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x4b0e0215956ab91d4a0060bd0278c0a2","result":{"parentHash":"0x7afcc0eb3362118ba51aaaa280025ffc519c8fc6f1d2757483f56083048d02c6","sha3Uncles":"0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347","miner":"0x0000000000000000000000000000000000000000","stateRoot":"0xcc5edf548ce18220e10dbdcccf338d9eae2aaa34f4d7414f03fa078cbb530f80","transactionsRoot":"0xfcc7b40dd12082c0cc08cdaa52445e2f346db360c01a51fb22dfc0f54910d78a","receiptsRoot":"0x271653cbaa99ab816081edd4d75bac84f89bbd22d9e324bd77e23d907759d6ce","logsBloom":"0x000000000048000000000000000001000000000000000200002000002000000000000002000400000101000022000020020010000000000000000100100000200000008004000000000000080000000030000800000010010000000000400000100010040000000024000100000000000000040000000000000000100040002000000080000000080400000000000080000000000400000000400a0000080000220000001000000400008000400000002002000000000000100000000000000800000002000000001012000000000000004200000000000080000000000010000000000400080000000000000001400000000000000000201000080000000000","difficulty":"0x2","number":"0x3b9746","gasLimit":"0x6ac132","gasUsed":"0x18b730","timestamp":"0x5c6df235","extraData":"0xd883010900846765746888676f312e31312e31856c696e757800000000000000a33b23b71f3098c6483682bea860373f2ced9bf1b6129bfd2136ec1d8c394bbe4334124d423b0e1da047bc436ab800195b342c123e7a2556c118c374fda64c9001","mixHash":"0x0000000000000000000000000000000000000000000000000000000000000000","nonce":"0x0000000000000000","hash":"0x5a02841b2b19cfb070fcf5c0ebd14c7f5af187fabdcfe32ff1e9b3053edab4f9"}}}
2019-02-21 00:35:01.126  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : It's a notification
2019-02-21 00:35:01.126  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : New block: 3905350

// We get a notification of a new transaction (event) but with {"removed":true} : TxID 0x0e38e59d7fa42ac564f407cd072fad9add9d5ac014620b5c149108c924af09f6
2019-02-21 00:35:01.126  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : RelayService, got message: {"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x32d884746f22ec3d1350ec0bae228eb","result":{"address":"0x3d604ca5de7737cec7ae90b27e80daf19b3a0d97","topics":["0x17b4c6b77962d1e408810debcc3c6cbeef1236c3f40ea34532480b19acacf165","0x00000000000000000000000000000000000000000000000000000000000000ff","0x000000000000000000000000000000000000000000000000002386f26fc10000"],"data":"0x","blockNumber":"0x3b9745","transactionHash":"0x0e38e59d7fa42ac564f407cd072fad9add9d5ac014620b5c149108c924af09f6","transactionIndex":"0xa","blockHash":"0xbc17c65c2e4132db38f6ed695bd33ddc4f7bf5340d3deb49bc4c681eadb8acb3","logIndex":"0x9","removed":true}}}
2019-02-21 00:35:01.126  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : Node is:
{"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x32d884746f22ec3d1350ec0bae228eb",
"result":{"address":"0x3d604ca5de7737cec7ae90b27e80daf19b3a0d97",
"topics":["0x17b4c6b77962d1e408810debcc3c6cbeef1236c3f40ea34532480b19acacf165","0x00000000000000000000000000000000000000000000000000000000000000ff","0x000000000000000000000000000000000000000000000000002386f26fc10000"],
"data":"0x","blockNumber":"0x3b9745","transactionHash":"0x0e38e59d7fa42ac564f407cd072fad9add9d5ac014620b5c149108c924af09f6","transactionIndex":"0xa","blockHash":"0xbc17c65c2e4132db38f6ed695bd33ddc4f7bf5340d3deb49bc4c681eadb8acb3",
"logIndex":"0x9","removed":true}}}
2019-02-21 00:35:01.126  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : It's a notification
2019-02-21 00:35:01.126  INFO 15842 --- [or-http-epoll-4] com.rivetz.relay.service.RelayService    : Skipping 'removed' FundingEvent

// BUG?? - We don't get a third notification, showing the transaction was confirmed in a block with a different hash.
// The actual transaction was confirmed in block #3905349 with hash 0x7afcc0eb3362118ba51aaaa280025ffc519c8fc6f1d2757483f56083048d02c6
// We received no notification of that block nor of the transaction being confirmed in that block.

Final confirmed Tx:
https://rinkeby.etherscan.io/tx/0x0e38e59d7fa42ac564f407cd072fad9add9d5ac014620b5c149108c924af09f6

Block 3905349:
https://rinkeby.etherscan.io/block/3905349
3

I believe you’re experiencing a similar issue described here, Hashes provided by newHeads subscription not lining up on Kovan

This is an issue in go-ethereum, we are working on a fix that will be released in the next 2 weeks.

4

Thanks! Will you let me know when the fix is released so I can re-test?

5

Of course, we will announce it here and on our blog.

6

I’ve taken over the project and it would be great to get status on this.