I missed a block today. please help me understand the logs

I don’t think the key is the problem

$ cardano-cli key verification-key  --signing-key-file vrf.skey --verification-key-file /tmp/vrf.vkey
$ cardano-cli node key-hash-VRF --verification-key-file /tmp/vrf.vkey
e52cd41c94e36f6e4bfce6cdff08dd83cacfd123c44dc323d97a67ba9829fd89

Absolutely. I use chrony but also I checked it manually today

I found many of this only in one relay (relay2). Total 358471 lines!

{"thread":"32456","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"77afb15e02568da5c401477a87f1c321402905116469109eceaaf3fa21a3a253\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":593960842},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["29608e905240c781827e10adafbd89d087afc2bbdccfeeec1ba10100c36188d9#0","687dc5113e0afeba26241f224148d7c7910a2faf802ef2f655ae01f83eb28ca3#1","8c2e816adf8a81b2790b6bdc3616aba8f25c65c373472a1f7112015e2addf17a#1","e24c8fec017a324787e24c0f16cd1699d8418cb0d2b7f4545fd08352aeb1287c#0"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 593960842 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"32456","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"179ae7305cf8d4a4973a09b8fe87eb0da69c12ec9c2a31bd4b1341a5f9dcc979\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26":{"586d617332303231443031333131":1},"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3":{"4c4f4253544552":1000000}},"lovelace":160795573},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["1d4cd2b3fb0b65fe1a01495278aa982eb048812f1409a2ddd1335e657cb97df8#1","55da61d71f7731763c5b7691c7f65e08689abd06b247e04ccded90522f40ebb1#0","bc3c24fe3fc2a67491fd561c67f2a442a22d4271b4b15fa592b272595e291723#3"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 160795573 (fromList [(PolicyID {policyID = ScriptHash \"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26\"},fromList [(\"Xmas2021D01311\",1)]),(PolicyID {policyID = ScriptHash \"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3\"},fromList [(\"LOBSTER\",1000000)])])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"28799","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"ce8e61bba55381f5b132c025657f965367f6bf02a1c058aaf5d10849b7534919\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":2049478087},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["01123543180f03b20df190a7e4b8110ce898cbaf415f9280176005f6563bad9a#1"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 2049478087 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"28799","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"77afb15e02568da5c401477a87f1c321402905116469109eceaaf3fa21a3a253\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":593960842},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["29608e905240c781827e10adafbd89d087afc2bbdccfeeec1ba10100c36188d9#0","687dc5113e0afeba26241f224148d7c7910a2faf802ef2f655ae01f83eb28ca3#1","8c2e816adf8a81b2790b6bdc3616aba8f25c65c373472a1f7112015e2addf17a#1","e24c8fec017a324787e24c0f16cd1699d8418cb0d2b7f4545fd08352aeb1287c#0"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 593960842 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"28799","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"179ae7305cf8d4a4973a09b8fe87eb0da69c12ec9c2a31bd4b1341a5f9dcc979\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26":{"586d617332303231443031333131":1},"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3":{"4c4f4253544552":1000000}},"lovelace":160795573},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["1d4cd2b3fb0b65fe1a01495278aa982eb048812f1409a2ddd1335e657cb97df8#1","55da61d71f7731763c5b7691c7f65e08689abd06b247e04ccded90522f40ebb1#0","bc3c24fe3fc2a67491fd561c67f2a442a22d4271b4b15fa592b272595e291723#3"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 160795573 (fromList [(PolicyID {policyID = ScriptHash \"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26\"},fromList [(\"Xmas2021D01311\",1)]),(PolicyID {policyID = ScriptHash \"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3\"},fromList [(\"LOBSTER\",1000000)])])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"41538","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"ce8e61bba55381f5b132c025657f965367f6bf02a1c058aaf5d10849b7534919\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":2049478087},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["01123543180f03b20df190a7e4b8110ce898cbaf415f9280176005f6563bad9a#1"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 2049478087 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"41538","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"77afb15e02568da5c401477a87f1c321402905116469109eceaaf3fa21a3a253\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":593960842},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["29608e905240c781827e10adafbd89d087afc2bbdccfeeec1ba10100c36188d9#0","687dc5113e0afeba26241f224148d7c7910a2faf802ef2f655ae01f83eb28ca3#1","8c2e816adf8a81b2790b6bdc3616aba8f25c65c373472a1f7112015e2addf17a#1","e24c8fec017a324787e24c0f16cd1699d8418cb0d2b7f4545fd08352aeb1287c#0"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 593960842 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"41538","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"179ae7305cf8d4a4973a09b8fe87eb0da69c12ec9c2a31bd4b1341a5f9dcc979\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26":{"586d617332303231443031333131":1},"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3":{"4c4f4253544552":1000000}},"lovelace":160795573},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["1d4cd2b3fb0b65fe1a01495278aa982eb048812f1409a2ddd1335e657cb97df8#1","55da61d71f7731763c5b7691c7f65e08689abd06b247e04ccded90522f40ebb1#0","bc3c24fe3fc2a67491fd561c67f2a442a22d4271b4b15fa592b272595e291723#3"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 160795573 (fromList [(PolicyID {policyID = ScriptHash \"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26\"},fromList [(\"Xmas2021D01311\",1)]),(PolicyID {policyID = ScriptHash \"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3\"},fromList [(\"LOBSTER\",1000000)])])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"33763","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"ce8e61bba55381f5b132c025657f965367f6bf02a1c058aaf5d10849b7534919\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":2049478087},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["01123543180f03b20df190a7e4b8110ce898cbaf415f9280176005f6563bad9a#1"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 2049478087 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"33763","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"77afb15e02568da5c401477a87f1c321402905116469109eceaaf3fa21a3a253\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":593960842},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["29608e905240c781827e10adafbd89d087afc2bbdccfeeec1ba10100c36188d9#0","687dc5113e0afeba26241f224148d7c7910a2faf802ef2f655ae01f83eb28ca3#1","8c2e816adf8a81b2790b6bdc3616aba8f25c65c373472a1f7112015e2addf17a#1","e24c8fec017a324787e24c0f16cd1699d8418cb0d2b7f4545fd08352aeb1287c#0"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 593960842 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"33763","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"179ae7305cf8d4a4973a09b8fe87eb0da69c12ec9c2a31bd4b1341a5f9dcc979\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26":{"586d617332303231443031333131":1},"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3":{"4c4f4253544552":1000000}},"lovelace":160795573},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["1d4cd2b3fb0b65fe1a01495278aa982eb048812f1409a2ddd1335e657cb97df8#1","55da61d71f7731763c5b7691c7f65e08689abd06b247e04ccded90522f40ebb1#0","bc3c24fe3fc2a67491fd561c67f2a442a22d4271b4b15fa592b272595e291723#3"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 160795573 (fromList [(PolicyID {policyID = ScriptHash \"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26\"},fromList [(\"Xmas2021D01311\",1)]),(PolicyID {policyID = ScriptHash \"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3\"},fromList [(\"LOBSTER\",1000000)])])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.48Z","ns":["cardano.node.Mempool"],"pid":"228770"}
{"thread":"33155","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"ce8e61bba55381f5b132c025657f965367f6bf02a1c058aaf5d10849b7534919\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":2049478087},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["01123543180f03b20df190a7e4b8110ce898cbaf415f9280176005f6563bad9a#1"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 2049478087 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay2","at":"2022-01-05T01:09:55.49Z","ns":["cardano.node.Mempool"],"pid":"228770"}

The other relay (relay1) has only this at the same time (13 lines)

{"thread":"5095","sev":"Info","data":{"mempoolSize":{"bytes":65441,"numTxs":48},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"ce8e61bba55381f5b132c025657f965367f6bf02a1c058aaf5d10849b7534919\"}"},"kind":"TraceMempoolAddedTx"},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.13Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"546","sev":"Info","data":{"mempoolSize":{"bytes":65441,"numTxs":48},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"ce8e61bba55381f5b132c025657f965367f6bf02a1c058aaf5d10849b7534919\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":2049478087},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["01123543180f03b20df190a7e4b8110ce898cbaf415f9280176005f6563bad9a#1"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 2049478087 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.14Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"330","sev":"Info","data":{"mempoolSize":{"bytes":65441,"numTxs":48},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"ce8e61bba55381f5b132c025657f965367f6bf02a1c058aaf5d10849b7534919\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":2049478087},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["01123543180f03b20df190a7e4b8110ce898cbaf415f9280176005f6563bad9a#1"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 2049478087 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.15Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"6174","sev":"Info","data":{"mempoolSize":{"bytes":66145,"numTxs":49},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"77afb15e02568da5c401477a87f1c321402905116469109eceaaf3fa21a3a253\"}"},"kind":"TraceMempoolAddedTx"},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.17Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"5095","sev":"Info","data":{"mempoolSize":{"bytes":66145,"numTxs":49},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"77afb15e02568da5c401477a87f1c321402905116469109eceaaf3fa21a3a253\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":593960842},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["29608e905240c781827e10adafbd89d087afc2bbdccfeeec1ba10100c36188d9#0","687dc5113e0afeba26241f224148d7c7910a2faf802ef2f655ae01f83eb28ca3#1","8c2e816adf8a81b2790b6bdc3616aba8f25c65c373472a1f7112015e2addf17a#1","e24c8fec017a324787e24c0f16cd1699d8418cb0d2b7f4545fd08352aeb1287c#0"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 593960842 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.17Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"716","sev":"Info","data":{"mempoolSize":{"bytes":66145,"numTxs":49},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"ce8e61bba55381f5b132c025657f965367f6bf02a1c058aaf5d10849b7534919\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":2049478087},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["01123543180f03b20df190a7e4b8110ce898cbaf415f9280176005f6563bad9a#1"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 2049478087 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.19Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"546","sev":"Info","data":{"mempoolSize":{"bytes":66145,"numTxs":49},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"77afb15e02568da5c401477a87f1c321402905116469109eceaaf3fa21a3a253\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":593960842},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["29608e905240c781827e10adafbd89d087afc2bbdccfeeec1ba10100c36188d9#0","687dc5113e0afeba26241f224148d7c7910a2faf802ef2f655ae01f83eb28ca3#1","8c2e816adf8a81b2790b6bdc3616aba8f25c65c373472a1f7112015e2addf17a#1","e24c8fec017a324787e24c0f16cd1699d8418cb0d2b7f4545fd08352aeb1287c#0"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 593960842 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.20Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"330","sev":"Info","data":{"mempoolSize":{"bytes":66145,"numTxs":49},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"77afb15e02568da5c401477a87f1c321402905116469109eceaaf3fa21a3a253\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{},"lovelace":593960842},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["29608e905240c781827e10adafbd89d087afc2bbdccfeeec1ba10100c36188d9#0","687dc5113e0afeba26241f224148d7c7910a2faf802ef2f655ae01f83eb28ca3#1","8c2e816adf8a81b2790b6bdc3616aba8f25c65c373472a1f7112015e2addf17a#1","e24c8fec017a324787e24c0f16cd1699d8418cb0d2b7f4545fd08352aeb1287c#0"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 593960842 (fromList [])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.20Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"5095","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"179ae7305cf8d4a4973a09b8fe87eb0da69c12ec9c2a31bd4b1341a5f9dcc979\"}"},"kind":"TraceMempoolAddedTx"},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.29Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"330","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"179ae7305cf8d4a4973a09b8fe87eb0da69c12ec9c2a31bd4b1341a5f9dcc979\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26":{"586d617332303231443031333131":1},"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3":{"4c4f4253544552":1000000}},"lovelace":160795573},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["1d4cd2b3fb0b65fe1a01495278aa982eb048812f1409a2ddd1335e657cb97df8#1","55da61d71f7731763c5b7691c7f65e08689abd06b247e04ccded90522f40ebb1#0","bc3c24fe3fc2a67491fd561c67f2a442a22d4271b4b15fa592b272595e291723#3"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 160795573 (fromList [(PolicyID {policyID = ScriptHash \"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26\"},fromList [(\"Xmas2021D01311\",1)]),(PolicyID {policyID = ScriptHash \"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3\"},fromList [(\"LOBSTER\",1000000)])])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.31Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"6174","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"179ae7305cf8d4a4973a09b8fe87eb0da69c12ec9c2a31bd4b1341a5f9dcc979\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26":{"586d617332303231443031333131":1},"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3":{"4c4f4253544552":1000000}},"lovelace":160795573},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["1d4cd2b3fb0b65fe1a01495278aa982eb048812f1409a2ddd1335e657cb97df8#1","55da61d71f7731763c5b7691c7f65e08689abd06b247e04ccded90522f40ebb1#0","bc3c24fe3fc2a67491fd561c67f2a442a22d4271b4b15fa592b272595e291723#3"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 160795573 (fromList [(PolicyID {policyID = ScriptHash \"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26\"},fromList [(\"Xmas2021D01311\",1)]),(PolicyID {policyID = ScriptHash \"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3\"},fromList [(\"LOBSTER\",1000000)])])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.32Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"546","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"179ae7305cf8d4a4973a09b8fe87eb0da69c12ec9c2a31bd4b1341a5f9dcc979\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26":{"586d617332303231443031333131":1},"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3":{"4c4f4253544552":1000000}},"lovelace":160795573},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["1d4cd2b3fb0b65fe1a01495278aa982eb048812f1409a2ddd1335e657cb97df8#1","55da61d71f7731763c5b7691c7f65e08689abd06b247e04ccded90522f40ebb1#0","bc3c24fe3fc2a67491fd561c67f2a442a22d4271b4b15fa592b272595e291723#3"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 160795573 (fromList [(PolicyID {policyID = ScriptHash \"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26\"},fromList [(\"Xmas2021D01311\",1)]),(PolicyID {policyID = ScriptHash \"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3\"},fromList [(\"LOBSTER\",1000000)])])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.32Z","ns":["cardano.node.Mempool"],"pid":"39759"}
{"thread":"716","sev":"Info","data":{"mempoolSize":{"bytes":66805,"numTxs":50},"tx":{"txid":"txid: TxId {_unTxId = SafeHash \"179ae7305cf8d4a4973a09b8fe87eb0da69c12ec9c2a31bd4b1341a5f9dcc979\"}"},"kind":"TraceMempoolRejectedTx","err":{"produced":{"policies":{"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26":{"586d617332303231443031333131":1},"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3":{"4c4f4253544552":1000000}},"lovelace":160795573},"consumed":{"policies":{},"lovelace":0},"kind":"ValueNotConservedUTxO","badInputs":["1d4cd2b3fb0b65fe1a01495278aa982eb048812f1409a2ddd1335e657cb97df8#1","55da61d71f7731763c5b7691c7f65e08689abd06b247e04ccded90522f40ebb1#0","bc3c24fe3fc2a67491fd561c67f2a442a22d4271b4b15fa592b272595e291723#3"],"error":"This transaction consumed Value 0 (fromList []) but produced Value 160795573 (fromList [(PolicyID {policyID = ScriptHash \"18f59066d205b9ffc4208d9b6cfad2dbdee84dc4a0097e0b9de7db26\"},fromList [(\"Xmas2021D01311\",1)]),(PolicyID {policyID = ScriptHash \"8654e8b350e298c80d2451beb5ed80fc9eee9f38ce6b039fb8706bc3\"},fromList [(\"LOBSTER\",1000000)])])"}},"loc":null,"env":"1.32.1:4f65f","msg":"","app":[],"host":"relay1","at":"2022-01-05T01:09:55.34Z","ns":["cardano.node.Mempool"],"pid":"39759"}
$ curl -s localhost:12798/metrics | grep cardano_node_metrics_Forge
cardano_node_metrics_Forge_node_not_leader_int 18321
cardano_node_metrics_Forge_forge_about_to_lead_int 18321

check your logfile - look what happened before your slot: Slot: 49778704, SlotInEpoch: 357904 as well as after…
if you are using journal:
journalctl -uq cardano-node.service -o cat | grep 49778704 -B5 -A10

check if your BP is performing leadership checks
if you can’t find anything in logs with slot nr 49778704, then the BP node was either down or overutilized

just open the log file and check what is happening before the 49778704 slot…

Hi @thomaspb !

Based on metrics from your BP, seems BP didn’t know that it was a SlotLeader. (You didn’t restarted your BP after missed slot, right?)

You should see something like this:

curl -s localhost:12798/metrics | grep cardano_node_metrics_Forge
cardano_node_metrics_Forge_adopted_int 19
cardano_node_metrics_Forge_forged_int 19
cardano_node_metrics_Forge_forge_about_to_lead_int 491329
cardano_node_metrics_Forge_node_is_leader_int 19
cardano_node_metrics_Forge_node_not_leader_int 491310

Can you remove CNCLI DB and recalculate everything from scratch?

That’s what I would also suggest as next step.

oh, somehow missed the TraceNodeNotLeader post, yeah, @georgem1976 is right… looks like you have an issue with cncli

Sorry but I restarted it before this post

This is probably the last option.
The biggest problem is not that I lost the block, but that I do not know why :cry:

Do you have grafana? If you have, you can check those metrics there.

Thank you for the quick replies. :slight_smile:

if the producer was not aware about that block can be an error generated by cncli (this is happen when you are using wrong vrf files or perhaps cncli db corrupted) can u try to search again on cncli and check the status for that slot?

I made a VM clone to continue the research. I will post the findings (if any)

Also Kes rotating keys should not be expired, not sure this was covered in the replies.

I don’t think the problem has anything to do with cncli. The problem is most likely solely related to cardano-node and something to do with the block producer keys.

The important part in the logs is:

If you are the slot leader, the next log after should be something like:

Jan 05 04:04:00 node1 cardano-node[151911]: [node1:cardano.node.Forge:Info:174
] [2022-01-05 04:04:00.00 UTC] fromList [("val",Object (fromList [("kind",String
 "TraceNodeIsLeader"),("slot",Number 4.9778704e7)])),("credentials",String "Card
ano")]

The important part is: “TraceNodeIsLeader”

If your logs don’t say that then the node didn’t assess that it was the leader. This indicates some problem related to the leadership calculation. As I understand the leadership calculation depends on the keys, stake and nonce values. The stake and nonce values are on-chain whereas the keys are only on your system. Therefore, most likely the problem relates to your keys and whether your cardano-node loaded them.

Do the following:

  1. Determine the start time of your cardano-node with:
startsec=$(curl -s -H 'Accept: application/json' http:/localhost:12788 | jq '.cardano.node.metrics.nodeStartTime.int.val'); startdate="$(date -d @${startsec})"; echo $startdate
  1. Subtract 1-2 seconds from the printed startdate value and use this value to check your logs to see exactly what the cardano-node process logged as its configuration used. Eg:
journalctl --since "2022-01-07 08:48:24" | head -n 10
  1. Review the details of the configuration log which will start with “Node configuration:” and look something like:
Jan 07 08:48:24 node1 cardano-node[166454]: Node configuration: NodeConfiguration {ncNodeIPv4Addr = Just 0.0.0.0, ncNodeIPv6Addr = Nothing, ncNodePortNumber = Just 3000, ncConfigFile = "/opt/cardano/etc/mainnet-config.json", ncTopologyFile = "/opt/cardano/etc/mainnet-topology.json", ncDatabaseFile = "/opt/cardano/db", ncProtocolFiles = ProtocolFilepaths {byronCertFile = Nothing, byronKeyFile = Nothing, shelleyKESFile = Just "/opt/cardano/priv/kes.skey", shelleyVRFFile = Just "/opt/cardano/priv/vrf.skey", shelleyCertFile = Just "/opt/cardano/priv/node.cert", shelleyBulkCredsFile = Nothing}, ncValidateDB = False, ncShutdownIPC = Nothing, ncShutdownOnSlotSynced = NoMaxSlotNo, ... snip ...

The important bit related to your keys is:

shelleyKESFile = Just "/opt/cardano/priv/kes.skey", shelleyVRFFile = Just "/opt/cardano/priv/vrf.skey", shelleyCertFile = Just "/opt/cardano/priv/node.cert"

Note: that these details are for my block producer’s keys which I have stored in “/opt/cardano/priv/”

  1. Check that your keys are stored where your node is looking for them and that they are the correct keys.

Good luck.

1 Like

Hello, I run a small pool (600kADA) and had a block in the leaderlog which I didn’t mint. According to my research, it was my first orphaned block :neutral_face: which is a thing not avoidable by me as the SPO, but I’m not entirely sure, so I’m asking some of you experts here to help me understand it.
I had in my leaderlog:
Slot: 74388345, UTC Time: 2022-10-16 21:10:36
GLiveView showed Leader: 1 and Adopted: 1 short after this time so I already thought I minted this block. I had zero missed slots hours before and after this slot number - so it couldn’t be due to missed slots.

Then I’ve ran VRF hash check as suggested in this thread and made sure it matched the “Vrf Hash” displayed on cardanoscan.io for my pool, and that vrf.skey file was also the file i used for the node startup, which was all good:
cardano-cli key verification-key --signing-key-file vrf.skey --verification-key-file /tmp/vrf.vkey
cardano-cli node key-hash-VRF --verification-key-file /tmp/vrf.vkey

Checking the logs for this slot (cat /var/log/syslog | grep 74388345), I found that for this slot I had a “Switched to a fork”:
Oct 16 23:10:36 SERVERNAME cardano-node[13707]: #033[35m[SERVERNAME:cardano.node.ChainDB:Notice:226]#033[0m [2022-10-16 21:10:36.11 UTC] Chain extended, new tip: 6c5b8d901cf9263981537d9b1396e8684b929a908d6909a2007b9975f1b685b8 at slot 74388345
Oct 16 23:10:36 SERVERNAME cardano-node[13707]: #033[35m[SERVERNAME:cardano.node.ChainDB:Notice:226]#033[0m [2022-10-16 21:10:36.57 UTC] Switched to a fork, new tip: 17dadc10f9c3dc51622352eb45e17d1206a81f10045c54bb6dd498fb28a6878a at slot 74388345

Is this already the explanation that this block was “orphaned”? Since I have “Switched to a fork” for 1.4% of the slots, is there an approx. 1.4% chance to have a block missed because of another pool having the same slot allocated? So with my total 6 blocks, I already hit the 1.4%?
cat /var/log/syslog | grep “Switched to a fork” | wc -l # returns 57
cat /var/log/syslog | grep “Chain extended” | wc -l # returns 4049 → 57/4049=1.5%
(unfortunately I don’t have other relevant stuff in the logs for this block, maybe someone can suggest good logging options for the block producer?)

Next thing I thought, was to see if this correlates to a slot battle. To see this, what is the correct way for this? Go to cexplorer.io, enter slot ID, find “epoch slot” id, enter this on pooltool.io to find the slot battle image?

Thanks a lot for help/hints!

It was a slot battle. Two pools were slot leader for the same slot. Unfortunately your pool lost the “slot battle”. In the past your pool would usually win such a slot battle because it is a very small pool and its leader VRF value would generally be lower than the other pool’s. This is because slot battles used to be determined based on leader VRF value. However, unfortunately the code was changed recently to make slot battles totally random. Slot battles are now determined by the entire block VRF value.

See here for more explanation: Leader VRF value no longer settling ties · Issue #4051 · input-output-hk/ouroboros-network · GitHub

1 Like

Interesting to see different approaches to debugging a missed block. I am attempting to document such things in one thread

If your VRF is correct then it’s probable that the issue is the calculation for slot was incorrect. I had this once before.

The solution was to fix a corrupted cncli db

I don’t think there is much to debug. The logs tell the story. Both blocks were for the same slot 74388345. The second block arrived 460ms after the first at 21:10:36.570 UTC and the node immediately preferred this second block since it switched its tip to this block. So this is not a height battle resolved according to longest chain but rather a simple slot battle. As far as I am aware, the only reason your own node would do this (to immediately prefer the block that it had not produced for the same slot) is if the second block had a lower “block” VRF score.

2 Likes

Thanks for the answers!

What are recommended logging options for the block producer to debug produced blocks and not harm performance?
what are you using as minSeverity?

Note: Lowering the minimal severity harms efficiency , so while using a low severity can be very helpful for debugging a problem, it should be used with care during normal operation.

(cardano-node/logging.md at master · input-output-hk/cardano-node · GitHub)

I just have the default settings in my mainnet-config.json:

  "TracingVerbosity": "NormalVerbosity",
  "minSeverity": "Info",

What you had in your journal logs was already enough to see why your block got orphaned.

It is unfortunate. Your pool would have most likely won that slot battle prior to the 1.35.x software release because SECUR is a much bigger, and multi-pool, operator with 5 separate pools. I really miss the times when small pools were almost guaranteed to win such battles.

1 Like