system tests: periodic cleanup and fixes

- basic       : add actual log-level tests
- events      : clean up, add --format tests
- systemd     : reorder proxy args for legibility
- auto-update : fix missing timeout that could lead to hang

Signed-off-by: Ed Santiago <santiago@redhat.com>

4 files changed, 96 insertions, 14 deletions

diff --git a/test/system/001-basic.bats b/test/system/001-basic.bats
index e3302bec3..378edc013 100644
--- a/test/system/001-basic.bats
+++ b/test/system/001-basic.bats
@@ -188,17 +188,77 @@ See 'podman version --help'" "podman version --remote"
 @test "podman --log-level recognizes log levels" {
     run_podman 1 --log-level=telepathic info
     is "$output" 'Log Level "telepathic" is not supported.*'
+
     run_podman --log-level=trace   info
+    if ! is_remote; then
+        # podman-remote does not do any trace logging
+        assert "$output" =~ " level=trace " "log-level=trace"
+    fi
+    assert "$output" =~ " level=debug " "log-level=trace includes debug"
+    assert "$output" =~ " level=info "  "log-level=trace includes info"
+    assert "$output" !~ " level=warn"   "log-level=trace does not show warn"
+
     run_podman --log-level=debug   info
+    assert "$output" !~ " level=trace " "log-level=debug does not show trace"
+    assert "$output" =~ " level=debug " "log-level=debug"
+    assert "$output" =~ " level=info "  "log-level=debug includes info"
+    assert "$output" !~ " level=warn"   "log-level=debug does not show warn"
+
     run_podman --log-level=info    info
+    assert "$output" !~ " level=trace " "log-level=info does not show trace"
+    assert "$output" !~ " level=debug " "log-level=info does not show debug"
+    assert "$output" =~ " level=info "  "log-level=info"
+
     run_podman --log-level=warn    info
+    assert "$output" !~ " level=" "log-level=warn shows no logs at all"
+
+    # Force a warning (local podman only; podman-remote doesn't check versions)
+    if ! is_remote; then
+        run_podman --log-level=warn --storage-opt=mount_program=/bin/false info
+        assert "$output" =~ " level=warning msg=\"Failed to retrieve " \
+               "log-level=warn"
+
+        # confirm that default level is "warn", by invoking without --log-level
+        run_podman --storage-opt=mount_program=/bin/false info
+        assert "$output" =~ " level=warning msg=\"Failed to retrieve " \
+               "default log level includes warning messages"
+    fi
+
     run_podman --log-level=warning info
+    assert "$output" !~ " level=" "log-level=warning shows no logs at all"
+
     run_podman --log-level=error   info
-    run_podman --log-level=fatal   info
-    run_podman --log-level=panic   info
+    assert "$output" !~ " level=" "log-level=error shows no logs at all"
+
+    # error, fatal, panic:
+    if is_remote; then
+        # podman-remote does not grok --runtime; all we can do is test parsing
+        for level in error fatal panic; do
+            run_podman --log-level=$level info
+            assert "$output" !~ " level=" \
+                   "log-level=$level shows no logs at all"
+        done
+    else
+        # local podman only
+        run_podman --log-level=error --storage-opt=mount_program=/bin/false --runtime=/bin/false info
+        assert "$output" =~ " level=error msg=\"Getting info on OCI runtime " \
+               "log-level=error shows "
+        assert "$output" !~ " level=warn" \
+               "log-level=error does not show warnings"
+
+        run_podman --log-level=fatal --storage-opt=mount_program=/bin/false --runtime=/bin/false info
+        assert "$output" !~ " level=" "log-level=fatal shows no logs at all"
+
+        run_podman --log-level=panic --storage-opt=mount_program=/bin/false --runtime=/bin/false info
+        assert "$output" !~ " level=" "log-level=panic shows no logs at all"
+    fi
+
     # docker compat
     run_podman --debug   info
+    assert "$output" =~ " level=debug " "podman --debug gives debug output"
     run_podman -D        info
+    assert "$output" =~ " level=debug " "podman -D gives debug output"
+
     run_podman 1 --debug --log-level=panic info
     is "$output" "Setting --log-level and --debug is not allowed"
 }
diff --git a/test/system/090-events.bats b/test/system/090-events.bats
index 3fac51938..90b9b3b9c 100644
--- a/test/system/090-events.bats
+++ b/test/system/090-events.bats
@@ -22,24 +22,25 @@ load helpers
 
     # Now filter just by container name, no label
     run_podman events --filter type=container --filter container=$cname --filter event=start --stream=false
-    is "$output" "$expect" "filtering just by label"
+    is "$output" "$expect" "filtering just by container"
 }
 
 @test "truncate events" {
     cname=test-$(random_string 30 | tr A-Z a-z)
-    labelname=$(random_string 10)
-    labelvalue=$(random_string 15)
 
     run_podman run -d --name=$cname --rm $IMAGE echo hi
     id="$output"
 
-    expect="$id"
     run_podman events --filter container=$cname --filter event=start --stream=false
     is "$output" ".* $id " "filtering by container name full id"
 
-    truncID=$(expr substr "$id" 1 12)
+    truncID=${id:0:12}
     run_podman events --filter container=$cname --filter event=start --stream=false --no-trunc=false
     is "$output" ".* $truncID " "filtering by container name trunc id"
+
+    # --no-trunc does not affect --format; we always get the full ID
+    run_podman events --filter container=$cname --filter event=died --stream=false --format='{{.ID}}--{{.Image}}' --no-trunc=false
+    assert "$output" = "${id}--${IMAGE}"
 }
 
 @test "image events" {
@@ -65,6 +66,7 @@ load helpers
     run_podman --events-backend=file untag $IMAGE $tag
     run_podman --events-backend=file tag $IMAGE $tag
     run_podman --events-backend=file rmi -f $imageID
+    run_podman --events-backend=file load -i $tarball
 
     run_podman --events-backend=file events --stream=false --filter type=image --since $t0
     is "$output" ".*image push $imageID dir:$pushedDir
@@ -78,6 +80,25 @@ load helpers
 .*image untag $imageID $tag:latest
 .*image remove $imageID $imageID" \
        "podman events"
+
+    # With --format we can check the _exact_ output, not just substrings
+    local -a expect=("push--dir:$pushedDir"
+                     "save--$tarball"
+                     "loadfromarchive--$tarball"
+                     "pull--docker-archive:$tarball"
+                     "tag--$tag"
+                     "untag--$tag:latest"
+                     "tag--$tag"
+                     "untag--$IMAGE"
+                     "untag--$tag:latest"
+                     "remove--$imageID"
+                     "loadfromarchive--$tarball"
+                    )
+    run_podman --events-backend=file events --stream=false --filter type=image --since $t0 --format '{{.Status}}--{{.Name}}'
+    for i in $(seq 0 ${#expect[@]}); do
+        assert "${lines[$i]}" = "${expect[$i]}" "events, line $i"
+    done
+    assert "${#lines[@]}" = "${#expect[@]}" "Total lines of output"
 }
 
 function _events_disjunctive_filters() {
@@ -111,7 +132,8 @@ function _events_disjunctive_filters() {
     is "$output" "hi" "Should support events-backend=file"
 
     run_podman 125 --events-backend=file logs --follow test
-    is "$output" "Error: using --follow with the journald --log-driver but without the journald --events-backend (file) is not supported" "Should fail with reasonable error message when events-backend and events-logger do not match"
+    is "$output" "Error: using --follow with the journald --log-driver but without the journald --events-backend (file) is not supported" \
+       "Should fail with reasonable error message when events-backend and events-logger do not match"
 
 }
 
@@ -136,7 +158,7 @@ function _populate_events_file() {
     local events_file=$1
     truncate --size=0 $events_file
     for i in {0..99}; do
-    printf '{"Name":"busybox","Status":"pull","Time":"2022-04-06T11:26:42.7236679%02d+02:00","Type":"image","Attributes":null}\n' $i >> $events_file
+        printf '{"Name":"busybox","Status":"pull","Time":"2022-04-06T11:26:42.7236679%02d+02:00","Type":"image","Attributes":null}\n' $i >> $events_file
     done
 }
 
@@ -196,7 +218,7 @@ EOF
     # Make sure that `podman events` can read the file, and that it returns the
     # same amount of events.  We checked the contents before.
     CONTAINERS_CONF=$containersConf run_podman events --stream=false --since="2022-03-06T11:26:42.723667984+02:00"
-    is "$(wc -l <$eventsFile)" "$(wc -l <<<$output)" "all events are returned"
+    assert "${#lines[@]}" = 51 "Number of events returned"
     is "${lines[-2]}" ".* log-rotation $eventsFile"
 }
 
diff --git a/test/system/250-systemd.bats b/test/system/250-systemd.bats
index 3f6296b36..0e1dc356d 100644
--- a/test/system/250-systemd.bats
+++ b/test/system/250-systemd.bats
@@ -34,9 +34,8 @@ function teardown() {
 # Helper to start a systemd service running a container
 function service_setup() {
     run_podman generate systemd \
-               -e http_proxy -e HTTP_PROXY \
-               -e https_proxy -e HTTPS_PROXY \
-               -e no_proxy -e NO_PROXY \
+               -e http_proxy -e https_proxy -e no_proxy \
+               -e HTTP_PROXY -e HTTPS_PROXY -e NO_PROXY \
                --new $cname
     echo "$output" > "$UNIT_FILE"
     run_podman rm $cname
diff --git a/test/system/255-auto-update.bats b/test/system/255-auto-update.bats
index a106914fe..76f6b02e8 100644
--- a/test/system/255-auto-update.bats
+++ b/test/system/255-auto-update.bats
@@ -115,6 +115,7 @@ function _confirm_update() {
     # Image has already been pulled, so this shouldn't take too long
     local timeout=5
     while [[ $timeout -gt 0 ]]; do
+        sleep 1
         run_podman '?' inspect --format "{{.Image}}" $cname
         if [[ $status != 0 ]]; then
             if [[ $output =~ (no such object|does not exist in database): ]]; then
@@ -126,7 +127,7 @@ function _confirm_update() {
         elif [[ $output != $old_iid ]]; then
             return
         fi
-        sleep 1
+        timeout=$((timeout - 1))
     done
 
     die "Timed out waiting for $cname to update; old IID=$old_iid"