Reduce log verbosity

[Stebalien]

Enabling info logging currently causes nodes to fall out of sync due to a flood of messages like:

2021-10-08T00:09:24.757 INFO filecoin_proofs::pieces > verifying 1 pieces
2021-10-08T00:09:24.757 INFO filecoin_proofs::api::seal > compute_comm_d:finish
2021-10-08T00:09:24.757 INFO filcrypto::proofs::api > generate_data_commitment: finish
2021-10-08T00:09:24.757 INFO filcrypto::proofs::api > generate_data_commitment: start
2021-10-08T00:09:24.757 INFO filecoin_proofs::api::seal > compute_comm_d:start
2021-10-08T00:09:24.757 INFO filecoin_proofs::pieces > verifying 1 pieces
2021-10-08T00:09:24.757 INFO filecoin_proofs::api::seal > compute_comm_d:finish
2021-10-08T00:09:24.757 INFO filcrypto::proofs::api > generate_data_commitment: finish
2021-10-08T00:09:24.758 INFO filcrypto::proofs::api > generate_data_commitment: start
2021-10-08T00:09:24.758 INFO filecoin_proofs::api::seal > compute_comm_d:start
2021-10-08T00:09:24.758 INFO filecoin_proofs::pieces > verifying 1 pieces
2021-10-08T00:09:24.758 INFO filecoin_proofs::api::seal > compute_comm_d:finish
2021-10-08T00:09:24.758 INFO filcrypto::proofs::api > generate_data_commitment: finish
2021-10-08T00:09:24.758 INFO filcrypto::proofs::api > generate_data_commitment: start

2021-10-08T00:09:25.105 INFO filecoin_proofs::api::seal > got verifying key (68719476736) while verifying seal
2021-10-08T00:09:25.105 INFO filecoin_proofs::api::seal > verify_seal:finish: SectorId(15312)
2021-10-08T00:09:25.106 INFO filcrypto::proofs::api > verify_seal: finish
2021-10-08T00:09:25.106 INFO filcrypto::proofs::api > verify_seal: start
2021-10-08T00:09:25.106 INFO filecoin_proofs::api::seal > verify_seal:start: SectorId(1512883)
2021-10-08T00:09:25.106 INFO filecoin_proofs::caches > trying parameters memory cache for: STACKED[68719476736]-verifying-key
2021-10-08T00:09:25.106 INFO filecoin_proofs::caches > found params in memory cache for STACKED[68719476736]-verifying-key
2021-10-08T00:09:25.106 INFO filecoin_proofs::api::seal > got verifying key (68719476736) while verifying seal
2021-10-08T00:09:25.106 INFO filecoin_proofs::api::seal > verify_seal:finish: SectorId(143174)
2021-10-08T00:09:25.106 INFO filcrypto::proofs::api > verify_seal: finish
2021-10-08T00:09:25.106 INFO filcrypto::proofs::api > verify_seal: start
2021-10-08T00:09:25.106 INFO filecoin_proofs::api::seal > verify_seal:start: SectorId(44431)
2021-10-08T00:09:25.106 INFO filecoin_proofs::caches > trying parameters memory cache for: STACKED[34359738368]-verifying-key
2021-10-08T00:09:25.106 INFO filecoin_proofs::caches > found params in memory cache for STACKED[34359738368]-verifying-key
2021-10-08T00:09:25.106 INFO filecoin_proofs::api::seal > got verifying key (34359738368) while verifying seal
2021-10-08T00:09:25.106 INFO filecoin_proofs::api::seal > verify_seal:finish: SectorId(78605)
2021-10-08T00:09:25.106 INFO filecoin_proofs::api::seal > verify_seal:finish: SectorId(16609)
2021-10-08T00:09:25.106 INFO filcrypto::proofs::api > verify_seal: finish
2021-10-08T00:09:25.106 INFO filcrypto::proofs::api > verify_seal: start
2021-10-08T00:09:25.106 INFO filecoin_proofs::api::seal > verify_seal:start: SectorId(242314)
2021-10-08T00:09:25.106 INFO filecoin_proofs::caches > trying parameters memory cache for: STACKED[68719476736]-verifying-key

2021-10-08T00:09:24.973 INFO filecoin_proofs::api::seal > compute_comm_d:finish
2021-10-08T00:09:24.973 INFO filcrypto::proofs::api > generate_data_commitment: finish
2021-10-08T00:09:24.974 INFO filcrypto::proofs::api > generate_data_commitment: start
2021-10-08T00:09:24.974 INFO filecoin_proofs::api::seal > compute_comm_d:start
2021-10-08T00:09:24.974 INFO filecoin_proofs::pieces > verifying 1 pieces
2021-10-08T00:09:24.974 INFO filecoin_proofs::api::seal > compute_comm_d:finish
2021-10-08T00:09:24.974 INFO filcrypto::proofs::api > generate_data_commitment: finish
2021-10-08T00:09:24.974 INFO filcrypto::proofs::api > generate_data_commitment: start
2021-10-08T00:09:24.974 INFO filecoin_proofs::api::seal > compute_comm_d:start
2021-10-08T00:09:24.974 INFO filecoin_proofs::pieces > verifying 1 pieces
2021-10-08T00:09:24.974 INFO filecoin_proofs::api::seal > compute_comm_d:finish
2021-10-08T00:09:24.974 INFO filcrypto::proofs::api > generate_data_commitment: finish
2021-10-08T00:09:24.975 INFO filcrypto::proofs::api > generate_data_commitment: start
2021-10-08T00:09:24.975 INFO filecoin_proofs::api::seal > compute_comm_d:start
2021-10-08T00:09:24.975 INFO filecoin_proofs::pieces > verifying 1 pieces
2021-10-08T00:09:24.975 INFO filecoin_proofs::api::seal > compute_comm_d:finish
2021-10-08T00:09:24.975 INFO filcrypto::proofs::api > generate_data_commitment: finish
2021-10-08T00:09:24.978 INFO filcrypto::proofs::api > generate_data_commitment: start
2021-10-08T00:09:24.978 INFO filecoin_proofs::api::seal > compute_comm_d:start
2021-10-08T00:09:24.978 INFO filecoin_proofs::pieces > verifying 1 pieces

These should all be debug.

[arajasek]

Note we're not sure that that's what's causing nodes to fall out of sync, but agree with the suggestion

[cryptonemo]

It sounds very unlikely a culprit to sync issues (or at least hasn't changed much recently). But we can tweak some logging and levels.

[Stebalien]

@cryptonemo the default log level appears to be warn (I think?). The user in question enabled debug logging, then their node started falling out of sync. I'd expect debug logging to cause that regardless, but these messages still shouldn't be logged as infos.

[Stebalien]

Or maybe just off?

[Stebalien]

I guess the question is: do we run any nodes with this level of logging enabled?

[cryptonemo]

I guess the question is: do we run any nodes with this level of logging enabled?

Fair question. I don't run it on my node. Generally, we only advise enabling logging when there are failures being investigated. I agree that the info/debug/trace levels need adjustment though.