sys tests: run_podman: check for unwanted warnings/errors

With few exceptions, commands that exit 0 should not emit any
messages with level=warning or =error. Let's start enforcing
that in run_podman.

Allow one-off exceptions, typically when we're testing an
actual warning condition (usual case: "podman stop" where it
times out to SIGKILL). Exceptions are specified via:

    run_podman 0+w subcommand...
               ^^^---- or, rarely, 0+e

"0" stands for "expect exit status 0", which is the default
so it's implicit anyway. The +w / +e (or even +we) is the
new part. I have added it to tests where necessary.

And, because life is what it is, add two global exceptions:

  - Debian. Because runc has too many flakes.
  - kube. Ditto. Kube commands emit lots of nasty error
    messages (yes, level=error) that don't seem to affect
    results.

Similar to containers#18442

Signed-off-by: Ed Santiago <[email protected]>

test/system/001-basic.bats

@@ -35,7 +35,7 @@ function setup() {
     run_podman -v
     is "$output" "podman.*version \+"               "'Version line' in output"
 
-    run_podman --config foobar version
+    run_podman 0+w --config foobar version
     is "$output" ".*The --config flag is ignored by Podman. Exists for Docker compatibility\+"		  "verify warning for --config option"
 }
 

test/system/010-images.bats

@@ -387,7 +387,9 @@ EOF
     tries=100
     while [[ ${#lines[*]} -gt 1 ]] && [[ $tries -gt 0 ]]; do
         # Prior to #18980, 'podman images' during rmi could fail with 'image not known'
-        run_podman images --format "{{.ID}} {{.Names}}"
+        # '0+w' reflects that we may see "Top layer not found" warnings.
+        # FIXME FIXME: find a way to check for any other warnings
+        run_podman 0+w images --format "{{.ID}} {{.Names}}"
         tries=$((tries - 1))
     done
 

test/system/030-run.bats

@@ -181,7 +181,7 @@ echo $rand        |   0 | $rand
     run_podman image exists $NONLOCAL_IMAGE
 
     # Now try running with --rmi : it should succeed, but not remove the image
-    run_podman run --rmi --rm $NONLOCAL_IMAGE /bin/true
+    run_podman 0+e run --rmi --rm $NONLOCAL_IMAGE /bin/true
     is "$output" ".*image is in use by a container" "--rmi should warn that the image was not removed"
     run_podman image exists $NONLOCAL_IMAGE
 
@@ -229,7 +229,7 @@ echo $rand        |   0 | $rand
        "conmon pidfile (= PID $conmon_pid_from_file) points to conmon process"
 
     # All OK. Kill container.
-    run_podman rm -f $cid
+    run_podman rm -f -t0 $cid
     if [[ -e $cidfile ]]; then
         die "cidfile $cidfile should be removed along with container"
     fi
@@ -946,7 +946,7 @@ EOF
     if grep -- -1000 /proc/self/oom_score_adj; then
         skip "the current oom-score-adj is already -1000"
     fi
-    run_podman run --oom-score-adj=-1000 --rm $IMAGE true
+    run_podman 0+w run --oom-score-adj=-1000 --rm $IMAGE true
     is "$output" ".*Requested oom_score_adj=.* is lower than the current one, changing to .*"
 }
 
@@ -1058,7 +1058,12 @@ $IMAGE--c_ok" \
            "ls /dev/tty[0-9] with --systemd=always: should have no ttyN devices"
 
     # Make sure run_podman stop supports -1 option
-    run_podman stop -t -1 $cid
+    # FIXME: why is there no signal name here? Should be 'StopSignal XYZ'
+    # FIXME: do we really really mean to say FFFFFFFFFFFFFFFF here???
+    run_podman 0+w stop -t -1 $cid
+    if ! is_remote; then
+        assert "$output" =~ "StopSignal  failed to stop container .* in 18446744073709551615 seconds, resorting to SIGKILL" "stop -t -1 (negative one) issues warning"
+    fi
     run_podman rm -t -1 -f $cid
 }
 

test/system/045-start.bats

@@ -27,7 +27,10 @@ load helpers
     run_podman wait $cid_none_implicit $cid_none_explicit $cid_on_failure
 
     run_podman rm $cid_none_implicit $cid_none_explicit $cid_on_failure
-    run_podman stop -t 1 $cid_always
+    run_podman 0+w stop -t 1 $cid_always
+    if ! is_remote; then
+        assert "$output" =~ "StopSignal SIGTERM failed to stop container .*, resorting to SIGKILL"
+    fi
     run_podman rm $cid_always
 }
 

test/system/050-stop.bats

@@ -9,8 +9,11 @@ load helpers
 
     # Run 'stop'. Time how long it takes.
     t0=$SECONDS
-    run_podman stop $cid
+    run_podman 0+w stop $cid
     t1=$SECONDS
+    if ! is_remote; then
+        assert "$output" =~ "StopSignal SIGTERM failed to stop container .*, resorting to SIGKILL"
+    fi
 
     # Confirm that container is stopped. Podman-remote unfortunately
     # cannot tell the difference between "stopped" and "exited", and
@@ -44,7 +47,10 @@ load helpers
     is "${lines[2]}" "c3--Up.*"  "podman ps shows running container (3)"
 
     # Stop -a
-    run_podman stop -a -t 1
+    run_podman 0+w stop -a -t 1
+    if ! is_remote; then
+        assert "$output" =~ "StopSignal SIGTERM failed to stop container .*, resorting to SIGKILL"
+    fi
 
     # Now podman ps (without -a) should show nothing.
     run_podman ps --format '{{.Names}}'
@@ -185,8 +191,10 @@ load helpers
 @test "podman stop -t 1 Generate warning" {
     skip_if_remote "warning only happens on server side"
     run_podman run --rm --name stopme -d $IMAGE sleep 100
-    run_podman stop -t 1 stopme
-    is "$output" ".*StopSignal SIGTERM failed to stop container stopme in 1 seconds, resorting to SIGKILL"  "stopping container should print warning"
+    run_podman 0+w stop -t 1 stopme
+    if ! is_remote; then
+        is "$output" ".*StopSignal SIGTERM failed to stop container stopme in 1 seconds, resorting to SIGKILL"  "stopping container should print warning"
+    fi
 }
 
 @test "podman stop --noout" {
@@ -204,7 +212,7 @@ load helpers
 
     run_podman run --rm -d --name rmstop $IMAGE sleep infinity
     local cid="$output"
-    run_podman stop rmstop
+    run_podman stop -t0 rmstop
 
     # Check the OCI runtime directory has removed.
     is "$(ls $OCIDir | grep $cid)" "" "The OCI runtime directory should have been removed"

test/system/055-rm.bats

@@ -72,7 +72,7 @@ load helpers
     # the window for race conditions that led to #9479.
     run_podman run --rm -d $IMAGE sleep infinity
     local cid="$output"
-    run_podman rm -af
+    run_podman rm -af -t0
 
     # Check the OCI runtime directory has removed.
     is "$(ls $OCIDir | grep $cid)" "" "The OCI runtime directory should have been removed"

test/system/075-exec.bats

@@ -61,7 +61,6 @@ load helpers
 
     is "$(check_exec_pid)" "" "there isn't any exec pid hash file leak"
 
-    run_podman stop --time 1 $cid
     run_podman rm -t 0 -f $cid
 }
 

test/system/250-systemd.bats

@@ -79,7 +79,7 @@ function service_cleanup() {
     # Warn when a custom restart policy is used without --new (see #15284)
     run_podman create --restart=always $IMAGE
     cid="$output"
-    run_podman generate systemd $cid
+    run_podman 0+w generate systemd $cid
     is "$output" ".*Container $cid has restart policy .*always.* which can lead to issues on shutdown.*" "generate systemd emits warning"
     run_podman rm -f $cid
 

test/system/330-corrupt-images.bats

@@ -77,7 +77,7 @@ function _corrupt_image_test() {
         is "$output" "Error: locating item named \".*\" for image with ID \"$id\" (consider removing the image to resolve the issue): file does not exist.*"
 
         # Run the requested command. Confirm it succeeds, with suitable warnings
-        run_podman $*
+        run_podman 0+w $*
         is "$output" ".*Failed to determine parent of image.*ignoring the error" \
            "$* with missing $what_to_rm"
 

test/system/450-interactive.bats

@@ -81,7 +81,7 @@ function teardown() {
 
 
 @test "podman run --tty -i failure with no tty" {
-    run_podman run --tty -i --rm $IMAGE echo hello < /dev/null
+    run_podman 0+w run --tty -i --rm $IMAGE echo hello < /dev/null
     is "$output" ".*The input device is not a TTY.*" "-it _without_ a tty"
 
     CR=$'\r'

test/system/500-networking.bats

@@ -82,8 +82,7 @@ load helpers.network
     is "$output" 'Error: failed to find published port "99/tcp"'
 
     # Clean up
-    run_podman stop -t 1 myweb
-    run_podman rm myweb
+    run_podman rm -f -t0 myweb
 }
 
 # Issue #5466 - port-forwarding doesn't work with this option and -d
@@ -630,7 +629,11 @@ load helpers.network
         run curl --retry 2 -s $SERVER/index.txt
         is "$output" "$random_1" "curl 127.0.0.1:/index.txt after auto restart"
 
-        run_podman restart $cid
+        run_podman 0+w restart $cid
+        if ! is_remote; then
+            assert "$output" =~ "StopSignal SIGTERM failed to stop container .* in 10 seconds, resorting to SIGKILL" "podman restart issues warning"
+        fi
+
         # Verify http contents again: curl from localhost
         # Use retry since it can take a moment until the new container is ready
         run curl --retry 2 -s $SERVER/index.txt

test/system/520-checkpoint.bats

@@ -222,7 +222,7 @@ function teardown() {
     local subnet="$(random_rfc1918_subnet)"
     run_podman network create --subnet "$subnet.0/24" $netname
 
-    run_podman run -d --network $netname $IMAGE sleep inf
+    run_podman run -d --network $netname $IMAGE top
     cid="$output"
     # get current ip and mac
     run_podman inspect $cid --format "{{(index .NetworkSettings.Networks \"$netname\").IPAddress}}"
@@ -310,7 +310,7 @@ function teardown() {
     # now create a container with a static mac and ip
     local static_ip="$subnet.2"
     local static_mac="92:d0:c6:0a:29:38"
-    run_podman run -d --network "$netname:ip=$static_ip,mac=$static_mac" $IMAGE sleep inf
+    run_podman run -d --network "$netname:ip=$static_ip,mac=$static_mac" $IMAGE top
     cid="$output"
 
     run_podman container checkpoint $cid
@@ -340,7 +340,7 @@ function teardown() {
     run_podman rm -t 0 -f $cid
 
     # now create container again and try the same again with --export and --import
-    run_podman run -d --network "$netname:ip=$static_ip,mac=$static_mac" $IMAGE sleep inf
+    run_podman run -d --network "$netname:ip=$static_ip,mac=$static_mac" $IMAGE top
     cid="$output"
 
     run_podman container checkpoint --export "$archive" $cid

test/system/helpers.bash

@@ -325,8 +325,11 @@ function timestamp() {
 #
 function run_podman() {
     # Number as first argument = expected exit code; default 0
-    expected_rc=0
+    # "0+[we]" = require success, but allow warnings/errors
+    local expected_rc=0
+    local allowed_levels="dit"
     case "$1" in
+        0\+[we]*)        allowed_levels+=$(expr "$1" : "^0+\([we]\+\)"); shift;;
         [0-9])           expected_rc=$1; shift;;
         [1-9][0-9])      expected_rc=$1; shift;;
         [12][0-9][0-9])  expected_rc=$1; shift;;
@@ -336,8 +339,8 @@ function run_podman() {
     # Remember command args, for possible use in later diagnostic messages
     MOST_RECENT_PODMAN_COMMAND="podman $*"
 
-    # stdout is only emitted upon error; this echo is to help a debugger
-    echo "$(timestamp) $_LOG_PROMPT $PODMAN $*"
+    # stdout is only emitted upon error; this printf is to help in debugging
+    printf "\n%s %s %s\n" "$(timestamp)" "$_LOG_PROMPT" "$*"
     # 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
@@ -381,6 +384,28 @@ function run_podman() {
             die "exit code is $status; expected $expected_rc"
         fi
     fi
+
+    # Check for "level=<unexpected>" in output, because a successful command
+    # should never issue unwanted warnings or errors. The "0+w" convention
+    # (see top of function) allows our caller to indicate that warnings are
+    # expected, e.g., "podman stop" without -t0.
+    if [[ $status -eq 0 ]]; then
+        # FIXME: don't do this on Debian: runc is way, way too flaky:
+        # FIXME: #11784 - lstat /sys/fs/.../*.scope: ENOENT
+        # FIXME: #11785 - cannot toggle freezer: cgroups not configured
+        if [[ ! "${DISTRO_NV}" =~ debian ]]; then
+            # FIXME: All kube commands emit unpredictable errors:
+            #    "Storage for container <X> has been removed"
+            #    "no container with ID <X> found in database"
+            # These are level=error but we still get exit-status 0.
+            # Just skip all kube commands completely
+            if [[ ! "$*" =~ kube ]]; then
+                if [[ "$output" =~ level=[^${allowed_levels}] ]]; then
+                    die "Command succeeded, but issued unexpected warnings"
+                fi
+            fi
+        fi
+    fi
 }
 
 
@@ -413,7 +438,7 @@ function wait_for_output {
 
     t1=$(expr $SECONDS + $how_long)
     while [ $SECONDS -lt $t1 ]; do
-        run_podman logs $cid
+        run_podman 0+w logs $cid
         logs=$output
         if expr "$logs" : ".*$expect" >/dev/null; then
             return
@@ -426,7 +451,7 @@ function wait_for_output {
             exitcode=$output
 
             # One last chance: maybe the container exited just after logs cmd
-            run_podman logs $cid
+            run_podman 0+w logs $cid
             if expr "$logs" : ".*$expect" >/dev/null; then
                 return
             fi