`RUST_LOG=debug` time/date is not showing

Reiers commented 2 years ago

Checklist

[X] This is not a security-related bug/issue. If it is, please follow please follow the security policy.
[X] This is not a question or a support request. If you have any lotus related questions, please ask in the lotus forum.
[X] This is not a new feature request. If it is, please file a feature request instead.
[X] This is not an enhancement request. If it is, please file a improvement suggestion instead.
[X] I have searched on the issue tracker and the lotus forum, and there is no existing related issue or discussion.
[X] I am running the Latest release, or the most recent RC(release canadiate) for the upcoming release or the dev branch(master), or have an issue updating to any of these.
[X] I did not make any code changes to lotus.

Lotus component

[ ] lotus daemon - chain sync
[ ] lotus miner - mining and block production
[ ] lotus miner/worker - sealing
[ ] lotus miner - proving(WindowPoSt)
[ ] lotus miner/market - storage deal
[ ] lotus miner/market - retrieval deal
[ ] lotus miner/market - data transfer
[ ] lotus client
[ ] lotus JSON-RPC API
[ ] lotus message management (mpool)
[X] Other

Lotus Version

Daemon:  1.15.2-rc1+mainnet+git.dcf6f6414+api1.5.0
Local: lotus version 1.15.2-rc1+mainnet+git.dcf6f6414

Describe the Bug

With RUST_LOG=debugenv. Time and dates are messed up in the logs, on v1.15.2-rc1.

Feel free too close if a fix is already merged.

See snippet from winningPost worker.

Its the same for wdPost worker and if the miner does it.

Logging Information

%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: 2 working device(s) selected. (CPU utilization: 0)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 0: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 1: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::multiexp > GPU Multiexp kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > prover time: 1.051676894s
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > trying parameters memory cache for: WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > found params in memory cache for WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:start
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > Bellperson 0.18.2 is being used!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > synthesis time: 76.044973ms
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > starting proof timer
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for FFT!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: 2 working device(s) selected. 
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 0: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 1: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::domain > GPU FFT kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for Multiexp!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: 2 working device(s) selected. (CPU utilization: 0)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 0: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 1: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::multiexp > GPU Multiexp kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > prover time: 930.448603ms
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > trying parameters memory cache for: WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > found params in memory cache for WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:start
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > Bellperson 0.18.2 is being used!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > synthesis time: 81.410931ms
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > starting proof timer
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for FFT!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: 2 working device(s) selected. 
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 0: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 1: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::domain > GPU FFT kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for Multiexp!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: 2 working device(s) selected. (CPU utilization: 0)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 0: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 1: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::multiexp > GPU Multiexp kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > prover time: 1.323812592s
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > trying parameters memory cache for: WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > found params in memory cache for WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:start
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > Bellperson 0.18.2 is being used!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > synthesis time: 80.108429ms
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > starting proof timer
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for FFT!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: 2 working device(s) selected. 
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 0: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 1: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::domain > GPU FFT kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for Multiexp!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: 2 working device(s) selected. (CPU utilization: 0)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 0: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 1: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::multiexp > GPU Multiexp kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > prover time: 1.016691432s
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > trying parameters memory cache for: WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > found params in memory cache for WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:start
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > Bellperson 0.18.2 is being used!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > synthesis time: 71.22486ms
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > starting proof timer
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for FFT!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: 2 working device(s) selected. 
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 0: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 1: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::domain > GPU FFT kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for Multiexp!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: 2 working device(s) selected. (CPU utilization: 0)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 0: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 1: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::multiexp > GPU Multiexp kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > prover time: 790.88991ms
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > trying parameters memory cache for: WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::caches > found params in memory cache for WINNING_POST[34359738368]
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:start
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > single_partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::post_util > partition_vanilla_proofs:finish
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:start
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > Bellperson 0.18.2 is being used!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > synthesis time: 185.509121ms
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > starting proof timer
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for FFT!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: 2 working device(s) selected. 
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 0: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::fft > FFT: Device 1: NVIDIA GeForce RTX 3090
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::domain > GPU FFT kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::locks > GPU is available for Multiexp!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::program > Using kernel on CUDA.
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: 2 working device(s) selected. (CPU utilization: 0)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 0: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::gpu::multiexp > Multiexp: Device 1: NVIDIA GeForce RTX 3090 (Chunk-size: 18061702)
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::multiexp > GPU Multiexp kernel instantiated!
%Y-%m-%dT%H:%M:%S%.3f INFO bellperson::groth16::prover > prover time: 1.437755102s
%Y-%m-%dT%H:%M:%S%.3f INFO storage_proofs_core::compound_proof > snark_proof:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filecoin_proofs::api::winning_post > generate_winning_post_with_vanilla:finish
%Y-%m-%dT%H:%M:%S%.3f INFO filcrypto::proofs::api > generate_winning_post_with_vanilla: finish

Repo Steps

export RUST_LOG=debug

lotus-miner run

See broken times in log.

jennijuju commented 2 years ago

@cryptonemo this lies under rust proof side of the things i think?

RobQuistNL commented 2 years ago

Was about to say it, yes:

{"level":"info","ts":"%Y-%m-%dT%H:%M:%S%.3f%z","logger":"storage_proofs_core::compound_proof","caller":"/home/lotus/.cargo/registry/src/github.com-1ecc6299db9ec823/storage-proofs-core-11.0.2/src/compound_proof.rs:92","msg":"vanilla_proofs:start"}
{"level":"info","ts":"%Y-%m-%dT%H:%M:%S%.3f%z","logger":"storage_proofs_core::compound_proof","caller":"/home/lotus/.cargo/registry/src/github.com-1ecc6299db9ec823/storage-proofs-core-11.0.2/src/compound_proof.rs:96","msg":"vanilla_proofs:finish"}
{"level":"info","ts":"%Y-%m-%dT%H:%M:%S%.3f%z","logger":"storage_proofs_core::compound_proof","caller":"/home/lotus/.cargo/registry/src/github.com-1ecc6299db9ec823/storage-proofs-core-11.0.2/src/compound_proof.rs:102","msg":"snark_proof:start"}
{"level":"info","ts":"%Y-%m-%dT%H:%M:%S%.3f%z","logger":"bellperson::groth16::prover","caller":"/home/lotus/.cargo/registry/src/github.com-1ecc6299db9ec823/bellperson-0.18.2/src/groth16/prover.rs:253","msg":"Bellperson 0.18.2 is being used!"}

this seems to be in storage-proofs-core-11.0.2

leveleven commented 2 years ago

see https://github.com/filecoin-project/rust-fil-logger/commit/429ee9065b6ad77c9e77a00633275230665cdd6f

rjan90 commented 2 years ago

The new v1.15.2-rc2 has the updated ffi which includes a fix for this. So closing this issue for now.

filecoin-project / lotus