varnish-cache icon indicating copy to clipboard operation
varnish-cache copied to clipboard

vtim: Work with the "YYYY-MM-DDThh:mm:ss[.s]TZD" date-time format

Open dridi opened this issue 7 months ago • 6 comments

This is a format shared by a W3C note and an old IETF RFC, and still in use 5000+ RFCs later.

It's not being used anywhere in this patch series (I'm using it in a separate project) but I think it could be very useful in certain areas where we print timestamps, like the ban list, the first (non-prefix) field of SLT_Timestamp records, and possibly others not popping off the top of my head.

Three interesting properties of this specific format:

  • timestamps are naturally sorted
  • no spaces, a good fit for field/column layouts
  • sub-second resolution
  • human readable

I'm submitting this independently of any usage, but I thought the 8.0 release could be a good occasion to "break" the output of CLI responses, or the layout of VSL records, or anything else where we print timestamps.

dridi avatar May 23 '25 15:05 dridi

VTIM_parse() returns zero on error, instead of something like NAN. I adopted the same behavior for VTIM_parse_web() to retain similar semantics.

dridi avatar May 23 '25 15:05 dridi

I cherry-picked the first commit thinking that it should be an undisputed (flw) improvement. Other than that I really do not have much of an opinion, other than that I never particularly liked the "ISO 8601-style" timestamps precisely because of the lack of whitespace, which does not seem to match well with how my brain parses strings.

nigoroll avatar May 28 '25 15:05 nigoroll

I never particularly liked the "ISO 8601-style" timestamps precisely because of the lack of whitespace, which does not seem to match well with how my brain parses strings.

And this is why I predicted that out of 4 properties, only 3 were interesting.

Joke aside, since 8.0 is around the corner, I went away and used this format for the ban list as an example, here is what I get on my machine:

$ ./varnishtest -i tests/c00019.vtc -v | sed -n '/CLI RX.*\(Present bans\|ban.list\)/,/CLI 200/p'
**** v1    CLI RX|Present bans:
**** v1    CLI RX|2025-05-25T13:18:27.533433Z      0 -  req.url ~ FOO
**** v1    CLI RX|2025-05-25T13:18:27.361111Z      0 C  
**   v1    CLI 200 <ban.list>
**** v1    CLI RX|Present bans:
**** v1    CLI RX|2025-05-25T13:18:27.533433Z      2 -  req.url ~ FOO
**   v1    CLI 200 <ban.list>
**** v1    CLI RX|Present bans:
**** v1    CLI RX|2025-05-25T13:18:27.68648Z       0 -  req.url ~ FOO
**** v1    CLI RX|2025-05-25T13:18:27.533433Z      2 C  
**   v1    CLI 200 <ban.list>
**** v1    CLI RX|Present bans:
**** v1    CLI RX|2025-05-25T13:18:27.68648Z       1 -  req.url ~ FOO
**** v1    CLI RX|2025-05-25T13:18:27.533433Z      1 C  
**   v1    CLI 200 <ban.list>
**** v1    CLI RX|Present bans:
**** v1    CLI RX|2025-05-25T13:18:27.956411Z      0 -  req.url ~ FOO
**** v1    CLI RX|2025-05-25T13:18:27.871459Z      0 C  
**** v1    CLI RX|2025-05-25T13:18:27.828823Z      0 -  req.url ~ KILROY
**** v1    CLI RX|2025-05-25T13:18:27.68648Z       1 C  
**** v1    CLI RX|2025-05-25T13:18:27.533433Z      1 C  
**   v1    CLI 200 <ban.list>
**** v1    CLI RX|Present bans:
**** v1    CLI RX|2025-05-25T13:18:27.956411Z      1 -  req.url ~ FOO
**** v1    CLI RX|2025-05-25T13:18:27.871459Z      0 C  
**** v1    CLI RX|2025-05-25T13:18:27.828823Z      0 -  req.url ~ KILROY
**** v1    CLI RX|2025-05-25T13:18:27.68648Z       0 C  
**** v1    CLI RX|2025-05-25T13:18:27.533433Z      1 C  
**   v1    CLI 200 <ban.list>
**** v1    CLI RX|[ 2, ["ban.list", "-j"], 1750857508.093,
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.956411Z",
**** v1    CLI RX|    "refs": 1,
**** v1    CLI RX|    "completed": false,
**** v1    CLI RX|    "spec": "req.url ~ FOO"
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.871459Z",
**** v1    CLI RX|    "refs": 0,
**** v1    CLI RX|    "completed": true,
**** v1    CLI RX|    "spec": ""
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.828823Z",
**** v1    CLI RX|    "refs": 0,
**** v1    CLI RX|    "completed": false,
**** v1    CLI RX|    "spec": "req.url ~ KILROY"
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.68648Z",
**** v1    CLI RX|    "refs": 0,
**** v1    CLI RX|    "completed": true,
**** v1    CLI RX|    "spec": ""
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.533433Z",
**** v1    CLI RX|    "refs": 1,
**** v1    CLI RX|    "completed": true,
**** v1    CLI RX|    "spec": ""
**** v1    CLI RX|}
**** v1    CLI RX|]
**   v1    CLI 200 <ban.list -j>
**** v1    CLI RX|Present bans:
**** v1    CLI RX|2025-05-25T13:18:28.208483Z      0 -  obj.http.Host ~ "Foo"
**** v1    CLI RX|2025-05-25T13:18:28.178795Z      0 -  req.url ~ BAR
**** v1    CLI RX|2025-05-25T13:18:27.956411Z      1 -  req.url ~ FOO
**** v1    CLI RX|2025-05-25T13:18:27.871459Z      0 C  
**** v1    CLI RX|2025-05-25T13:18:27.828823Z      0 -  req.url ~ KILROY
**** v1    CLI RX|2025-05-25T13:18:27.68648Z       0 C  
**** v1    CLI RX|2025-05-25T13:18:27.533433Z      1 C  
**   v1    CLI 200 <ban.list>
**** v1    CLI RX|[ 2, ["ban.list", "-j"], 1750857508.303,
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:28.208483Z",
**** v1    CLI RX|    "refs": 0,
**** v1    CLI RX|    "completed": false,
**** v1    CLI RX|    "spec": "obj.http.Host ~ \"Foo\""
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:28.178795Z",
**** v1    CLI RX|    "refs": 0,
**** v1    CLI RX|    "completed": false,
**** v1    CLI RX|    "spec": "req.url ~ BAR"
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.956411Z",
**** v1    CLI RX|    "refs": 1,
**** v1    CLI RX|    "completed": false,
**** v1    CLI RX|    "spec": "req.url ~ FOO"
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.871459Z",
**** v1    CLI RX|    "refs": 0,
**** v1    CLI RX|    "completed": true,
**** v1    CLI RX|    "spec": ""
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.828823Z",
**** v1    CLI RX|    "refs": 0,
**** v1    CLI RX|    "completed": false,
**** v1    CLI RX|    "spec": "req.url ~ KILROY"
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.68648Z",
**** v1    CLI RX|    "refs": 0,
**** v1    CLI RX|    "completed": true,
**** v1    CLI RX|    "spec": ""
**** v1    CLI RX|},
**** v1    CLI RX|  {
**** v1    CLI RX|    "time": "2025-05-25T13:18:27.533433Z",
**** v1    CLI RX|    "refs": 1,
**** v1    CLI RX|    "completed": true,
**** v1    CLI RX|    "spec": ""
**** v1    CLI RX|}
**** v1    CLI RX|]
**   v1    CLI 200 <ban.list -j>

I think that despite the lack of whitespace, this kind of output is more human-readable than the decimal number we have today.

dridi avatar Jun 25 '25 13:06 dridi

@dridi I think the ban list is a particularly bad example, because we said that the "number" would officially be opaque, with the only requirement to define global ordering.

nigoroll avatar Jun 30 '25 13:06 nigoroll

I went ahead with the ban list as an example based on this:

https://github.com/varnishcache/varnish-cache/blob/7f7b030bfbe61857bc9c398ec238bbe280cb0df8/include/tbl/cli_cmds.h#L52-L71

This column is described as "Time the ban was issued" and there is no (in)formal JSON schema, so I deemed this format appropriate for the "time" field.

If my example is wrong, it was made in good faith with due diligence.

dridi avatar Jun 30 '25 13:06 dridi

Re @dridi

If my example is wrong, it was made in good faith with due diligence.

you absolutely did. The detail of the ban id becoming opaque is buried in the VDD23Q1 notes and not even particularly explicit there:

control system can assign the "ban id" (current vtim_real)

Also, I should have written "would officially become opaque".

nigoroll avatar Jul 02 '25 08:07 nigoroll