Syncing stopped at height 58214823 - bad block

[ttibord]

System information

OS : Linux
JVM : Private Build 1.8.0_392 amd64
Git : 9e95599
Version : 4.7.2 (upgraded to 4.7.3.1 just in case, no change)
Code : 18031

Expected behaviour

Node to continue syncing.

Actual behaviour

One of our nodes running version 4.7.2 stopped syncing on block height 58214823, following log error now repeats:

14:47:59.687 ERROR [sync-handle-block] [net](TronNetDelegate.java:289) Process block failed, Num:58214824,ID:00000000037849a8aa1faee85a5f373ace9ae9d60829d43e5214fe927c1ccea9, reason: account [TNJZQfCnsmYNoDRFZwKJRrmUNNc8rGi1Rk] has insufficient bandwidth[266] and balance[266000] to create new account
14:47:59.687 ERROR [sync-handle-block] [net](SyncService.java:307) Process sync block Num:58214824,ID:00000000037849a8aa1faee85a5f373ace9ae9d60829d43e5214fe927c1ccea9 failed, type: 10, bad block

We attempted to upgrade to latest version, 4.7.3.1, and the node unwound for a couple of blocks, but stopped at the same one:

Client version: "TRON/v4.7.2/Linux/Java1.8"
Block number: 58214823
Block timestamp: 2024-01-15T00:30:06
System time:     2024-01-17T13:17:31

Client version: "TRON/v4.7.3.1/Linux/Java1.8"
Block number: 58214805
Block timestamp: 2024-01-15T00:29:12
System time:     2024-01-17T13:19:00

Client version: "TRON/v4.7.3.1/Linux/Java1.8"
Block number: 58214817
Block timestamp: 2024-01-15T00:29:48
System time:     2024-01-17T13:19:04

Client version: "TRON/v4.7.3.1/Linux/Java1.8"
Block number: 58214823
Block timestamp: 2024-01-15T00:30:06
System time:     2024-01-17T13:19:05

Client version: "TRON/v4.7.3.1/Linux/Java1.8"
Block number: 58214823
Block timestamp: 2024-01-15T00:30:06
System time:     2024-01-17T14:16:25

This is the first occurrence of log error on block 58214824, 2023-01-15:

00:30:09.492 INFO  [nioEventLoopGroup-6-16] [net](P2pEventHandlerImpl.java:167) Receive message from  peer: /8.217.69.117:45128, type: BLOCK
Num:58214824,ID:00000000037849a8aa1faee85a5f373ace9ae9d60829d43e5214fe927c1ccea9, trx size: 169

00:30:09.492 INFO  [nioEventLoopGroup-6-16] [net](FetchBlockService.java:84) Fetch block success, Num:58214824,ID:00000000037849a8aa1faee85a5f373ace9ae9d60829d43e5214fe927c1ccea9
00:30:09.493 INFO  [nioEventLoopGroup-6-77] [net](P2pEventHandlerImpl.java:167) Receive message from  peer: /198.244.177.175:44788, type: INVENTORY
invType: BLOCK, size: 1, First hash: 00000000037849a8aa1faee85a5f373ace9ae9d60829d43e5214fe927c1ccea9
00:30:09.493 ERROR [PeerClient-52] [DB](Manager.java:1306) account [TNJZQfCnsmYNoDRFZwKJRrmUNNc8rGi1Rk] has insufficient bandwidth[266] and balance[266000] to create new account
org.tron.core.exception.AccountResourceInsufficientException: account [TNJZQfCnsmYNoDRFZwKJRrmUNNc8rGi1Rk] has insufficient bandwidth[266] and balance[266000] to create new account
        at org.tron.core.db.BandwidthProcessor.consume(BandwidthProcessor.java:153)
        at org.tron.core.db.Manager.consumeBandwidth(Manager.java:954)
        at org.tron.core.db.Manager.processTransaction(Manager.java:1432)
        at org.tron.core.db.Manager.processBlock(Manager.java:1728)
        at org.tron.core.db.Manager.applyBlock(Manager.java:1012)
        at org.tron.core.db.Manager.pushBlock(Manager.java:1298)
        at org.tron.core.net.TronNetDelegate.processBlock(TronNetDelegate.java:260)
        at org.tron.core.net.messagehandler.BlockMsgHandler.processBlock(BlockMsgHandler.java:147)
        at org.tron.core.net.messagehandler.BlockMsgHandler.processMessage(BlockMsgHandler.java:89)
        at org.tron.core.net.P2pEventHandlerImpl.processMessage(P2pEventHandlerImpl.java:196)
...

We have two more nodes running 4.7.2 that passed that block normally and are in sync, as well as a DB snapshot from this node some 20 hours before the offending block, so checking here to see:

1. if I can do something more precise to the stuck node besides copying a healthy DB to resume, or syncing from last snapshot
2. if our current node state is useful for troubleshooting a bug

Otherwise very happy with TRON stability, thanks for all the work!

[ferdinand026]

@ttibord 1. This is caused by the node database which is not consistent with others. The solution can be: stopping one normal node correctly, then copy the DB. Or redownload a snapshot. 2. There are many reasons for database damage, such as abnormal node stop, the status of the machine at that time, etc.

[inapeace0]

Hello, @ttibord
This is my private question for the installation of a full node. I'm also installing a full node and it's in the process of sync.
Could you please tell me how long it took to finish sync? I started it a month ago, but it's not finished yet.
I'm a bit bored. 😁😢
Thanks.

[ttibord]

@ferdinand026 Gotcha, thanks! No problem to restore DB if there are no other options (unwinding on upgrade made me hopeful). This can be closed, as far as I'm concerned.

@CaCaBlocker In my experience a watched node never catches up so you have to convincingly not care 😆 We synced TRON from snapshots, so can't help with a serious answer, sorry. Semi-helpful is to chart time diff from head, and then watch the curve flatten and boredom transform into something else. I hope you get better answers from the team 🍀

[inapeace0]

Hi, @ttibord
Thanks for your kind answer.
But I also downloaded snapshots, unzipped them, and started a node.
You can refer to this, and I'm sure you will fully understand my mind.
#5640

I want to know my fault and figure out this asap.
Thanks.

[ttibord]

@CaCaBlocker Yeah, month of syncing from days-old snapshot sounds weird, thought it was from genesis and that you were not in a hurry. I just started downloading the latest official snapshot to test and will report our syncing experience back in your issue, as it seems unrelated to this one.

[ttibord]

@ferdinand026 Actually you can help additionally, because I am seeing more syncing problems with daily snapshots on the machine where error occurred (and downloading the official snapshot again in parallel as the advised solution).

1. The snapshot before got stuck on the same block, presumably because the error in DB was older and the recent transaction just revealed the issue with DB state for this account?

# snapshot from 2024-01-14_05:30:08
Client version: "TRON/v4.7.3.1/Linux/Java1.8"
Block number: 58214823
Block timestamp: 2024-01-15T00:30:06

2. snapshot 24 hours before that one gets stuck on a different block:

# snapshot from 2024-01-13_05:30:07
Client version: "TRON/v4.7.3.1/Linux/Java1.8"
Block number: 58200503
Block timestamp: 2024-01-14T12:33:54

Error in logs this time is:

12:43:26.783 INFO  [sync-handle-block] [DB](PendingManager.java:57) Pending tx size: 0.
12:43:26.783 ERROR [sync-handle-block] [net](TronNetDelegate.java:289) Process block failed, Num:58200504,ID:00000000037811b871fd19eba5529b519452145520c931127c2b779096b6fdf0, reason: account [TVREKRwTtrAb2Rd8Wmp9ujkmR7F3522wga] does not exist
12:43:26.783 ERROR [sync-handle-block] [net](SyncService.java:307) Process sync block Num:58200504,ID:00000000037811b871fd19eba5529b519452145520c931127c2b779096b6fdf0 failed, type: 10, bad block
12:43:26.783 INFO  [sync-handle-block] [net](PeerConnection.java:175) Send peer /141.95.126.145:42848 message type: P2P_DISCONNECT

Currently testing the previous daily snapshot, just for completeness, but I am doubting our snapshot approach in general, as the nodes where we are not making snapshots on work normally. This machine stops and resumes TRON service daily to create a ZFS snapshot, with no IO errors detected on the pool with raidz. Node shutdown seems clean in app logs:

05:30:01.740 INFO  [Thread-7] [app](ApplicationImpl.java:74) ******** start to shutdown ********
05:30:01.740 INFO  [nioEventLoopGroup-6-150] [net](P2pChannelInitializer.java:44) Close channel:/135.125.188.185:46212
05:30:01.740 INFO  [nioEventLoopGroup-6-116] [net](P2pChannelInitializer.java:44) Close channel:/148.251.121.154:54260
05:30:01.740 INFO  [nioEventLoopGroup-6-96] [net](P2pChannelInitializer.java:44) Close channel:/128.140.85.88:29750
05:30:01.740 INFO  [nioEventLoopGroup-6-97] [net](P2pChannelInitializer.java:44) Close channel:/135.125.189.109:44142
05:30:01.740 INFO  [nioEventLoopGroup-6-187] [net](P2pChannelInitializer.java:44) Close channel:/176.9.144.165:39644
05:30:01.740 INFO  [nioEventLoopGroup-6-22] [net](P2pChannelInitializer.java:44) Close channel:/170.187.189.31:30256
... a lot more log lines that don't seem problematic, but can attach if useful
05:30:04.437 INFO  [Thread-7] [DB](ChainBaseManager.java:249) ******** Begin to close PbftSignDataStore. ********
05:30:04.437 INFO  [Thread-7] [DB](ChainBaseManager.java:255) ******** End to close PbftSignDataStore. ********
05:30:04.437 INFO  [Thread-7] [DB](ChainBaseManager.java:249) ******** Begin to close SectionBloomStore. ********
05:30:05.232 INFO  [Thread-7] [DB](ChainBaseManager.java:255) ******** End to close SectionBloomStore. ********
05:30:05.232 INFO  [Thread-7] [DB](ChainBaseManager.java:249) ******** Begin to close AccountAssetStore. ********
05:30:05.256 INFO  [Thread-7] [DB](ChainBaseManager.java:255) ******** End to close AccountAssetStore. ********
05:30:05.256 INFO  [Thread-7] [DB](Manager.java:1924) ******** End to close db. ********
05:30:05.268 INFO  [Thread-7] [o.t.c.l.EventPluginLoader](EventPluginLoader.java:461) eventPlugin stopped
05:30:05.268 INFO  [Thread-7] [app](DynamicArgs.java:111) Closing the dynamic loading configuration service
05:30:05.268 INFO  [Thread-7] [app](ApplicationImpl.java:89) ******** end to shutdown ********
... snapshot made here, and start-up follows
05:30:13.134 INFO  [main] [app](FullNode.java:55) Full node running.

Other than the restarts for snapshots node seems to run normally for months, and we would like to have a reliable way of creating local snapshots. Can you advise?

[ferdinand026]

@ttibord You have one machine to do the DB snapshot daily, so the first thing we should ensure the snapshot's correctness, Tron supports to stop at a certain condition, then you can do the DB backup. The stop condition can be one of the below configuration items.

node.shutdown = {
  # BlockTime  = "54 59 08 * * ?" # if block header time in persistent db matched.
  BlockHeight = 33350800 # if block header height in persistent db matched.
  # BlockCount = 12 # block sync count after node start.
}

After configuring the stop condition, then the node will stop automatically when the condition is meet. I think you may have a try with this way to ensure the node stops correctly, then do the snapshot backup.

[inapeace0]

Hello, @ttibord
Could you recommend a good service to purchase a server for the Tron full node?
I would like to change my server for the future matter.
Thanks.

[ttibord]

@ferdinand026 thank you, will try and post here!

@CaCaBlocker Contabo dedicated server with SSDs worked for us, they're crypto-friendly and service was decent.