ZTS: include microsecond timestamps on all output

[robn]

[Sponsors: Klara, Inc., Wasabi Technology, Inc.]

Motivation and Context

When reviewing test output after a failure, it's often quite difficult to work out the order and timing of events, and to correlate test suite output with kernel logs.

Description

This adds timestamps to ZTS output to help correlate events:

• all of the standard log_XXX functions ultimately end up in _printline, which now prefixes output with a timestamp.
• the test runner logging function log() also now prefixes its output with a timestamp.
• on failure, when capturing the kernel log in zfs_dmesg.ksh, the iso time format is requested. This is gated behind a platform check, as FreeBSD's dmesg has no switches to control timestamps.

How Has This Been Tested?

Manually, running a test I know fails in my test VMs and considering the output.

$ zfs-tests.sh -DvKx -t zfs_load-key_https
...
/usr/local/share/zfs/test-runner/bin/test-runner.py  -D  -K -c "/var/tmp/zfs-tests.481.run" -T "functional" -i "/usr/local/share/zfs/zfs-tests" -I "1"
[    6.960295] ZTS run /usr/local/share/zfs/zfs-tests/tests/functional/cli_root/zfs_load-key/setup
[2025-02-12T01:05:34.353115] NOTE: begin default_setup_noexit
[2025-02-12T01:05:34.398547] SUCCESS: zpool create -f testpool loop0
[2025-02-12T01:05:34.432899] SUCCESS: zfs create testpool/testfs
[2025-02-12T01:05:34.463772] SUCCESS: zfs set mountpoint=/var/tmp/testdir testpool/testfs
[2025-02-12T01:05:35.520185] SUCCESS: openssl req -x509 -newkey rsa:4096 -sha256 -days 1 -nodes -keyout /testpool/snakeoil.key -out /testpool/snakeoil.crt -subj /CN=localhost
Traceback (most recent call last):
  File "<string>", line 16, in <module>
  File "<string>", line 10, in <module>
  File "/usr/lib/python3.11/socketserver.py", line 456, in __init__
    self.server_bind()
  File "/usr/lib/python3.11/http/server.py", line 136, in server_bind
    socketserver.TCPServer.server_bind(self)
  File "/usr/lib/python3.11/socketserver.py", line 472, in server_bind
    self.socket.bind(self.server_address)

[2025-02-12T01:06:25.290486] NOTE: Performing test-fail callback (/usr/local/share/zfs/zfs-tests/callbacks/zfs_dbgmsg.ksh)
...
[2025-02-12T01:06:25.315555] NOTE: Performing test-fail callback (/usr/local/share/zfs/zfs-tests/callbacks/zfs_dmesg.ksh)
=================================================================
 Tailing last 200 lines of dmesg log
=================================================================
2025-02-12T01:05:28,971544+00:00 .... node  #0, CPUs:      #1 #2 #3 #4 #5
2025-02-12T01:05:28,971544+00:00 smp: Brought up 1 node, 6 CPUs
2025-02-12T01:05:28,971544+00:00 smpboot: Max logical packages: 1
2025-02-12T01:05:28,971544+00:00 smpboot: Total of 6 processors activated (23904.00 BogoMIPS)
2025-02-12T01:05:29,090172+00:00 node 0 deferred pages initialised in 120ms
...
=================================================================
 End of dmesg log
=================================================================
[2025-02-12T01:06:25.334713] NOTE: Performing test-fail callback (/usr/local/share/zfs/zfs-tests/callbacks/zfs_mmp.ksh)
[2025-02-12T01:06:25.340432] Test: /usr/local/share/zfs/zfs-tests/tests/functional/cli_root/zfs_load-key/setup (run as root) [00:51] [FAIL]
[2025-02-12T01:06:25.345063] Test: /usr/local/share/zfs/zfs-tests/tests/functional/cli_root/zfs_load-key/zfs_load-key_https.ksh (run as root) [00:00] [SKIP]
[   58.006623] ZTS run /usr/local/share/zfs/zfs-tests/tests/functional/cli_root/zfs_load-key/cleanup
[2025-02-12T01:06:25.551120] SUCCESS: zpool destroy -f testpool
[2025-02-12T01:06:25.583079] SUCCESS: rm -rf /var/tmp/testdir
[2025-02-12T01:06:25.594580] Test: /usr/local/share/zfs/zfs-tests/tests/functional/cli_root/zfs_load-key/cleanup (run as root) [00:00] [PASS]
...

(fyi, this test fails because the VM has no network support at all, not even a loopback. It's no big deal)

Types of changes

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Performance enhancement (non-breaking change which improves efficiency)
• Code cleanup (non-breaking change which makes code smaller or more readable)
• Breaking change (fix or feature that would cause existing functionality to change)
• Library ABI change (libzfs, libzfs_core, libnvpair, libuutil and libzfsbootenv)
• Documentation (a change to man pages or other documentation)

Checklist:

• My code follows the OpenZFS code style requirements.
• I have updated the documentation accordingly.
• I have read the contributing document.
• I have added tests to cover my changes.
• I have run the ZFS Test Suite with this change applied.
• All commit messages are properly formatted and contain Signed-off-by.

[amotin]

"03:04:46.89 [2025-02-16T03:04:46.898708]" looks duplicate and excessively verbose. I suspect you meant to add the timestamps in some places where they weren't, but seems now there are places when they are duplicate.

And BTW, the CI seems very unhappy for some reason.

[robn]

03:04:46.89 [2025-02-16T03:04:46.898708]

This doesn't happen locally. Might be something in the CI runner adding timestamps? I'll look soon.

[tonyhutter]

@robn can you rebase this and see if that fixes the CI problems?

[robn]

Done. I did have a very short look and decided the extra bit might have been the CI proper, but I had no big ideas and haven't had time to get back to it properly yet. So lets see, either this will work or give me a new data point. Cheers :)

[tonyhutter]

If you need a reproducer - zpool_add_dryrun_output.ksh will pass on master and fail with this PR in local testing.

[AttilaFueloep]

Yeah, while comparing the output of zpool add -n with what we expect we do:

        typeset out="$(log_must eval "zpool add -n '$TESTPOOL' $add" | \
            sed /^SUCCESS/d)"

        if [[ "$out" != "$want" ]]; then
                log_fail "Got:\n" "$out" "\nbut expected:\n" "$want"
        fi

If the output of zpool add -n is prepended with a timestamp, the tests obviously will fail. The same should aply to all other tests from PR #11167 as well. The fix would be to extend the sed expression to remove the timestamps.

[AttilaFueloep]

zfs/tests/zfs-tests/tests/functional/cli_root/zpool_add/zpool_add_dryrun_output.ksh

Line 159 in dd2a46b

sed /^SUCCESS/d)"

Just wondering if

-            sed /^SUCCESS/d)"
+            sed /.*SUCCESS/d)"

would fix the test failure.

[robn]

Good find, thanks. I think I don't like that pattern - I don't like a test that is dependent on the output of the test framework it's running inside. There's only three instances in the whole test suite, so I'll rework them to just say what they mean.

[AttilaFueloep]

Yeah, agreed. At least I cleaned up my mess in #17198.

[robn]

Rebased onto #17198 and those three tests now pass. Pushed, lets see how it goes.

[amotin]

It is still somehow double-stamped in CI:

11:22:40.11 [2025-04-09T11:22:40.107876] SUCCESS: cp /var/tmp/cachefile.59027 /var/tmp/cachefile.59027.bkp

[AttilaFueloep]

Forgot to mention, that I'm seeing the short timestamps as well. Seems not to be CI related. This is on a somewhat current
master without this PR applied.

$ /usr/share/zfs/zfs-tests.sh -t tests/functional/cli_root/zpool_split/zpool_split_dryrun_output.ksh
....
$ head -4 </var/tmp/test_results/current/log
Test: /usr/share/zfs/zfs-tests/tests/functional/cli_root/zpool_split/setup (run as root) [00:00] [PASS]
Test: /usr/share/zfs/zfs-tests/tests/functional/cli_root/zpool_split/zpool_split_dryrun_output.ksh (run as root) [00:06] [FAIL]
02:33:55.43 ASSERTION: 'zpool split -n <pool> <newpool> [<vdev>]...' can display the configuration
02:33:55.43 SUCCESS: truncate -s 67108864 /var/tmp/filedev00

[allanjude]

@amotin found that the extra timestamp comes from the Github CI infrastructure, and maybe we can turn that off and just use our own

[robn]

Rebased and pushed; I just wanna get a fresh look at it.

[robn]

Last push fixes it, I hope!

Turns out the user_run function captures the output of whatever you run, and then re-emits it. If you run log_note or similar under user_run, then we'd get the timestamp in the captured output as well.

Maybe it'd be better to audit all those places and do something different, but its sort of also running into the limits of what this shellish contraption can do. So instead I've wired a suppression through with an environment variable.

Limited local testing suggests its plausible; I've got a full ZTS run in progress and of course CI is cruising, lets see what shakes out.

[robn]

Last push updates the CI to only prefix output with runner name & test number, using the timestamps emitted directly from the test:

[vm1  265] [2025-08-05T01:51:54.113748] Test: functional/cli_root/zfs_destroy/zfs_destroy_008_pos (run as root) [00:00] [PASS]
[vm1  266] [2025-08-05T01:51:55.716259] Test: functional/cli_root/zfs_destroy/zfs_destroy_009_pos (run as root) [00:01] [PASS]
[vm1  267] [2025-08-05T01:51:57.306903] Test: functional/cli_root/zfs_destroy/zfs_destroy_010_pos (run as root) [00:01] [PASS]
[vm1  268] [2025-08-05T01:51:58.396773] Test: functional/cli_root/zfs_destroy/zfs_destroy_011_pos (run as root) [00:01] [PASS]
[vm1  269] [2025-08-05T01:51:59.659868] Test: functional/cli_root/zfs_destroy/zfs_destroy_012_pos (run as root) [00:01] [PASS]

@mcmilk does this work for you? I couldn't see a great reason to continue doing the timestamps in the CI side when the more granular ones are already in the captured output, but I'm also fairly ambivalent, so if you feel strongly I can put it back exactly how it was, just updating the Test: matching.

[mcmilk]

[vm1 265] [2025-08-05T01:51:54.113748] Test: functional/cli_root/zfs_destroy/zfs_destroy_008_pos (run as root) [00:00] [PASS]
[vm1 266] [2025-08-05T01:51:55.716259] Test: functional/cli_root/zfs_destroy/zfs_destroy_009_pos (run as root) [00:01] [PASS]

This look okay, but is their a chance of displaying not the current datetime but the test "test running time".
Maybe some switch?

[robn]

Ahh, never mind. I just realised this is only changing the summary; the full output is still there in the full test log. That's all I need. So I've just pushed an update to the original; matching the new timestamps and removing them.

[mcmilk]

Ahh, never mind. I just realised this is only changing the summary; the full output is still there in the full test log. That's all I need. So I've just pushed an update to the original; matching the new timestamps and removing them.

Yes - thank you.

[robn]

Thanks all, really pleased about this one!