Fix potentially negative Timestamp in logs.

This bug was activated by [1] when we started to store the timestamp
in the webrtc::Timestamp class (causing an RTC_DCHECK to trigger) but
it has been in the codebase for long time (but without using
webrtc::Timestamp the RTC_DCHECK was not triggered).

Basically, LogStartTime() can be called externally to create a baseline
for logging but if that is not the case, LogMessage should call it [2]
and initialise the baseline.

This was happening in reverse order, causing the first LogMessage to
call LogStartTime() after the SystemTimeMillis(), causing a negative
time difference that when gets wrapped into webrtc::Timestamp triggers
the RTC_DCHECK [3].


[1] - https://webrtc-review.googlesource.com/c/src/+/269249
[2] - https://source.chromium.org/chromium/chromium/src/+/main:third_party/webrtc/rtc_base/logging.h;l=493-497;drc=821b92a66ed661714cc21020b5a045fcd18d0176
[3] - https://source.chromium.org/chromium/chromium/src/+/main:third_party/webrtc/rtc_base/units/unit_base.h;l=122;drc=6dcd43f1e4f2f3ec0bd844cd45e011e9c4d16e38

Bug: b/238157120
Change-Id: I891799316503030c0df5e10e759a61dfc5e1ab3c
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/271582
Reviewed-by: Tomas Gunnarsson <tommi@webrtc.org>
Commit-Queue: Tomas Gunnarsson <tommi@webrtc.org>
Cr-Commit-Position: refs/heads/main@{#37770}
This commit is contained in:
Mirko Bonadei 2022-08-12 15:38:43 +02:00 committed by WebRTC LUCI CQ
parent dfb9e8b02c
commit 57574ea577

View file

@ -138,9 +138,10 @@ LogMessage::LogMessage(const char* file,
int err) {
log_line_.set_severity(sev);
if (log_timestamp_) {
int64_t log_start_time = LogStartTime();
// Use SystemTimeMillis so that even if tests use fake clocks, the timestamp
// in log messages represents the real system time.
int64_t time = TimeDiff(SystemTimeMillis(), LogStartTime());
int64_t time = TimeDiff(SystemTimeMillis(), log_start_time);
// Also ensure WallClockStartTime is initialized, so that it matches
// LogStartTime.
WallClockStartTime();