suppress the debug log for unexpected file report

[garyyu]

A minor improvement on debug log, to suppress the following boring unexpected files report. Since these pmmr_leaf.bin.{hash} files are expected to be removed before zipping.

20190213 18:48:02.410 DEBUG grin_chain::txhashset::txhashset - Unexpected file(s) found in txhashset subfolder "/home/garyyu/.grin/main/chain_data/txhashset_zip_00000236631a/kernel", removing.
20190213 18:48:02.410 DEBUG grin_chain::txhashset::txhashset - check_and_remove_files: unexpected file '"/home/garyyu/.grin/main/chain_data/txhashset_zip_00000236631a/kernel/pmmr_leaf.bin"' removed
20190213 18:48:02.410 DEBUG grin_chain::txhashset::txhashset - Unexpected file(s) found in txhashset subfolder "/home/garyyu/.grin/main/chain_data/txhashset_zip_00000236631a/rangeproof", removing.
20190213 18:48:02.410 DEBUG grin_chain::txhashset::txhashset - check_and_remove_files: unexpected file '"/home/garyyu/.grin/main/chain_data/txhashset_zip_00000236631a/rangeproof/pmmr_leaf.bin.0000014f8fb4"' removed
20190213 18:48:02.410 DEBUG grin_chain::txhashset::txhashset - check_and_remove_files: unexpected file '"/home/garyyu/.grin/main/chain_data/txhashset_zip_00000236631a/rangeproof/pmmr_leaf.bin.0000026277b8"' removed
20190213 18:48:02.411 DEBUG grin_chain::txhashset::txhashset - check_and_remove_files: unexpected file '"/home/garyyu/.grin/main/chain_data/txhashset_zip_00000236631a/rangeproof/pmmr_leaf.bin.00000514c11e"' removed
20190213 18:48:02.411 DEBUG grin_chain::txhashset::txhashset - check_and_remove_files: unexpected file '"/home/garyyu/.grin/main/chain_data/txhashset_zip_00000236631a/rangeproof/pmmr_leaf.bin.000000251759"' removed
20190213 18:48:02.411 DEBUG grin_chain::txhashset::txhashset - check_and_remove_files: unexpected file '"/home/garyyu/.grin/main/chain_data/txhashset_zip_00000236631a/rangeproof/pmmr_leaf.bin.0000016dce01"' removed
20190213 18:48:02.411 DEBUG grin_chain::txhashset::txhashset - check_and_remove_files: unexpected file 
 ...

(totally I have 5 pages of such kind of logs)

[antiochp]

Minor: These files are not really "unexpected" files, we fully expect to clean them up over time.
Maybe we should just change the messaging to reflect this?

Something simple like -
"{} files cleaned up from txhashset dir."

[antiochp]

👍

[antiochp]

Testing this locally. Getting into the habit of actually checking PRs out and actually running them.

[antiochp]

Testing this against mainnet with a fast sync and seeing the following.

The CorruptedStorage log messages are concerning. But I'm not immediately sure they are related to this PR.

20190215 14:05:07.816 DEBUG grin_servers::common::types - sync_state: sync_status: TxHashsetDownload { start_time: 2019-02-15T14:01:25.741609Z, downloaded_size: 183160731, total_size: 183160731 } -> TxHashsetSetup
20190215 14:05:07.816 DEBUG grin_chain::chain - txhashset_write: body_head - 40adad0aec27, 0, header_head - 000004d6ff40, 44289, sync_head - 000004d6ff40, 44289
20190215 14:05:08.627 DEBUG grin_chain::chain - txhashset_write: need a state sync for txhashset. oldest block which is not on local chain: 000000bf7e67 at 1
20190215 14:05:09.268 ERROR grin_store::types - Corrupted storage, could not read an entry from data file: IOErr("failed to fill whole buffer", UnexpectedEof)
20190215 14:05:09.331 DEBUG grin_chain::txhashset::txhashset - 1 tmp file(s) found in txhashset subfolder "/antiochp/grin/node_mainnet/chain_data/txhashset/output", 1 removed.
20190215 14:05:09.331 DEBUG grin_chain::txhashset::txhashset - 1 tmp file(s) found in txhashset subfolder "/antiochp/grin/node_mainnet/chain_data/txhashset/rangeproof", 1 removed.
20190215 14:05:09.331 DEBUG grin_chain::txhashset::txhashset - 1 tmp file(s) found in txhashset subfolder "/antiochp/grin/node_mainnet/chain_data/txhashset/kernel", 1 removed.
20190215 14:05:09.332 DEBUG grin_store::leaf_set - leaf_set: copying rewound file /antiochp/grin/node_mainnet/chain_data/txhashset/output/pmmr_leaf.bin.0000013b6298 to /antiochp/grin/node_mainnet/chain_data/txhashset/output/pmmr_leaf.bin
20190215 14:05:09.575 DEBUG grin_store::prune_list - prune_list: bitmap 60699 pos (82008 bytes), pruned_cache 510939 pos (82008 bytes), shift_cache 60699, leaf_shift_cache 60699
20190215 14:05:09.575 DEBUG grin_store::leaf_set - leaf_set: copying rewound file /antiochp/grin/node_mainnet/chain_data/txhashset/rangeproof/pmmr_leaf.bin.0000013b6298 to /antiochp/grin/node_mainnet/chain_data/txhashset/rangeproof/pmmr_leaf.bin
20190215 14:05:09.824 DEBUG grin_store::prune_list - prune_list: bitmap 60699 pos (82008 bytes), pruned_cache 510939 pos (82008 bytes), shift_cache 60699, leaf_shift_cache 60699
20190215 14:05:09.825 DEBUG grin_chain::txhashset::txhashset - About to rebuild header extension from 40adad0aec27 to 0000013b6298.
20190215 14:05:10.467 DEBUG grin_chain::txhashset::txhashset - Truncating header extension.
20190215 14:05:10.467 DEBUG grin_chain::txhashset::txhashset - Re-applying 41408 headers to extension, from 000000bf7e67 to 0000013b6298.
20190215 14:05:11.169 ERROR grin_store::types - Corrupted storage, could not read an entry from data file: IOErr("failed to fill whole buffer", UnexpectedEof)
20190215 14:05:11.607 DEBUG grin_chain::chain - validate_kernel_history: rewinding and validating kernel history (readonly)
20190215 14:05:12.108 DEBUG grin_chain::chain - validate_kernel_history: validated kernel root on 41408 headers
20190215 14:05:12.108 DEBUG grin_chain::chain - txhashset_write: rewinding a 2nd time (writeable)
20190215 14:05:12.108 DEBUG grin_chain::txhashset::txhashset - Rewind to header 0000013b6298 at 41408
20190215 14:05:12.108 DEBUG grin_chain::txhashset::txhashset - input_pos_to_rewind: 0 < 41408, nothing to rewind
20190215 14:05:12.108 DEBUG grin_chain::txhashset::txhashset - txhashset: rewind_to_pos: header 82812, output 829728, kernel 306076
20190215 14:05:12.569 DEBUG grin_chain::txhashset::txhashset - txhashset: validated the header 82812, output 829728, rproof 829728, kernel 306076 mmrs, took 0s
20190215 14:05:13.071 ERROR grin_store::types - Corrupted storage, could not read an entry from data file: IOErr("failed to fill whole buffer", UnexpectedEof)
20190215 14:05:15.240 ERROR grin_store::types - Corrupted storage, could not read an entry from data file: IOErr("failed to fill whole buffer", UnexpectedEof)
20190215 14:05:17.152 ERROR grin_store::types - Corrupted storage, could not read an entry from data file: IOErr("failed to fill whole buffer", UnexpectedEof)

Actually seeing this on master currently as well.
Fast sync completes successfully here and on master so it looks like something unrelated.

This is master -

20190215 14:28:06.164 ERROR grin_store::types - Corrupted storage, could not read an entry from data file: IOErr("failed to fill whole buffer", UnexpectedEof)
20190215 14:28:08.066 ERROR grin_store::types - Corrupted storage, could not read an entry from data file: IOErr("failed to fill whole buffer", UnexpectedEof)
20190215 14:28:10.235 ERROR grin_store::types - Corrupted storage, could not read an entry from data file: IOErr("failed to fill whole buffer", UnexpectedEof)
20190215 14:28:12.151 ERROR grin_store::types - Corrupted storage, could not read an entry from data file: IOErr("failed to fill whole buffer", UnexpectedEof)

[antiochp]

Going to open a separate ticket to investigate the "Corrupted storage" issue separately.