--trace-time shows incorrect timestamps

[jethrogb]

I did this

When using the --trace-time option, curl doesn't print the actual time, but some other time:

$ strace -tt -etrace=connect curl --trace-time https://github.com --verbose
10:44:59.048287 * TCP_NODELAY set
10:44:59.174363 connect(5, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("140.82.116.4")}, 16) = -1 EINPROGRESS (Operation now in progress)
10:44:59.077392 * Connected to github.com (140.82.116.4) port 443 (#0)
...

I expected the following

The timestamps printed by curl shouldn't be ~100ms off from the ones printed by strace.

curl/libcurl version

curl 7.68.0 (x86_64-pc-linux-gnu) libcurl/7.68.0 OpenSSL/1.1.1f zlib/1.2.11 brotli/1.0.7 libidn2/2.2.0 libpsl/0.21.0 (+libidn2/2.2.0) libssh/0.9.3/openssl/zlib nghttp2/1.40.0 librtmp/2.3
Release-Date: 2020-01-08
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS brotli GSS-API HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL TLS-SRP UnixSockets

operating system

Ubuntu 20.04

[jethrogb]

I dug into the code a little bit, and it appears curl is combining the subsecond numbers from the MONOTONIC clock with the hours, minutes, seconds from the REALTIME clock. The MONOTONIC clock doesn't represent walltime and should only be used to calculate durations (time differences). AFAICT, all tracing tools that include timestamps (strace, tcpdump) use the REALTIME clock.

See for example the different clocks on my system right now:

$ lsclocks 
ID NAME             TYPE                 TIME RESOL                            ISO_TIME
 0 realtime         sys  1732042151.879344492   1ns 2024-11-19T18:49:11.879344492+00:00
 1 monotonic        sys      201005.754070539   1ns 1970-01-03T07:50:05.754070539+00:00

[dfandrich]

Are you looking at the latest code? 7.68.0 is almost 5 years old.

[jethrogb]

$ strace -tt -etrace=connect ./curl --verbose --trace-time https://github.com
12:49:58.081888 * Host github.com:443 was resolved.
12:49:58.082203 * IPv6: (none)
12:49:58.082423 * IPv4: 140.82.116.4
12:49:58.082747 *   Trying 140.82.116.4:443...
12:49:58.208494 connect(4, {sa_family=AF_INET, sin_port=htons(443), sin_addr=inet_addr("140.82.116.4")}, 16) = -1 EINPROGRESS (Operation now in progress)
12:49:58.111433 * ALPN: curl offers h2,http/1.1
...
12:49:58.151056 * Connected to github.com (140.82.116.4) port 443

curl 8.11.1-DEV (x86_64-pc-linux-gnu) libcurl/8.11.1-DEV OpenSSL/1.1.1f zlib/1.2.11 brotli/1.0.7 libidn2/2.2.0 libpsl/0.21.0 nghttp2/1.40.0 OpenLDAP/2.4.49
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns ldap ldaps mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp ws wss
Features: alt-svc AsynchDNS brotli HSTS HTTP2 HTTPS-proxy IDN IPv6 Largefile libz NTLM PSL SSL threadsafe TLS-SRP UnixSockets

[dfandrich]

I don't see any place in the code where a monotonic clock time is combined with another time. The only place I can see a inconsistent time being used is if the call to get the monotonic time fails in which case the real time is used, but the time parts aren't mixed and the kinds of things that could go wrong with getting the monotonic time mean that it's unlikely that both would be found in the same log file. I think you're probably just seeing the difference between monotonic time and real time on your system.

The change to monotonic time seems to have been made 16 years ago in commit 19479ea and I don't recall this issue being brought up before. It probably doesn't matter much if the trace log is used in isolation, but if you're trying to correlate with external events in other log files, it would make a huge difference. The original change was probably done to avoid problems with internal timeouts, but log timestamping is sufficiently different that it's probably worth switching back to real time for that one.

[jethrogb]

curl/src/tool_cb_dbg.c

Lines 111 to 113 in cb2ae6e

	tv = tvnow();
	msnprintf(timebuf, sizeof(timebuf), "%s.%06ld ",
	hms_for_sec(tv.tv_sec), (long)tv.tv_usec);

tvnow() uses CLOCK_MONOTONIC if it's enabled. hms_for_sec uses time() internally.

[jethrogb]

I think you're probably just seeing the difference between monotonic time and real time on your system.

See #15614 (comment) - they're actually hours (years) apart.

[dfandrich]

I see the issue now. tool_debug_cb() mixes the two time sources via hms_for_sec(). The underlying issue looks to have been present since the switch to the monotonic time source.

[icing]

To summarize: besides tvnow(), which uses monotonic when available, we need a tvlocaltime() that uses gettimeofday()/time(NULL) or GetLocalTime() on Windows?

[icing]

I made #15641 as a fix for this. Would be nice if you could verify that this fixes things for you.