dream icon indicating copy to clipboard operation
dream copied to clipboard

server logger: use ISO 8601 + RFC 3339 for date format

Open toastal opened this issue 7 months ago • 15 comments

Not everyone subscribes to Euro-centric date formats. In ‘computer land’ Unix timestamps and ISO 8601 + RFC 3339 are the standards[^1].

Subjectively, I found the date format at present confusing at a glance — & I would prefer that ambiguity cleared up for me & all other users.

Now renders like this on my machine

2025-05-17T15:18:00.500-00:00    dream.logger  INFO REQ 1 GET / ::1:37698 fd 6 Mozilla/5.0 (X11; Linux x86_64; rv:138.0) Gecko/20100101 Firefox/138.0

This request nets a negative lines by just picking one of Ptime’s 2 output options.

[^2]

[^1]: Asia also likes ISO 8601 + RFC 3339 format & most governments recognize it too [^2]: Please consider giving up MS GitHub or offering a non-proprietary, non-US-corporate-controlled mirror for this free software project. I wish to delete this Microsoft account in the future, but I need more projects like this to support alternative methods to send patches & contribute.

toastal avatar May 17 '25 15:05 toastal

For comparison: Current: 2025-08-08 08:13:32.650 dream.logger... This PR: 2025-05-17T15:18:00.500-00:00 dream.logger ...

Willenbrink avatar Aug 08 '25 08:08 Willenbrink

Apache & Nginx use “Common Log Format”

127.0.0.1 - frank [10/Oct/2000:13:55:36 -0700] "GET /apache_pb.gif HTTP/1.0" 200 2326 

toastal avatar Aug 08 '25 08:08 toastal

Spring, the popular Java web framework, is on the ISO format:

2025-08-08T10:24:44.808+02:00  INFO 31647 --- [  restartedMain] com.example.demo.DemoApplication         : Starting DemoApplication using Java 21.0.7 with PID 31647 ...

Flask (Python) is on the Common Log Format: 127.0.0.1 - - [08/Aug/2025 10:58:25] "GET / HTTP/1.1" 200 -

For comparison: Current: 2025-08-08 08:13:32.650 dream.logger... This PR: 2025-05-17T15:18:00.500-00:00 dream.logger ...

— @Willenbrink

The current is actually: 08.08.25 08:28:07.584

$ dune exec bin/main.exe
08.08.25 08:28:10.842    dream.logger  INFO REQ 1 GET /  fd 8 Mozilla/5.0 (X11; Linux x86_64; rv:141.0) Gecko/20100101 Firefox/141.0
08.08.25 08:28:10.842    dream.logger  INFO REQ 1 200 in 214 μs

toastal avatar Aug 08 '25 08:08 toastal

I would prefer it if upstream Ptime treated -00:00 as Z to cut down on character noise which is valid according to the ISO spec where 2025-08-08T15:18:00.500-00:00 would be 2025-08-08T15:18:00.500Z, but that could be raised. This PR suggests just using what Ptime gives us as the ISO output (meaning Ptime.to_rfc3339 ~frac_s:3 time).

toastal avatar Aug 08 '25 08:08 toastal

where 2025-08-08T15:18:00.500-00:00 would be 2025-08-08T15:18:00.500Z,

apparently, it's not exactly the same (one is implying that the time zone is UTC, while the other says the time zone is unknown, see https://www.rfc-editor.org/rfc/rfc3339#section-4.3)

sabine avatar Aug 08 '25 10:08 sabine

It seems like the choice is between ISO and Common Log Format.

aantron avatar Aug 08 '25 10:08 aantron

https://h2o.examp1e.net/configure/access_log_directives.html

H2O lets it be specified with % args with a default of Common Log Format (for compat with other reverse proxies + tools like fail2ban, but that is a different target than a web server/framework typically behind a reverse proxy).

toastal avatar Aug 08 '25 10:08 toastal

Note since I was side half-dragged into that discussion (specify a time zone offset of 0 to get Z!) I'll give my two unsolicited euro cents. Why don't you let the logging endpoint handle the time component ?

In my own web stack I simply log on stdout without the time. This means that:

  1. When I develop I don't get times. That's ok and actually less noise, I have a good idea of what time it is :-)
  2. When I run the service, I usually do so with a systemd unit and then I just get the logs via journalctl -u myservice. That gives you the the timings and you can format and query it in all sorts of manners. A real example:
Aug 08 13:55:49 localhost hyperbib[1528560]: GET [200  21ms] /references/uncertainties-plurality-and-robustness-in-climate-research-and-modeling-on-the-reliability-of-climate-prognoses/94 (OK)
Aug 08 13:57:06 localhost hyperbib[1528560]: GET [200  29ms] /subjects/reliability-uncertainty/22 (OK)
Aug 08 14:02:12 localhost hyperbib[1528560]: GET [200 430ms] /persons/richard-b-howarth/407 (OK)
Aug 08 14:02:15 localhost hyperbib[1528560]: GET [200 416ms] /persons/robert-j-lempert/136 (OK)

dbuenzli avatar Aug 08 '25 12:08 dbuenzli

We are leaning towards Common Log Format. Any strong objections?

aantron avatar Aug 15 '25 07:08 aantron

As noted a bit earlier, Common Log is okay too. I use it with fail2ban’s built-ins with H2O to block spam (addressing someone saying existing tools have parsers for it).

But ISO8601 is used by basically everything & well as the standards for many non-servers & governments.

Both of these are “big endian” date-time formats (year, month, day, hour, second, microsecond) rather than a mix of endianness.

toastal avatar Aug 15 '25 07:08 toastal

Yes, the endianness is important. The current format is definitely wrong because the year is not first.

aantron avatar Aug 15 '25 07:08 aantron

Hi, an upvote from me for using the ISO-8601/RFC3339 timestamp format. With respect to @dbuenzli's comment, maybe we can add an optional argument ?timestamp (default true) which controls whether the timestamp is printed or not. In case people want to disable the timestamp in production use cases where eg systemd, Docker, Kubernetes and so on will timestamp logs anyway.

yawaramin avatar Aug 15 '25 16:08 yawaramin

@yawaramin Could you give the reasoning for prefering the ISO format to Common Log Format?

aantron avatar Aug 15 '25 18:08 aantron

I think ISO timestamps are easier to scan because they order by biggest to smallest unit. Eg compare:

2025-08-15 13:31:54.214                     Running at http://localhost:8080
2025-08-15 13:31:54.214                     Type Ctrl+C to stop
2025-08-15 13:32:02.253    dream.logger WRN REQ 4eeef7e6 404 51μs ::1:63759 GET / Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36
2025-08-15 13:32:32.920    dream.logger INF REQ 75ed552b 200 76μs ::1:63759 GET /greeting/yawar Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36

vs

15/Aug/2025:13:31:54.214                     Running at http://localhost:8080
15/Aug/2025:13:31:54.214                     Type Ctrl+C to stop
15/Aug/2025:13:32:02.253    dream.logger WRN REQ 4eeef7e6 404 51μs ::1:63759 GET / Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36
15/Aug/2025:13:32:32.920    dream.logger INF REQ 75ed552b 200 76μs ::1:63759 GET /greeting/yawar Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36

In the latter case you have to mentally go up to bigger units and then flip back down to smaller units.

It would also make the log lines trivial to sort by date order just by doing a lexicographic sort.

yawaramin avatar Aug 15 '25 19:08 yawaramin