Skip to content

Conversation

@dridi
Copy link
Member

@dridi dridi commented May 23, 2025

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 added 6 commits May 21, 2025 16:23
This should allow compilers and static analyzers to complain about
buffers too small, and this emphasizes the difference between the
format and parse operations and how they treat their respective
string arguments.
The only effective change is the optional white space relying on the OWS
syntax (SP / HTAB) from the HTTP grammar instead of SP only.
As per an old recommendation on date-time formatting for better
interoperability. This format also has the convenient property
of being chronologically sorted.
@dridi
Copy link
Member Author

dridi commented May 23, 2025

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

@nigoroll
Copy link
Member

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.

VSB_printf(vsb, "%04d-%02d-%02dT%02d:%02d:%02d",
tm.tm_year + 1900, tm.tm_mon, tm.tm_mday,
tm.tm_hour, tm.tm_min, tm.tm_sec);

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why even bother with the VSB ?

You are printing a fixed-length format, use strftime() directly ?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because what follows is of variable length.

dridi added 2 commits June 25, 2025 14:42
Just to be safe, even though this is currently working fine with the
handful of test cases.

Spotted by @daghf.
@dridi
Copy link
Member Author

dridi commented Jun 25, 2025

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.

Copy link
Member

@daghf daghf left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I reviewed and approved this elsewhere, so I might as well do it here. LGTM

@nigoroll
Copy link
Member

@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.

@dridi
Copy link
Member Author

dridi commented Jun 30, 2025

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

CLI_CMD(BAN_LIST,
"ban.list",
"ban.list [-j]",
"List the active bans.",
" Unless ``-j`` is specified for JSON output, "
" the output format is:\n\n"
" * Time the ban was issued.\n\n"
" * Objects referencing this ban.\n\n"
" * ``C`` if ban is completed = no further testing against it.\n\n"
" * if ``lurker`` debugging is enabled:\n\n"
" * ``R`` for req.* tests\n\n"
" * ``O`` for obj.* tests\n\n"
" * Pointer to ban object\n\n"
" * Ban specification\n\n"
" Durations of ban specifications get normalized, for example \"7d\""
" gets changed into \"1w\".",
0, 0
)

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.

@nigoroll
Copy link
Member

nigoroll commented Jul 2, 2025

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".

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants