Log missing chain head as warning, not trace

[matthew1001]

PR description

Change CHAIN_HEAD_NOT_AVAILABLE to a warning, not a trace log entry

Fixed Issue(s)

Fixes #6126

[github-actions]

• I thought about documentation and added the doc-change-required label to this PR if updates are required.
• I thought about the changelog and included a changelog update if required.
• If my PR includes database changes (e.g. KeyValueSegmentIdentifier) I have thought about compatibility and performed forwards and backwards compatibility tests

[garyschulte]

this is blowing up the logs on my test node. We encounter this way too often to make this a warning

[garyschulte]

{"@timestamp":"2023-11-07T00:05:18,003","level":"WARN","thread":"nioEventLoopGroup-3-9","class":"TransactionPool","message":"Discard invalid transaction 0x3124130967cb066ab9a6c5807a96f3147d354ae09f1bb8cda6b95c39033756f1={MessageCall, 51156, 0xa76a91f8b0d7ef28d2b76a703bc0770ba8996bfc, EIP1559, mf: 12 wei, pf: 2 wei, gl: 800000, v: 0 wei, to: 0x9d51bca23612851f98ced6d4f7aac75356d45f58}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,004","level":"WARN","thread":"nioEventLoopGroup-3-9","class":"TransactionPool","message":"Discard invalid transaction 0x5549d54c0b7025b4ba0f38ae06df73ee2e3eb70d2b8865216c136df3d0779d71={MessageCall, 51157, 0xa76a91f8b0d7ef28d2b76a703bc0770ba8996bfc, EIP1559, mf: 12 wei, pf: 2 wei, gl: 800000, v: 0 wei, to: 0x9d51bca23612851f98ced6d4f7aac75356d45f58}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,004","level":"WARN","thread":"nioEventLoopGroup-3-9","class":"TransactionPool","message":"Discard invalid transaction 0x97b1abe588275c401407c4c77146bfed484cac7d262baf3902239ed1df2205c1={MessageCall, 51158, 0xa76a91f8b0d7ef28d2b76a703bc0770ba8996bfc, EIP1559, mf: 12 wei, pf: 2 wei, gl: 800000, v: 0 wei, to: 0x9d51bca23612851f98ced6d4f7aac75356d45f58}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,004","level":"WARN","thread":"nioEventLoopGroup-3-9","class":"TransactionPool","message":"Discard invalid transaction 0xab615870b1fa53c6d3259e537b90c0fdbc171037b60586c9145c669dbd7df115={MessageCall, 51159, 0xa76a91f8b0d7ef28d2b76a703bc0770ba8996bfc, EIP1559, mf: 12 wei, pf: 2 wei, gl: 800000, v: 0 wei, to: 0x9d51bca23612851f98ced6d4f7aac75356d45f58}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,004","level":"WARN","thread":"nioEventLoopGroup-3-9","class":"TransactionPool","message":"Discard invalid transaction 0x56c5a492629efd144aca16ef57c21455bd0685d4fd91e2f19ab8f8321c8e84c3={MessageCall, 51160, 0xa76a91f8b0d7ef28d2b76a703bc0770ba8996bfc, EIP1559, mf: 12 wei, pf: 2 wei, gl: 800000, v: 0 wei, to: 0x9d51bca23612851f98ced6d4f7aac75356d45f58}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,004","level":"WARN","thread":"nioEventLoopGroup-3-9","class":"TransactionPool","message":"Discard invalid transaction 0xce7da2376d040fb5b5463430558437ddd09126908087afc376ba6b98ed1f6dfb={MessageCall, 51161, 0xa76a91f8b0d7ef28d2b76a703bc0770ba8996bfc, EIP1559, mf: 12 wei, pf: 2 wei, gl: 800000, v: 0 wei, to: 0x9d51bca23612851f98ced6d4f7aac75356d45f58}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,004","level":"WARN","thread":"nioEventLoopGroup-3-9","class":"TransactionPool","message":"Discard invalid transaction 0x99c1928d6df041948b4f0e86f7e081562880237d5bc5136446ab70db02be791f={MessageCall, 51162, 0xa76a91f8b0d7ef28d2b76a703bc0770ba8996bfc, EIP1559, mf: 12 wei, pf: 2 wei, gl: 800000, v: 0 wei, to: 0x9d51bca23612851f98ced6d4f7aac75356d45f58}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,084","level":"WARN","thread":"EthScheduler-Transactions-0","class":"TransactionPool","message":"Discard invalid transaction 0xcd3fab021ba2cb0022c71e873c87fcc44b5eca17bea6874bf9845f8e9f52080b={MessageCall, 12074, 0x6b78b7c287b21d4d65cb91bd84eb6b79ab9e8af5, EIP1559, mf: 24 wei, pf: 2 wei, gl: 31628, v: 0 wei, to: 0xff00000000000000000000000000000000000000}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,084","level":"WARN","thread":"EthScheduler-Transactions-0","class":"TransactionPool","message":"Discard invalid transaction 0xd5ffddbae76a7cf76e8a14ca88ae8cd1146758bc2b849406964b365cbfe8d9fb={MessageCall, 43067, 0xe02c9aef141d5bbf78fb20c5d46da5faa635cef7, EIP1559, mf: 24 wei, pf: 2 wei, gl: 26012, v: 0 wei, to: 0xff00000000000000000000000000000000042069}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,589","level":"WARN","thread":"EthScheduler-Transactions-0","class":"TransactionPool","message":"Discard invalid transaction 0x7b2183566b34e459f665df56d2173e0f295755db1a3384e46d5437b23ac9f014={MessageCall, 152692, 0x39b9c34ee948752e640cd01364036dc8468416b8, EIP1559, mf: 24 wei, pf: 2 wei, gl: 31000, v: 0 wei, to: 0xff00000000000000000000000000000000042069}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:18,911","level":"WARN","thread":"EthScheduler-Transactions-0","class":"TransactionPool","message":"Discard invalid transaction 0x541895f95660f310606b554c26b6ce02cd11472d4bdde32543705c0aa371ec26={MessageCall, 0, 0x4fa8acbc72b834f5976a75f917f66c384b3e09a9, FRONTIER, gp: 15 wei, gl: 21000, v: 114.65 finney, to: 0x3fdf957b0054d1617132d4d874eb41d4efe81cff}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:19,001","level":"WARN","thread":"nioEventLoopGroup-3-9","class":"TransactionPool","message":"Discard invalid transaction 0x0309aa802e467da5a1cce6d7c52cf3553f897c58c98f52aae21bc0c41c501c3f={MessageCall, 58315, 0x046f8def6dba949b2e588a67bfa14faef584dfc4, EIP1559, mf: 19 wei, pf: 2 wei, gl: 800000, v: 0 wei, to: 0x117a5ab00f93469bea455f0864ef9ad8d9630cc9}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:19,002","level":"WARN","thread":"nioEventLoopGroup-3-9","class":"TransactionPool","message":"Discard invalid transaction 0x0ed8048bb4886786d1099089e1a735249cbe0c9f993d468d91d746d6d82846ad={MessageCall, 58322, 0x046f8def6dba949b2e588a67bfa14faef584dfc4, EIP1559, mf: 19 wei, pf: 2 wei, gl: 800000, v: 0 wei, to: 0x117a5ab00f93469bea455f0864ef9ad8d9630cc9}, reason GAS_PRICE_TOO_LOW","throwable":""}
{"@timestamp":"2023-11-07T00:05:19,229","level":"WARN","thread":"EthScheduler-Transactions-0","class":"TransactionPool","message":"Discard invalid transaction 0x7aef4bc36c4a77f421f9a487bbcdca35b465ecd4a0a6f01a65e7ed1abe5fa1ec={MessageCall, 270917, 0xbaec44f49df3578749fb299769d723eaccddb605, EIP1559, mf: 24 wei, pf: 2 wei, gl: 26620, v: 0 wei, to: 0xff00000000000000000000000000000000042069}, reason GAS_PRICE_TOO_LOW","throwable":""}

[fab-10]

As said also on discord, I'd like to understand why this happens, before changing the logs.

[garyschulte]

Chain head not available seems to happen on backwards sync. We might be better off disabling txpool while we are doing backwards sync

[matthew1001]

@garyschulte @fab-10 apologies for the noisy logs. I had only intended to change the rejecting transaction log to warn, not the discard transaction one. Think I had both changed locally and inadvertently included both in the commit.

I've just raised #6143 which I think addresses the root cause, at least in the case we've been testing. I've not been able to hit the same error with that fix in place.

@fab-10 - I think the rejecting transaction log being a warning rather than trace is worth keeping in unless we see cases where it produces too much noise.

[fab-10]

Chain head not available seems to happen on backwards sync. We might be better off disabling txpool while we are doing backwards sync

Since we are in the private network field here, I exclude backward sync is involved

[fab-10]

@matthew1001 better not touch the log level by default, since it will be noisy (see the rejected of mainnet graph below) and will make every user worried about what it is happening, instead it is easy to change the log level of a single class at runtime to enable logging these rejected txs, or by the way of a custom log4j configuration.

[matthew1001]

Yes I certainly agree that if this is happening at the rate of several a minute then it's too noisy. But in this case, isn't it only for chain-head not available, which I don't think shows up on the chart above at all? I.e. isn't this a much less likely occurrence, which logging a warning for would seem reasonable to do? I totally agree that the generic Discard transaction log shouldn't be a warning. I just feel that in the scenario we were hitting this, the fact that it was only a trace entry meant we were missing the more fundamental sychronization issue that's being discussed in #6143. If it was a warning, we would have spotted it happening some time ago.

[matthew1001]

I do think an interesting area of discussion, perhaps on the next contributor call, would be logging that has different defaults for PoA/non-PoA setups. I think some enterprise users would want to see more warnings in certain scenarios that public node runners wouldn't be interested in.

[fab-10]

I think having different defaults could be an option, and in case add more documentation on how to tune the log for your use case, and that enterprise user should monitor the metrics to spot if there are not expected rejected tx, since in that case it is better to consume the metrics.