Terminal block is unknown parent

[paulhauner]

System information

Geth version: v1.10.21
OS & Version: Linux
Commit hash : NA

Description

In Lighthouse CI we have a series of "execution integration tests" where we test some scenarios between Geth and LH.

Since these tests started running on v1.1.0.21, we've noticed a change in behaviour. The previous behaviour was:

1. LH uses getPayload to request a payload from Geth.
   1. Geth response with a payload.
2. LH sends a forkchoiceUpdated for the payload that was returned
   1. Geth response with SYNCING
3. LH sends a newPayload with the payload
   1. Geth responses with VALID

Now, with v1.10.21 Geth responds in 3.i with ACCEPTED. I believe this response violates the "the payload doesn't extend the canonical chain" point of the newPayload API.

I'm aware that an fcU before newPayload is weird behaviour, so I don't see this as an immediate issue. However I thought it's worth raising to your attention ☺️

[paulhauner]

Oh actually, it appears that there might be more to this issue than I originally thought.

Here are some logs from Geth from a Lighthouse CI run:

INFO [07-28|01:05:18.741]  
INFO [07-28|01:05:18.741] Initialising Ethereum protocol           network=1 dbversion=<nil>
INFO [07-28|01:05:18.744] Loaded most recent local header          number=0 hash=901a0b..7a8082 td=17,179,869,184 age=53y4mo1d
INFO [07-28|01:05:18.744] Loaded most recent local full block      number=0 hash=901a0b..7a8082 td=17,179,869,184 age=53y4mo1d
INFO [07-28|01:05:18.744] Loaded most recent local fast block      number=0 hash=901a0b..7a8082 td=17,179,869,184 age=53y4mo1d
WARN [07-28|01:05:18.746] Failed to load snapshot, regenerating    err="missing or corrupted snapshot"
INFO [07-28|01:05:18.746] Rebuilding state snapshot 
INFO [07-28|01:05:18.747] Resuming state snapshot generation       root=a6ea55..be6106 accounts=0 slots=0 storage=0.00B dangling=0 elapsed="574.125µs"
INFO [07-28|01:05:18.747] Generated state snapshot                 accounts=2 slots=0 storage=98.00B dangling=0 elapsed="980.842µs"
INFO [07-28|01:05:18.747] Regenerated local transaction journal    transactions=0 accounts=0
INFO [07-28|01:05:18.747] Gasprice oracle is ignoring threshold set threshold=2
WARN [07-28|01:05:18.747] Error reading unclean shutdown markers   error="leveldb: not found"
WARN [07-28|01:05:18.747] Engine API enabled                       protocol=eth
INFO [07-28|01:05:18.748] Starting peer-to-peer node               instance=Geth/v1.10.21-stable-67109427/linux-amd64/go1.17.12
INFO [07-28|01:05:18.754] New local node record                    seq=1,658,970,318,753 id=d56017e7ff9517ec ip=127.0.0.1 udp=34839 tcp=34839
INFO [07-28|01:05:18.755] Started P2P networking                   self=enode://37c97ac3903b3c132eebd4ab238e005f6feefd8eac33c7c4b24ee5a5648ecdd21b8373a54e7d839afec0d582721c8061f2381396fe8060d41cfd3d0ca6bee322@127.0.0.1:34839
INFO [07-28|01:05:18.756] IPC endpoint opened                      url=/tmp/.tmpJzV69x/geth.ipc
INFO [07-28|01:05:18.756] Loaded JWT secret file                   path=/tmp/.tmpJzV69x/jwt.hex crc32=0xcd36ad97
INFO [07-28|01:05:18.757] HTTP server started                      endpoint=127.0.0.1:39729 auth=false prefix= cors= vhosts=localhost
INFO [07-28|01:05:18.757] WebSocket enabled                        url=ws://127.0.0.1:37099
INFO [07-28|01:05:18.757] HTTP server started                      endpoint=127.0.0.1:37099 auth=true  prefix= cors=localhost vhosts=localhost
INFO [07-28|01:05:20.649] New local node record                    seq=1,658,970,318,754 id=d56017e7ff9517ec ip=20.225.233.129 udp=1025  tcp=34839
INFO [07-28|01:05:21.374] New local node record                    seq=1,658,970,318,641 id=85a8ac32d5c1afdc ip=20.225.233.129 udp=1024  tcp=38771
INFO [07-28|01:05:26.067] Setting new local account                address=0x7b8C3a386C0eea54693fFB0DA17373ffC9228139
INFO [07-28|01:05:26.067] Submitted transaction                    hash=0x9879a9032316333697e430b4ed8ca8bae53f7ab983eb1658b6c4ccc9dae4b77b from=0x7b8C3a386C0eea54693fFB0DA17373ffC9228139 nonce=0 recipient=0xdA2DD7560DB7e212B945fC72cEB54B7D8C886D77 value=1
INFO [07-28|01:05:26.070] Submitted transaction                    hash=0x296a3b91236668c01aa552d95548acce799e691b9cb6729dd722c482d1a01518 from=0x7b8C3a386C0eea54693fFB0DA17373ffC9228139 nonce=1 recipient=0xdA2DD7560DB7e212B945fC72cEB54B7D8C886D77 value=1
INFO [07-28|01:05:26.073] Submitted transaction                    hash=0x5cfa16c90a764932535a63d05a955df43b90ce640ab7bcc84eb4ceef9f00c27f from=0x7b8C3a386C0eea54693fFB0DA17373ffC9228139 nonce=2 recipient=0xdA2DD7560DB7e212B945fC72cEB54B7D8C886D77 value=1
INFO [07-28|01:05:26.075] Submitted contract creation              hash=0xd36404548c9ddf920ecdb40178b9fb0ed83a6d2512f0f63d2333a73f0f20254f from=0x7b8C3a386C0eea54693fFB0DA17373ffC9228139 nonce=3 contract=0x64f43BEc7F86526686C931d65362bB8698872F90 value=0
INFO [07-28|01:05:26.077] Submitted transaction                    hash=0x79b352a34151dce6e17b671e584e815756adca24254e2013e5a64ee720b8ce21 from=0x7b8C3a386C0eea54693fFB0DA17373ffC9228139 nonce=4 recipient=0x64f43BEc7F86526686C931d65362bB8698872F90 value=0
INFO [07-28|01:05:29.063] Looking for peers                        peercount=0 tried=26 static=0
WARN [07-28|01:05:29.082] Forkchoice requested unknown head        hash=e53892..2336c3
WARN [07-28|01:05:29.084] Ignoring payload with missing parent     number=1 hash=e53892..2336c3 parent=901a0b..7a8082

In particular, these two logs:

INFO [07-28|01:05:18.744] Loaded most recent local fast block      number=0 hash=901a0b..7a8082 td=17,179,869,184 age=53y4mo1d

WARN [07-28|01:05:29.084] Ignoring payload with missing parent     number=1 hash=e53892..2336c3 parent=901a0b..7a8082

It appears to me that 901a0b..7a8082 should be a known block.

[karalabe]

This seems very odd, I can't see anything in the code that could explain missing the genesis block.

[karalabe]

Could you provide some dump of the payload json you're transmitting? Something seems off here

[karalabe]

Quoting my comment from the Lighthouse repo:

Hey all, the new behavior is correct (though it should have returned SYNCING), just changed from the previous incorrect one.

Geth by default starts in snap sync mode. In snap sync, the node must finish a sync cycle first before it accepts blocks. The reason is that snap sync goes around all block validation pathways and writes stuff directly to the database, so it cannot allow some process to inject something conflicting out of band. I.e. if Geth is asked to snap sync, it will deny importing a payload on the engine API until snap sync finishes.

You should start geth with --syncmode=full if you want to test feeding Geth blocks from #1 onward via the engine API.

[karalabe]

We should however fix the warning log and the return code to make this funny behavior obvious.