[SERVER-64788] some server log timestamps switch to UTC+DST after startup Created: 22/Mar/22  Updated: 06/Dec/22

Status: Open
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Billy Donahue Assignee: Backlog - Service Architecture
Resolution: Unresolved Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Assigned Teams:
Service Arch
Operating System: ALL
Participants:

 Description   

Mongod is somehow sensitive to DST and putting out timestamps at +01:00, which is not technically an incorrect timestamp but it isn't useful and doesn't line up vertically.

We're clearly trying to put timestamps in GMT and failing.

This behavior seems to start at some point during server initialization, and doesn't affect all executables. mongobridge is unaffected, for example.

https://logkeeper.mongodb.org/lobster/build/ebabdaaa968aa29914a86dfffc247a2c/test/6239d498f84ae8392f66d81f#bookmarks=0%2C92%2C93%2C60413&l=1

[js_test:incremental_backup_rollback] d20030| 2022-03-22T13:52:27.485Z I  -        4672602 [-] "Testing behaviors are enabled. This has serious implications for both performance and security."
[js_test:incremental_backup_rollback] d20030| 2022-03-22T14:52:27.488+01:00 I  CONTROL  23285   [-] "Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"

Somewhere between these lines, the mongod changed timezone.
We started out at 13:52:27.485Z, but 3 milliseconds later the logs wrote 14:52:27.488+01:00, which is in British Summer Time. That's not a timezone we should ever be using in evergreen buildhosts.



 Comments   
Comment by Githook User [ 25/Mar/22 ]

Author:

{'name': 'Billy Donahue', 'email': 'billy.donahue@mongodb.com', 'username': 'BillyDonahue'}

Message: SERVER-64788 demystify time_support_test
Branch: master
https://github.com/mongodb/mongo/commit/1ddb5b1e8aaa5eca91162b3426e46d9e9e833dfb

Comment by Billy Donahue [ 23/Mar/22 ]

I wonder if this code is the culprit. Shouldn't the struct tm be zeroed out before use?

https://github.com/mongodb/mongo/blob/master/src/mongo/util/time_support.cpp#L164

DateStringBuffer& DateStringBuffer::iso8601(Date_t date, bool local) {
    invariant(date.isFormattable());
 
    struct tm t;
    time_t_to_Struct(date.toTimeT(), &t, local);

Comment by Billy Donahue [ 22/Mar/22 ]

henrik.edin any ideas? I don't see anything obvious. It appears that at some point in initialization we switch the server to local time. If the buildhosts are set to UTC, I still don't understand how a DST offset of +01:00 would appear in logs, as UTC doesn't observe DST.
Weird one.

Maybe buildhosts are misconfigured.
Doesn't look like it from this rhel8 spawnhost.

[ec2-user@ip-10-122-36-85 ~]$ timedatectl
               Local time: Tue 2022-03-22 20:29:24 UTC
           Universal time: Tue 2022-03-22 20:29:24 UTC
                 RTC time: Tue 2022-03-22 20:29:24
                Time zone: UTC (UTC, +0000)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

Aside, this does bring up an issue that if local, we use a numeric offset, otherwise "Z". We do this even if the numeric offset happens to be zero. We also could try to identify the zero offset and represent it with "Z" instead of a "+00:00".

Generated at Thu Feb 08 06:01:09 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.