Log growth increased exponentially since the 2.0.2 upgrade

[AngelBlock]

Problem

After upgrading to Anza v2.0.2 by running sh -c "$(curl -sSfL https://release.anza.xyz/v2.0.2/install)" we noticed a significant increase in logging

Now node produces ~70-80Gb of logs per hour.

Not totally sure what contributes most to the increase, but seems like there are a lot of entries like below

[2024-07-17T11:09:56.269371633Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282555425, bbAbtiNZLQVWmURUB2eXJuxbztr46QDEs2CooYyCmKc
[2024-07-17T11:09:56.269379307Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282555425, 5FpqqdC9qpZCTaaesnXRExbSdYvQVLgHjDN6ECeCt4kn
[2024-07-17T11:09:56.269394997Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282555425, 66PxYPFkmLa2xN5vVukn9e3PNsFPRk6vwQTLcVGAzjgG
[2024-07-17T11:09:56.269402300Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282555425, 69c4SaTzaFy6YbJ74ntmybS946EBet2wvpYYh89JDyxi
[2024-07-17T11:09:56.269409173Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282555425, 77AeywWioynv4JNEEScckaeDm1PBQ1NAqbigKa5rYv23
[2024-07-17T11:09:56.269417429Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282555425, 7NRo6KSU38tNMFPqXQg28rKr5XGpbtvYSmCJLaHwqUXk

OS: #26~22.04.1-Ubuntu agave-validator 2.0.2 (src:b5bc3b23; feat:4288794394, client:Agave)

Proposed Solution

Workaround (not a solution) is to change log rotation to hourly, clear up more ofter, or redirect logs to journal and limit the size.

[brooksprumo]

Thanks for the report.

Would you be able to:

1. Upload the log (or some of it) to this issue?
2. Count the number of occurrences of this log line to see if it is the culprit? Something like

   grep "found unpackable account" path_to_log | wc -l

   should do the trick

[AngelBlock]

grep "found unpackable account" path_to_log | wc -l

result of above is 386583348

64G Jul 17 16:26 solana-validator.log. - this is about 3 hours old

what exactly are you looking from from logs, there a plenty, please see below just a few lines of these

[2024-07-16T15:12:52.659921772Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437764, AKnZ8xKR8Y57cd5mbi43jVkDPT8cQHHnsRTsszyQ6Lkd
[2024-07-16T15:12:52.659926170Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437764, FpCXgxr3iodcJSFiKpjVkWtgv9q9NQ88MyeAqhEyQPU7
[2024-07-16T15:12:52.659930528Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437764, HT7o3KSxii6S8B3nF37yfYz8T8fKDnEbGnbuKn5Wfu8c
[2024-07-16T15:12:52.659935357Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437761, 5NnkNvqHm24WKYYd2Xy4fV73zYByZcyjRCqQZmEj2SJN
[2024-07-16T15:12:52.659940186Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437761, BegnLaRKD9d1CbEUpnBoj3Fs287bUWBLJiq3PvdfDQq6
[2024-07-16T15:12:52.659944675Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437761, DcJQy5vWKDDo2KEeq2k9BUNjuwqn9eZjerrhc3hzDbkp
[2024-07-16T15:12:52.659949323Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437760, 7sicnCPUb5ZRKvxGW7SXX6SueZ43DkJENZJ14kMTCnK
[2024-07-16T15:12:52.659954303Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437760, P56PwVfE1teVn6aRUmZPaG7TensZABcMwdKaQ4F3ZmX
[2024-07-16T15:12:52.659958891Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437760, CPPxiGgjHGoH5NVGsR5M7J3bpTJuZyAfxNR1VtMcWeYY
[2024-07-16T15:12:52.659963340Z INFO  solana_accounts_db::ancient_append_vecs] ancient append vec: found unpackable account: 282437760, DgUgWTUiszWrRngeNEVQPzkWK3YNs7Y3ozoKV4KHKNiq

Hope this help

[brooksprumo]

I'm trying to get a sense for how frequent the "found unpackable account" lines were, to see if that was the main problem.

With wc -l returning 386,583,348 lines, and each line being ~180 bytes, that's approximately 70 GB right there.

If that was over 3 hours, and you noticed log growth of 70-80 GB per 1 hour, then the "found unpackage account" logs are roughly one third of that.

So I wonder what the other two thirds are?

[AngelBlock]

I'm trying to get a sense for how frequent the "found unpackable account" lines were, to see if that was the main problem.

With wc -l returning 386,583,348 lines, and each line being ~180 bytes, that's approximately 70 GB right there.

If that was over 3 hours, and you noticed log growth of 70-80 GB per 1 hour, then the "found unpackage account" logs are roughly one third of that.

So I wonder what the other two thirds are?

I didn't give you accurate times, it was approximate, but perhaps this help

its a new logs file, other was rotated: 39G Jul 17 18:14 solana-validator.log

grep "found unpackable account" solana-validator.log | wc -l 225229081

grep -v "found unpackable account" solana-validator.log | wc -l 4061064

wc -l solana-validator.log 229290145 solana-validator.log

So, other none matching lines are only ~1.8%

[brooksprumo]

So, other none matching lines are only ~1.8%

Ok, that makes it pretty clear then! Thanks for the information.

[AngelBlock]

Update: @brooksprumo It has stopped since a couple of days ago, with no changes, restarts, etc on our side.

now the size is as before and as expected: 5.3G Jul 21 10:33 solana-validator.log

grep "found unpackable account" /disk2/solana-validator.log | wc -l 22433278

wc -l /disk2/solana-validator.log 28365052

so found unpackable account still accounts for ~80%, but log size is 200 times smaller