opensource/podman
1
0
Fork 0
mirror of https://github.com/containers/podman.git synced 2025-08-06 11:32:07 +08:00
Code Issues Packages Projects Releases Wiki Activity

system tests: add precision timestamps

Browse Source 
In run_podman(), display a nanosecond-level timestamp next to
each command and its output.

Because this clutters the results, teach logformatter to grok
these new timestamps, strip them, and display a more human-readable
time delta in the left-hand timestamp column. logformatter started off
as a mess and is now, well, 🤮. I'm sorry. I just hope its results
make it worthwhile.

Signed-off-by: Ed Santiago <santiago@redhat.com>
This commit is contained in:
Ed Santiago
2023-05-16 05:43:34 -06:00
parent 5d07b1c59b
commit 3360214a0f
4 changed files with 108 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files

39
contrib/cirrus/logformatter
View File

@ -230,6 +230,7 @@ END_HTML
# State variables
my $previous_timestamp = ''; # timestamp of previous line
my $previous_timestamp_fine; # fine-grain timestamp (BATS only)
my $cirrus_task; # Cirrus task number, used for linking
my $git_commit; # git SHA, used for linking to source files
my $subtest_status; # pass, fail, skip, flake - for each subtest
@ -375,6 +376,44 @@ END_HTML
if ($looks_like_bats) {
my $css;
# 2023-05-16 run_podman() now displays NS-precision timestamps
# on commands and their output. This is cluttery, so if we
# see these, strip them and display in the left-hand (coarse)
# timestamp column instead. Hovering will display the full time.
#
# 1 1 23 3 4 4 5 52
if ($line =~ s{^(#\s)\[((\d+):(\d+):(\d+\.\d+))\]\s}{$1}) {
my ($full, $h, $m, $s) = ($2, $3, $4, $5);
my $timestamp_fine = $h * 3600.0 + $m * 60.0 + $s;
my $short;
if ($previous_timestamp_fine) {
# This will fail if we do a midnight wraparound. NBD.
my $delta = $timestamp_fine - $previous_timestamp_fine;
# Human-readable format
if ($delta > 10) {
$short = sprintf("%04ds", $delta);
}
elsif ($delta > 1) {
$short = sprintf("%03.2fs", $delta);
}
elsif ($delta > 0.001) {
$short = sprintf("%03dms", $delta * 1000.0);
}
else {
# Ultra-improbable
$short = sprintf("%03dns", $delta * 1_000_000.0);
}
}
else {
$short = " ";
}
# left-hand timestamp [+0001s] becomes <+013ms>
$timestamp = "<span title=\"$full\">&lt;+$short&gt;</span> ";
$previous_timestamp_fine = $timestamp_fine;
}
# Readability: /long/path/to/podman -> podman (hover for full path)
# Also make it boldface, to make commands stand out
$line =~ s{^(#\s+(#|\$)\s+)(\S+/)(podman\S*)(\s.*)}

64
contrib/cirrus/logformatter.t
View File

@ -115,10 +115,66 @@ ok 4 blah
<hr/><span class='bats-summary'>Summary: <span class='bats-passed'>2 Passed</span>, <span class='bats-failed'>1 Failed</span>, <span class='bats-skipped'>1 Skipped</span>. Total tests: 4</span>
== bats with timestamps 2023-05-16
<<<
[+0000s] 1..2
[+0000s] ok 1 this passes
[+0018s] not ok 2 this fails, and includes command timestamps
[+0018s] # (from function `die' in file test/system/helpers.bash, line 564,
[+0018s] # from function `run_podman' in file test/system/helpers.bash, line 245,
[+0018s] # in test file test/system/888-foo.bats, line 15)
[+0018s] # `run_podman image exists sdfsdfsdf' failed
[+0018s] # [07:46:52.641456481] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman rm -t 0 --all --force --ignore
[+0018s] # [07:46:52.688219032] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman ps --all --external --format {{.ID}} {{.Names}}
[+0018s] # [07:46:52.747613611] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman images --all --format {{.Repository}}:{{.Tag}} {{.ID}}
[+0018s] # [07:46:52.791987930] quay.io/libpod/testimage:20221018 f5a99120db64
[+0018s] # [07:46:52.801043907] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman container exists nonesuch
[+0018s] # [07:46:52.842840593] [ rc=1 (expected) ]
[+0018s] # [07:46:52.848492506] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman container exists nonesuch
[+0018s] # [07:46:52.893686015] [ rc=1 (expected) ]
[+0018s] # [07:47:02.910006230] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman image inspect --format {{.Os}} quay.io/libpod/testimage:20221018
[+0018s] # [07:47:02.961306244] linux
[+0018s] # [07:47:02.966100272] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman run --rm quay.io/libpod/testimage:20221018 sleep 7
[+0018s] # [07:47:10.167561880] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman image exists sdfsdfsdf
[+0018s] # [07:47:10.213750267] [ rc=1 (** EXPECTED 0 **) ]
[+0018s] # #/vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv
[+0018s] # #| FAIL: exit code is 1; expected 0
[+0018s] # #\^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[+0018s] # # [teardown]
[+0018s] # [07:47:10.219704348] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman pod rm -t 0 --all --force --ignore
[+0018s] # [07:47:10.263332041] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman rm -t 0 --all --force --ignore
[+0018s] # [07:47:10.300645440] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman network prune --force
[+0018s] # [07:47:10.337464840] $ /home/esm/src/atomic/2018-02.podman/libpod/bin/podman volume rm -a -f
>>>
<span class="timestamp">[+0000s] </span>1..2
<span class="timestamp"> </span><span class='bats-passed'><a name='t--00001'>ok 1 this passes</a></span>
<span class="timestamp">[+0018s] </span><span class='bats-failed'><a name='t--00002'>not ok 2 this fails, and includes command timestamps</a></span>
<span class="timestamp"> </span><span class='bats-log'># (from function `die&#39; in file test/system/<a class="codelink" href="https://github.com/containers/podman/blob/ceci-nest-pas-une-sha/test/system/helpers.bash#L564">helpers.bash, line 564</a>,</span>
<span class="timestamp"> </span><span class='bats-log'># from function `run_podman&#39; in file test/system/<a class="codelink" href="https://github.com/containers/podman/blob/ceci-nest-pas-une-sha/test/system/helpers.bash#L245">helpers.bash, line 245</a>,</span>
<span class="timestamp"> </span><span class='bats-log'># in test file test/system/<a class="codelink" href="https://github.com/containers/podman/blob/ceci-nest-pas-une-sha/test/system/888-foo.bats#L15">888-foo.bats, line 15</a>)</span>
<span class="timestamp"> </span><span class='bats-log'># `run_podman image exists sdfsdfsdf&#39; failed</span>
<span class="timestamp"><span title="07:46:52.641456481">&lt;+ &gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> rm -t 0 --all --force --ignore</b></span>
<span class="timestamp"><span title="07:46:52.688219032">&lt;+046ms&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> ps --all --external --format {{.ID}} {{.Names}}</b></span>
<span class="timestamp"><span title="07:46:52.747613611">&lt;+059ms&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> images --all --format {{.Repository}}:{{.Tag}} {{.ID}}</b></span>
<span class="timestamp"><span title="07:46:52.791987930">&lt;+044ms&gt;</span> </span><span class='bats-log'># quay.io/libpod/testimage:20221018 f5a99120db64</span>
<span class="timestamp"><span title="07:46:52.801043907">&lt;+009ms&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> container exists nonesuch</b></span>
<span class="timestamp"><span title="07:46:52.842840593">&lt;+041ms&gt;</span> </span><span class='bats-log'># [ rc=1 (expected) ]</span>
<span class="timestamp"><span title="07:46:52.848492506">&lt;+005ms&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> container exists nonesuch</b></span>
<span class="timestamp"><span title="07:46:52.893686015">&lt;+045ms&gt;</span> </span><span class='bats-log'># [ rc=1 (expected) ]</span>
<span class="timestamp"><span title="07:47:02.910006230">&lt;+0010s&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> image inspect --format {{.Os}} quay.io/libpod/testimage:20221018</b></span>
<span class="timestamp"><span title="07:47:02.961306244">&lt;+051ms&gt;</span> </span><span class='bats-log'># linux</span>
<span class="timestamp"><span title="07:47:02.966100272">&lt;+004ms&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> run --rm quay.io/libpod/testimage:20221018 sleep 7</b></span>
<span class="timestamp"><span title="07:47:10.167561880">&lt;+7.20s&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> image exists sdfsdfsdf</b></span>
<span class="timestamp"><span title="07:47:10.213750267">&lt;+046ms&gt;</span> </span><span class='bats-log'># [ rc=1 (** EXPECTED 0 **) ]</span>
<span class="timestamp"> </span><span class='bats-log-failblock'># #/vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv</span>
<span class="timestamp"> </span><span class='bats-log-failblock'># #| FAIL: exit code is 1; expected 0</span>
<span class="timestamp"> </span><span class='bats-log-failblock'># #\^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^</span>
<span class="timestamp"> </span><span class='bats-log'># # [teardown]</span>
<span class="timestamp"><span title="07:47:10.219704348">&lt;+005ms&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> pod rm -t 0 --all --force --ignore</b></span>
<span class="timestamp"><span title="07:47:10.263332041">&lt;+043ms&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> rm -t 0 --all --force --ignore</b></span>
<span class="timestamp"><span title="07:47:10.300645440">&lt;+037ms&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> network prune --force</b></span>
<span class="timestamp"><span title="07:47:10.337464840">&lt;+036ms&gt;</span> </span><span class='bats-log'># $ <b><span title="/home/esm/src/atomic/2018-02.podman/libpod/bin/podman">podman</span> volume rm -a -f</b></span>
<hr/><span class='bats-summary'>Summary: <span class='bats-passed'>1 Passed</span>, <span class='bats-failed'>1 Failed</span>. Total tests: 2</span>
== simple ginkgo

2
test/system/070-build.bats
View File

@ -729,7 +729,7 @@ EOF
if is_remote; then remote_extra=".*";fi
expect="${random1}
.*
STEP 1/2: FROM $IMAGE
\[[0-9:.]\+\] STEP 1/2: FROM $IMAGE
STEP 2/2: RUN echo x${random2}y
x${random2}y${remote_extra}
COMMIT build_test${remote_extra}

11
test/system/helpers.bash
View File

@ -161,6 +161,11 @@ function restore_image() {
###############################################################################
# BEGIN podman helpers
# Displays '[HH:MM:SS.NNNNN]' in command output. logformatter relies on this.
function timestamp() {
date +'[%T.%N]'
}
################
# run_podman # Invoke $PODMAN, with timeout, using BATS 'run'
################
@ -197,13 +202,13 @@ function run_podman() {
MOST_RECENT_PODMAN_COMMAND="podman $*"
# stdout is only emitted upon error; this echo is to help a debugger
echo "$_LOG_PROMPT $PODMAN $*"
echo "$(timestamp) $_LOG_PROMPT $PODMAN $*"
# BATS hangs if a subprocess remains and keeps FD 3 open; this happens
# if podman crashes unexpectedly without cleaning up subprocesses.
run timeout --foreground -v --kill=10 $PODMAN_TIMEOUT $PODMAN $_PODMAN_TEST_OPTS "$@" 3>/dev/null
# without "quotes", multiple lines are glommed together into one
if [ -n "$output" ]; then
echo "$output"
echo "$(timestamp) $output"
# FIXME FIXME FIXME: instrumenting to track down #15488. Please
# remove once that's fixed. We include the args because, remember,
@ -215,7 +220,7 @@ function run_podman() {
fi
fi
if [ "$status" -ne 0 ]; then
echo -n "[ rc=$status ";
echo -n "$(timestamp) [ rc=$status ";
if [ -n "$expected_rc" ]; then
if [ "$status" -eq "$expected_rc" ]; then
echo -n "(expected) ";