The time zone of the log is changed from East 8 to UTC when starting wdpost

bruce20319 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

[X] lotus daemon - chain sync
[X] lotus miner - mining and block production
[ ] lotus miner/worker - sealing
[X] 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)
[ ] Other

Lotus Version

lotus-miner version 1.15.2+mainnet+git.518dc962e.dirty

Describe the Bug

The time zone of the log is changed from East 8 to UTC when starting wdpost

Logging Information

May 07 15:30:52 mXJHY lotus-miner[13876]: 2022-05-07T15:30:52.369+0800        DEBUG        advmgr        sector-storage/sched.go:457        SCHED windows: [{allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]} {allocated:{memUsedMin:0 memUsedMax:0 gpuUsed:0 cpuUse:0 cond:<nil> waiting:0} todo:[]}]
May 07 15:30:52 mXJHY lotus-miner[13876]: 2022-05-07T15:30:52.370+0800        DEBUG        advmgr        sector-storage/sched.go:458        SCHED Acceptable win: [[] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] [] []]
May 07 15:30:52 mXJHY lotus-miner[13876]: 2022-05-07T07:30:52.778 INFO storage_proofs_core::compound_proof > vanilla_proofs:finish
May 07 15:30:52 mXJHY lotus-miner[13876]: 2022-05-07T07:30:52.783 INFO storage_proofs_core::compound_proof > snark_proof:start
May 07 15:30:52 mXJHY lotus-miner[13876]: 2022-05-07T07:30:52.784 INFO bellperson::groth16::prover > Bellperson 0.18.0 is being used!
May 07 15:30:52 mXJHY lotus-miner[13876]: 2022-05-07T07:30:52.941 INFO bellperson::groth16::prover > synthesis time: 156.965424ms
May 07 15:30:52 mXJHY lotus-miner[13876]: 2022-05-07T07:30:52.941 INFO bellperson::groth16::prover > starting proof timer
May 07 15:30:52 mXJHY lotus-miner[13876]: 2022-05-07T07:30:52.961 INFO bellperson::gpu::locks > GPU is available for FFT!

Repo Steps

just check syslog

rjan90 commented 2 years ago

Thanks for the report @bruce20319!

I have filed an issue about the Time-zone changes in the logs here: https://github.com/filecoin-project/rust-fil-logger/issues/17.

rjan90 commented 2 years ago

Answer from vmx in the rust-fil-logger issue:

This issue occurs in multithreaded programs, and Lotus is multithreaded. Lotus would need to initialize the logger while it's still single threaded (I don't know if that's possible in Go). Then you would get the local time.

If you compile from source, you can try setting RUSTFLAGS="--cfg unsound_local_offset", though be aware that it [might lead to unexpected segmentation faults](https://docs.rs/time/0.3.5/time/#feature-flags).

The folks from chrono are working on a proper fix at https://github.com/chronotope/chrono/pull/677. flexi_logger has already a way to use chrono for that offset calculation, so I'd expect that at some time in the future we'll get local times back without any hacks.

So it seems that a fix is on the way.

johnnymatthews commented 2 years ago

I'm getting the same error, but for some reason that unsound_local_offset flag doesn't seem to be fixing the problem. I'm trying use_chrono_for_offset instead (seen here).

Never mind, that didn't fix it either.

rjan90 commented 2 years ago

Hey! To my knowledge the error seems to have been fixed in the chrono-dependecy. So we will just have to wait until they release a new version, and for that version to bubble up into rust-fil-logger and then Lotus!

rjan90 commented 1 year ago

Closing this issue now since the chrono fixes has made their way into Lotus dependecies, and the timezone for the RUST_LOGs now are in your local time.

Tested by changing the timezone to NY time:

root@Ubuntu-2004-focal-amd64-base ~ # timedatectl
               Local time: Sun 2023-03-05 06:17:20 EST  
           Universal time: Sun 2023-03-05 11:17:20 UTC  
                 RTC time: Sun 2023-03-05 11:17:20      
                Time zone: America/New_York (EST, -0500)
System clock synchronized: yes                          
              NTP service: active                       
          RTC in local TZ: no

And running a lotus-miner proving compute window-post to get RUST_LOGs:

2023-03-05T06:14:02.176-0500    INFO    wdpost  wdpost/wdpost_run.go:260        starting PoSt cycle     {"cycle": "2023-03-05T06:14:02.176-0500", "manual": true, "ts": "[bafy2bzacec3h3tqh4xcp7z2gx4tcm6u26ohl4hwxo7wuvw5hycvbdrqw6grqo]", "deadline": 2}
2023-03-05T06:14:02.178 INFO filcrypto::util::types > generate_fallback_sector_challenges: start
2023-03-05T06:14:02.178 INFO filecoin_proofs::api::post_util > generate_sector_challenges:start
2023-03-05T06:14:02.178 INFO filecoin_proofs::api::post_util > generate_sector_challenges:finish
2023-03-05T06:14:02.178 INFO filcrypto::util::types > generate_fallback_sector_challenges: end
2023-03-05T06:14:02.178 INFO filcrypto::util::types > generate_single_vanilla_proof: start
2023-03-05T06:14:02.178 INFO filecoin_proofs::api::post_util > generate_single_vanilla_proof:start: SectorId(33)
2023-03-05T06:14:02.197 INFO filecoin_proofs::api::post_util > generate_single_vanilla_proof:finish: SectorId(33)
2023-03-05T06:14:02.198 INFO filcrypto::util::types > generate_single_vanilla_proof: end

The logs are now consistent with the local time.

filecoin-project / lotus