erigon icon indicating copy to clipboard operation
erigon copied to clipboard

new heads subscription not returning any values

Open BlinkyStitt opened this issue 3 years ago • 2 comments

System information

Erigon version: 2022.09.03

OS & Version: Linux

Commit hash : 32bd69e5316050005e34448ec6b0165f97173d50

Expected behaviour

Blocks appear every 12 seconds

% websocat ws://$YOUR_NODE:$YOUR_PORT
{"id": 1, "method": "eth_subscribe", "params": ["newHeads"]}
{"jsonrpc":"2.0","id":1,"result":"0x89545c835fb5e61463e273a3c564452e"}
{"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x89545c835fb5e61463e273a3c564452e","result":{"parentHash":"0xababf0f66da3a47e172453e5936177eb3fc9aeb71a3a62430aa03412e27d668f","sha3Uncles":"0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347","miner":"0x388c818ca8b9251b393131c08a736a67ccb19297","stateRoot":"0x97f83b64d161c330a64f29a1e9f02e7fa9b76969c012190f4cf2cdce26890eca","transactionsRoot":"0xb7473f33c16e48d7d48314fd407d9a92596f460cedcd76a755308f21c2fc04ec","receiptsRoot":"0x98831f0bc751fdef5d4c8469cc4f5e289dce6a9d877d0a5434db52869b50e091","logsBloom":"0xb8e1c8f6dda3b8b8bbc2f9fa8432fe3ad353bed2ef49825e8715824ea658478fd43e8144766931582da23bbed20331977e43ce572be57876bef313ebeee536b39336d4155c43b1f87b56f6ff0959316eee648cfb2befb642e2b64fb19c074f301224e8f5cbfef63f453c1c5b755e09f9fe2c2135ae198d563369597f47fe057db72e9befadae7fd209ef6fe441885c3fc704acdbed655e38a5fb9ac5889b8af4fbc357217d56ee4f7afb5dc67e5c14efa7d4363ae7eafb3ae6a73affa60a6bedcd78a106bbcc9b496ee119b2ddfed026312923579cea7c5b3ad58d3b9fb77203c5ba747e194d5c1bef12f3fdd9fe3f27c5df8a3d0d2fb74bb3bce9b75b995ef5","difficulty":"0x0","number":"0xeeb414","gasLimit":"0x1c9c380","gasUsed":"0x137c7da","timestamp":"0x63366bcf","extraData":"0x","mixHash":"0xb15393b423fcd5a4d7a8fe5d4e25a606be0067d294aa1c11f5fc129ec92e9ba2","nonce":"0x0000000000000000","baseFeePerGas":"0x28f714a0d","hash":"0xeb9b6d83aecd8def662a98ab45c788a72a8d357263b2c154554a7cf10bdfa66d"}}}

Actual behavior

% websocat ws://$YOUR_NODE:$YOUR_PORT
{"id": 1, "method": "eth_subscribe", "params": ["newHeads"]}
{"jsonrpc":"2.0","id":1,"result":"0xba56dd94150e1c1d1cc0b0e0a9b27fd6"}

... wait 60 seconds and still nothing

Blocks are appearing on the node:

erigon-alpha_1                 | [INFO] [09-30|04:07:12.849] RPC Daemon notified of new headers       from=15643659 to=15643660 header sending=9.831µs log sending=320ns

...

erigon-alpha_1                 | [INFO] [09-30|04:07:24.703] Timings (slower than 50ms)               Execution=121ms IntermediateHashes=147ms
erigon-alpha_1                 | [INFO] [09-30|04:07:24.704] Tables                                   PlainState=88.0KB AccountChangeSet=28.0KB StorageChangeSet=68.0KB BlockTransaction=104.0KB TransactionLog=132.0KB FreeList=0B
erigon-alpha_1                 | [INFO] [09-30|04:07:24.705] Timings (slower than 50ms)               Headers=11.854s
erigon-alpha_1                 | [INFO] [09-30|04:07:24.705] Tables                                   PlainState=74.9GB AccountChangeSet=164.5GB StorageChangeSet=243.9GB BlockTransaction=8.8GB TransactionLog=455.4GB FreeList=54.1MB ReclaimableSpace=54.1GB
erigon-alpha_1                 | [INFO] [09-30|04:07:24.706] Commit cycle                             in=468.498µs
erigon-alpha_1                 | [INFO] [09-30|04:07:24.706] RPC Daemon notified of new headers       from=15643660 to=15643661 header sending=6.7µs log sending=330ns
erigon-alpha_1                 | [INFO] [09-30|04:07:24.706] [2/16 Headers] Waiting for Consensus Layer... 
erigon-alpha_1                 | [INFO] [09-30|04:07:24.803] Flushing in-memory state 
erigon-alpha_1                 | [INFO] [09-30|04:07:25.159] Timings (slower than 50ms)               Headers=160ms CallTraces=130ms LogIndex=71ms
erigon-alpha_1                 | [INFO] [09-30|04:07:25.159] Tables                                   PlainState=74.9GB AccountChangeSet=164.5GB StorageChangeSet=243.9GB BlockTransaction=8.8GB TransactionLog=455.4GB FreeList=54.1MB ReclaimableSpace=54.1GB
erigon-alpha_1                 | [INFO] [09-30|04:07:25.326] Commit cycle                             in=166.912709ms
erigon-alpha_1                 | [INFO] [09-30|04:07:25.326] RPC Daemon notified of new headers       from=15643660 to=15643661 header sending=13.32µs log sending=270ns
erigon-alpha_1                 | [INFO] [09-30|04:07:25.327] [2/16 Headers] Waiting for Consensus Layer... 

And lighthouse appears to be working:

lighthouse-for-erigon-alpha_1  | Sep 30 04:12:36.720 INFO New block received                      root: 0x9c9db3f545572d237a93627e6bdb67b909d499b18f7749256677bca69a067a3f, slot: 4807261
lighthouse-for-erigon-alpha_1  | Sep 30 04:12:41.001 INFO Synced                                  slot: 4807261, block: 0x9c9d…7a3f, epoch: 150226, finalized_epoch: 150224, finalized_root: 0xa716…f8f4, exec_hash: 0x5cf4…dbd8 (verified), peers: 31, service: slot_notifier

lighthouse-for-erigon-alpha_1  | Sep 30 04:12:53.000 INFO Synced                                  slot: 4807262, block:    …  empty, epoch: 150226, finalized_epoch: 150224, finalized_root: 0xa716…f8f4, exec_hash: 0x5cf4…dbd8 (verified), peers: 32, service: slot_notifier
lighthouse-for-erigon-alpha_1  | Sep 30 04:12:57.274 INFO New block received                      root: 0x9dcc12736c83a8e2017e921a68faed20c4e5213bd216e67a68b00f7f3aea2fa1, slot: 4807262
lighthouse-for-erigon-alpha_1  | Sep 30 04:13:01.013 INFO New block received                      root: 0x502549181629a15db3234d08f3a074c63d98e61688656469d623488f549ba4f4, slot: 4807263
lighthouse-for-erigon-alpha_1  | Sep 30 04:13:05.001 INFO Synced                                  slot: 4807263, block: 0x5025…a4f4, epoch: 150226, finalized_epoch: 150224, finalized_root: 0xa716…f8f4, exec_hash: 0xf583…2239 (verified), peers: 33, service: slot_notifier

I am pretty sure this worked on 2022.09.02, but I might have been on 2022.09.01 before.

Steps to reproduce the behavior

$ websocat ws://$YOUR_NODE:$YOUR_PORT
{"id": 1, "method": "eth_subscribe", "params": ["newHeads"]}

BlinkyStitt avatar Sep 30 '22 04:09 BlinkyStitt

went back to 2022.09.02 and it worked:

% websocat ws://$YOUR_ERIGON_HOST_AND_PORT
{"id": 1, "method": "eth_subscribe", "params": ["newHeads"]}
{"jsonrpc":"2.0","id":1,"result":"0x828ca24dc16b40d8ceb2d43521994825"}
{"jsonrpc":"2.0","method":"eth_subscription","params":{"subscription":"0x828ca24dc16b40d8ceb2d43521994825","result":{"parentHash":"0xcdf0ff256c0f4cfd25336b730e51c7b00655114eb71e857e7d2ea66765337690","sha3Uncles":"0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347","miner":"0x4675c7e5baafbffbca748158becba61ef3b0a263","stateRoot":"0xd791f66fd7069609b9e1cbdf203b485cc310da33f84e84554209b7e9745fc4af","transactionsRoot":"0x72622d8aefda4772b8e2fb0f52dd733eb0643ecf0b05ab10305cf95832bd75a7","receiptsRoot":"0x2f30df1840bcb36899ed4254be60413be7561b53e1303d39f9177a76a37710a3","logsBloom":"0x4da08120c426100a0b2c0014c045182120c14a4000800322884140241c88304240a400000a10061440006438200c09013206400c280508842000112800602071428100b20800bc24614080080080e060151008600040000820106485880440001a2081a0820220ee00489f0081803809404e000d091004c9300000112484040428260102046e10241449200480d0840180131d41004280c92e0500550c10e100fa0a612060804208408c409070200c20080a12e3102400825a08400041010051430b829300001544a000000809e8510c04577b4080ba0414401c895610412e4101f42308000124242b04f5620400ce8808808202020c8541060c08085a092821","difficulty":"0x0","number":"0xeeb471","gasLimit":"0x1c9c380","gasUsed":"0x5e6924","timestamp":"0x6336702b","extraData":"0x","mixHash":"0x17a215d016114f0087ff5d4941584acc254d603b253064da8be01b5d7ab406e6","nonce":"0x0000000000000000","baseFeePerGas":"0x2ff6f1ed6","hash":"0x9b8873582de67ecec8f8260d4d924c13f349e75218840041478c9cb5b8be7589"}}}

I'm going to stay on the older version for now. but the problem must be something changing in 2022.09.03

BlinkyStitt avatar Sep 30 '22 04:09 BlinkyStitt

problem should be solved by PR #5734

0x-3FFF avatar Oct 14 '22 02:10 0x-3FFF

this was fixed by #5734 which is in v2.28.1

BlinkyStitt avatar Nov 04 '22 03:11 BlinkyStitt