jrwashburn
commented
3 years ago I'm not entirely sure that I'm saying the same thing Emre is, but they may be related. Here's what I observed.
I also ran the VRF tool to compare my epoch 9. I didn't miss any blocks being generated; however when checking against Gareth's performance script which checks to see if the block was produced at the canonical height, it showed that I missed that block.
on 7/28, I had seen a chain kMRx->Bwyz->8Ngb->LsBz before I started producing a block on top of LsBz.
After producing that block (ending in YntX), it was broadcast, but then the node presumably went to catchup to fast forward to Bwyz as the tip, and then produced a second block BLYk which was rejected as too late and not sent.
(I'm assuming it went to catchup because of the double block production. I log status every 5 mins and it always showed in sync, but this could have been a quick catchup. I do see this in the catchup log message around that time ... at 21:40:48.237628Z shows 1 to build breadcrumb... "states":[[["To_build_breadcrumb"],1],[["To_initial_validate"],0],[["Finished"],622],[["To_verify"],0],[["To_download"],0],[["Wait_for_parent"],0]] )
I'm not sure if YntX was really broadcast, but nobody I asked reported seeing it. Presumably it would be dropped as part of a short fork, so that makes sense.
What doesn't make sense is that I saw Bwyz initially at 21:36, but at 21:39 was producing off of LsBz.
This all makes me suspect blocks are getting held up in the network buffer between things -- it's hard to imagine it really taking 3 mins to propagate -- I suspect it's way more likely that it was sitting around waiting to be processed.
21:39:00.001448Z - "Producing new block with parent $breadcrumb" ... **"previous_state_hash":"3NKe3F7f4ALxSvknH4DrVMSiPxvgjg7krEbmw4CtC2vTWguiLsBz"
21:40:27.013942Z - "Successfully produced a new block" ... previous_state_hash":"3NLFoaiYzY5B1XkFVfCmfSgmkkVh9n7b8bzr2FmqD1ecC8xcZofh" ..** "hash":"3NLqz46LSErA3HTJA3K9EHw2UNE6Nqc2qE2BBg1Mp792rgodYntX"
21:40:27.014515Z - "Waiting for block $state_hash to be inserted into frontier" ... "state_hash":"3NLqz46LSErA3HTJA3K9EHw2UNE6Nqc2qE2BBg1Mp792rgodYntX"
21:40:30.864098Z - "Generated transition $state_hash was accepted into transition frontier" ... "state_hash":"3NLqz46LSErA3HTJA3K9EHw2UNE6Nqc2qE2BBg1Mp792rgodYntX"
21:40:30.885492Z - "Saw block with state hash $state_hash" ... "previous_state_hash":"3NL7ukD8U4DuS8HEKFZVJmrzEBWZuZqtakaFTDqDF1sBYqZB8Ngb" ... "state_hash":"3NKydDuNc6frgKxnGRrxRgSrcBNXKKLYv4VAeJM5zVEmUS3eBwyz"
21:40:47.945952Z - "Producing block in 0 slots"
21:40:47.946374Z - "Producing new block with parent $breadcrumb" ... "previous_state_hash":"3NL7ukD8U4DuS8HEKFZVJmrzEBWZuZqtakaFTDqDF1sBYqZB8Ngb"
**21:41:00.140980Z - "Broadcasting new state over gossip net","metadata":{"host":"145.40.90.199","message":["New_state",{"protocol_state":{"previous_state_hash":"3NLFoaiYzY5B1XkFVfCmfSgmkkVh9n7b8bzr2FmqD1ecC8xcZofh**" ... "state_hash":"3NLqz46LSErA3HTJA3K9EHw2UNE6Nqc2qE2BBg1Mp792rgodYntX"...
21:41:51.521787Z - "Successfully produced a new block" ... "previous_state_hash":"3NKydDuNc6frgKxnGRrxRgSrcBNXKKLYv4VAeJM5zVEmUS3eBwyz"
21:42:03.479635Z - "Generated transition $state_hash was accepted into transition frontier" ... "state_hash":"3NKVvM9FAUFwVxEQnmhca5uxfGaTAboK7BLtJ87E1LZTWAZFBLYk"
21:42:49.437706Z - Error "Internally generated block $state_hash cannot be rebroadcast because it's not a valid time to do so ($timing)" ... "previous_state_hash":"3NKydDuNc6frgKxnGRrxRgSrcBNXKKLYv4VAeJM5zVEmUS3eBwyz" ... "state_hash":"3NKVvM9FAUFwVxEQnmhca5uxfGaTAboK7BLtJ87E1LZTWAZFBLYk","timing":"1 slots too late"
I had already seen other blocks that would be the longer (and eventually canonical chain) but produced off of the older because they were rejected initially:
{
"timestamp": "2021-07-28 21:36:01.933503Z",
"level": "Error",
"source": {
"module": "Transition_router__Initial_validator",
"location": "File \"src/lib/transition_router/initial_validator.ml\", line 69, characters 2-14"
},
"message": "Validation error: external transition with state hash $state_hash was rejected for reason $reason",
"metadata": {
"host": "145.40.90.199",
"peer_id": "12D3KooWB9YemkwqWVkRPMYr2T7htNC3A5sVBWTg32uncNTd4TaR",
"pid": 23365,
"port": 8302,
"reason": "invalid time",
"slot_diff": "1",
"state_hash": "3NKydDuNc6frgKxnGRrxRgSrcBNXKKLYv4VAeJM5zVEmUS3eBwyz",
"time_error": "too late",
"time_received": "2021-07-28 21:36:01.932000Z"
}
}Here are the receipt times of each of the chain candidates:
21:30:00.289989Z - 3NKe3F7f4ALxSvknH4DrVMSiPxvgjg7krEbmw4CtC2vTWguiLsBz
21:31:55.297343Z - 3NLFoaiYzY5B1XkFVfCmfSgmkkVh9n7b8bzr2FmqD1ecC8xcZofh
21:32:06.611819Z - 3NL7ukD8U4DuS8HEKFZVJmrzEBWZuZqtakaFTDqDF1sBYqZB8Ngb
21:33:43.585521Z - 3NKGvFcVqNKq7pYGd2VSLoQYj3xL1t6ZEXJTuZcjE9oE9iqxWfrf
21:36:01.932111Z - 3NKydDuNc6frgKxnGRrxRgSrcBNXKKLYv4VAeJM5zVEmUS3eBwyz
21:38:43.115240Z - 3NLchfxkvkB6ei5NSW274cqRQS2DF24opGsV4W586Y2rY4BmkMRx-- All were seen before I started producing at 21:39 on top of LsBz.
mina.log.21-22 have the details. Included .20 and .23 for additional context if needed...
https://drive.google.com/drive/folders/1z6OojQemOs_wpU8cjiCCV9bpgaN4uD-X?usp=sharing
EmrePiconbello
ghost-not-in-the-shell
EmreNOP
hsq125
garethtdavies
donadel01
p-shahi
After running with vrf check on epoch 10 we spot 4 blocks missing we have on crash on slot time and one block generated 1 block behind while rest is valid. Asking several members with archive node their node saw the block late while we don't spot any issue. We weigh on the network gossip layer issue. Logs are below log for slot 74978 Node 1 (US Region).txt logs for slot 71507 Node 1 (US Region).txt logs for slot 71725 Node 1 (US Region).txt log for slot 74429 Node 1 (US Region).txt log for slot 74978 node 2 (EU Region).txt logs for slot 71507 node 2 (EU Region).txt logs for slot 71725 node 2 (EU Region).txt log for slot 74429 node 2 (EU Region).txt log for slot 74978 node 3 (EU Region).txt logs for slot 71507 node 3 (EU Region).txt logs for slot 71725 node 3 (EU Region).txt log for slot 74429 node 3 (EU Region).txt