I'm not sure what is going on here, but today my block producing node forged a b…lock, my relay node sees it immediately, but it says FetchDeclineChainNotPlausible. Nine seconds later, it receives a block with the same block number as mine forged by someone else and only then **my block** is added to my relay's version of the chain. Then a fork is recognized and later on the chain with the other block got choosen. I can see the orphaned block on PoolTool and on some block explorers it was briefly visible before getting replaced by the other, thus other nodes did pick it up, but I guess only after that nine seconds have passed.
Why did my relay node waited before receiving the other block before adding it to its version of the chain?
Also, I do see that my relay node uses '10:59:27.99' as log time where the block is forged on the block producing node at '10:59:28.01' (slot time was 10:59:28), so the relay node's clock lags a little bit behind, but that cannot be a problem I guess?
Here the (somewhat annotated) logs from my relay:
**RELAY FETCHING MY BLOCK FROM MY CORE NODE (FetchDeclineChainNotPlausible):** Apr 04 12:59:27 nimue-relay1 bash[1332]: [nimue-re:cardano.node.BlockFetchDecision:Info:58] [2021-04-04 10:59:27.99 UTC] [TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:35611, remoteAddress = MY_CORE_LOCAL_IP:2770}) (Right [At (Block {blockPointSlot = SlotNo 25967677, blockPointHash = e6dfb148ab2d8bd607985d4c32465ad0a0fae4b833ffb76f013c5d6447ef65cd})]),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:33119, remoteAddress = 34.66.64.195:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:33843, remoteAddress = 75.32.204.221:6001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:34899, remoteAddress = 34.80.179.174:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:35439, remoteAddress = 3.126.142.56:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:35903, remoteAddress = 15.237.129.233:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:36867, remoteAddress = 78.23.133.211:3022}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:37573, remoteAddress = 178.128.196.58:5001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:39737, remoteAddress = 73.129.228.216:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:40369, remoteAddress = 66.42.127.211:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:40743, remoteAddress = 178.128.187.12:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:41505, remoteAddress = 88.99.39.191:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:42321, remoteAddress = 18.159.65.241:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:43093, remoteAddress = 161.97.175.144:3004}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:43209, remoteAddress = 209.151.148.76:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:43695, remoteAddress = 89.40.9.152:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:44037, remoteAddress = 134.209.26.2:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:46189, remoteAddress = 157.90.151.159:6003}) (Left FetchDeclineChainNotPlausible)]
Apr 04 12:59:30 nimue-relay1 bash[1332]: [nimue-re:cardano.node:Info:18780] [2021-04-04 10:59:30.50 UTC] fromList [("time(ps)",Number 6.6131797628408e16),("kind",String "MeasureTxsTimeStart"),("mempoolNumBytes",Number 1202.0),("mempoolNumTxs",Number 3.0)]
Apr 04 12:59:30 nimue-relay1 bash[1332]: [nimue-re:cardano.node.Mempool:Info:18780] [2021-04-04 10:59:30.50 UTC] fromList [("tx",Object (fromList [("txid",String "txid: TxId {_unTxId = \"5c33265d0e587315ad40c862b62fbe4e69602f924dc9c7e1df6f9b7b8f30e58a\"}")])),("kind",String "TraceMempoolAddedTx"),("mempoolSize",Object (fromList [("numTxs",Number 3.0),("bytes",Number 1202.0)]))]
Apr 04 12:59:30 nimue-relay1 bash[1332]: [nimue-re:cardano.node.Mempool:Info:268] [2021-04-04 10:59:30.52 UTC] fromList [("tx",Object (fromList [("txid",String "txid: TxId {_unTxId = \"5c33265d0e587315ad40c862b62fbe4e69602f924dc9c7e1df6f9b7b8f30e58a\"}")])),("kind",String "TraceMempoolRejectedTx"),("mempoolSize",Object (fromList [("numTxs",Number 3.0),("bytes",Number 1202.0)])),("err",Object (fromList [("kind",String "BadInputsUTxO"),("error",String "The transaction contains inputs that do not exist in the UTxO set."),("consumed",Object (fromList [("lovelace",Number 0.0),("policies",Object (fromList []))])),("badInputs",Array [Array [String "3fa78413aba48f4a3a3749c64349366aa714300ba076689a56d16cb2a109d854",Number 0.0]]),("produced",Object (fromList [("lovelace",Number 1.054774257e9),("policies",Object (fromList []))]))]))]
Apr 04 12:59:30 nimue-relay1 bash[1332]: [nimue-re:cardano.node.Mempool:Info:14375] [2021-04-04 10:59:30.65 UTC] fromList [("tx",Object (fromList [("txid",String "txid: TxId {_unTxId = \"5c33265d0e587315ad40c862b62fbe4e69602f924dc9c7e1df6f9b7b8f30e58a\"}")])),("kind",String "TraceMempoolRejectedTx"),("mempoolSize",Object (fromList [("numTxs",Number 3.0),("bytes",Number 1202.0)])),("err",Object (fromList [("kind",String "BadInputsUTxO"),("error",String "The transaction contains inputs that do not exist in the UTxO set."),("consumed",Object (fromList [("lovelace",Number 0.0),("policies",Object (fromList []))])),("badInputs",Array [Array [String "3fa78413aba48f4a3a3749c64349366aa714300ba076689a56d16cb2a109d854",Number 0.0]]),("produced",Object (fromList [("lovelace",Number 1.054774257e9),("policies",Object (fromList []))]))]))]
Apr 04 12:59:30 nimue-relay1 bash[1332]: [nimue-re:cardano.node.Mempool:Info:10579] [2021-04-04 10:59:30.65 UTC] fromList [("tx",Object (fromList [("txid",String "txid: TxId {_unTxId = \"5c33265d0e587315ad40c862b62fbe4e69602f924dc9c7e1df6f9b7b8f30e58a\"}")])),("kind",String "TraceMempoolRejectedTx"),("mempoolSize",Object (fromList [("numTxs",Number 3.0),("bytes",Number 1202.0)])),("err",Object (fromList [("kind",String "BadInputsUTxO"),("error",String "The transaction contains inputs that do not exist in the UTxO set."),("consumed",Object (fromList [("lovelace",Number 0.0),("policies",Object (fromList []))])),("badInputs",Array [Array [String "3fa78413aba48f4a3a3749c64349366aa714300ba076689a56d16cb2a109d854",Number 0.0]]),("produced",Object (fromList [("lovelace",Number 1.054774257e9),("policies",Object (fromList []))]))]))]
**RELAY SEES OTHER BLOCK WITH SAME BLOCK NO AS MINE:** Apr 04 12:59:37 nimue-relay1 bash[1332]: [nimue-re:cardano.node.BlockFetchDecision:Info:58] [2021-04-04 10:59:37.24 UTC] [TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:43209, remoteAddress = 209.151.148.76:3001}) (Right [At (Block {blockPointSlot = SlotNo 25967686, blockPointHash = 558241f6312c1ed94dcefad7ba2b2038cfae16fd1d3468a4a57f1303bd985a76})]),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:33119, remoteAddress = 34.66.64.195:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:33843, remoteAddress = 75.32.204.221:6001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:34899, remoteAddress = 34.80.179.174:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:35439, remoteAddress = 3.126.142.56:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:35611, remoteAddress = MY_CORE_LOCAL_IP:2770}) (Left FetchDeclineAlreadyFetched),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:35903, remoteAddress = 15.237.129.233:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:36867, remoteAddress = 78.23.133.211:3022}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:37573, remoteAddress = 178.128.196.58:5001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:39737, remoteAddress = 73.129.228.216:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:40369, remoteAddress = 66.42.127.211:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:40743, remoteAddress = 178.128.187.12:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:41505, remoteAddress = 88.99.39.191:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:42321, remoteAddress = 18.159.65.241:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:43093, remoteAddress = 161.97.175.144:3004}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:43695, remoteAddress = 89.40.9.152:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:44037, remoteAddress = 134.209.26.2:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:46189, remoteAddress = 157.90.151.159:6003}) (Left FetchDeclineChainNotPlausible)]
Apr 04 12:59:37 nimue-relay1 bash[1332]: [nimue-re:cardano.node.BlockFetchDecision:Info:58] [2021-04-04 10:59:37.29 UTC] [TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:39737, remoteAddress = 73.129.228.216:3001}) (Left (FetchDeclineConcurrencyLimit FetchModeDeadline 1)),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:33119, remoteAddress = 34.66.64.195:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:33843, remoteAddress = 75.32.204.221:6001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:34899, remoteAddress = 34.80.179.174:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:35439, remoteAddress = 3.126.142.56:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:35611, remoteAddress = MY_CORE_LOCAL_IP:2770}) (Left FetchDeclineAlreadyFetched),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:35903, remoteAddress = 15.237.129.233:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:36867, remoteAddress = 78.23.133.211:3022}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:37573, remoteAddress = 178.128.196.58:5001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:40369, remoteAddress = 66.42.127.211:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:40743, remoteAddress = 178.128.187.12:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:41505, remoteAddress = 88.99.39.191:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:42321, remoteAddress = 18.159.65.241:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:43093, remoteAddress = 161.97.175.144:3004}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:43209, remoteAddress = 209.151.148.76:3001}) (Left FetchDeclineInFlightThisPeer),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:43695, remoteAddress = 89.40.9.152:6000}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:44037, remoteAddress = 134.209.26.2:3001}) (Left FetchDeclineChainNotPlausible),TraceLabelPeer (ConnectionId {localAddress = MY_RELAY_LOCAL_IP:46189, remoteAddress = 157.90.151.159:6003}) (Left FetchDeclineChainNotPlausible)]
**RELAY EXTENDING CHAIN WITH MY BLOCK:** Apr 04 12:59:37 nimue-relay1 bash[1332]: [nimue-re:cardano.node.ChainDB:Notice:48] [2021-04-04 10:59:37.35 UTC] Chain extended, new tip: e6dfb148ab2d8bd607985d4c32465ad0a0fae4b833ffb76f013c5d6447ef65cd at slot 25967677
Apr 04 12:59:37 nimue-relay1 bash[1332]: [nimue-re:cardano.node.ChainDB:Notice:48] [2021-04-04 10:59:37.35 UTC] before next, messages elided = 66138644376224
**RELAY EXTENDING CHAIN WITH MY BLOCK (REPEAT):** Apr 04 12:59:37 nimue-relay1 bash[1332]: [nimue-re:cardano.node.ChainDB:Notice:48] [2021-04-04 10:59:37.35 UTC] Chain extended, new tip: e6dfb148ab2d8bd607985d4c32465ad0a0fae4b833ffb76f013c5d6447ef65cd at slot 25967677
**FORK RECOGNIZED:** Apr 04 12:59:37 nimue-relay1 bash[1332]: [nimue-re:cardano.node.ChainDB:Info:48] [2021-04-04 10:59:37.35 UTC] Block fits onto some fork: 558241f6312c1ed94dcefad7ba2b2038cfae16fd1d3468a4a57f1303bd985a76 at slot 25967686