Bug#1059725: autopkgtest: isolation-machine test fails: nearly all tests in podman-init fail

[Paul Gevers]

Source: autopkgtest
Version: 5.31.2
Severity: important
User: debian...@lists.debian.org
Usertags: isolation-machine

Hi,

I recently added support for isolation-machine testing on ci.d.n and when I ran the autopkgtest of src:autopkgtest, it failed. It failed the podman-init test and out of 44 tests, only 2 passed (PodmanInitRunner.test_user and PodmanInitRunner.test_user_needs_root) That's not very hopeful for the --podman --init flavor of autopkgtest-virt-docker. Nearly all of them fail in the way quoted below, I haven't figured out where these log errors come from: """logger: send message failed: Operation not permitted""" while running `create-normal-user`. Currently a full log lives here: https://ci.debian.net/data/autopkgtest/testing/amd64/a/autopkgtest/41372619/log.gz

The quote below is from me running the test inside a qemu testbed.

Paul


19:22:09 O: A skippable test succeeds ... FAIL
19:22:09 O:

19:22:09 O: A skippable test succeeds

19:22:09 O: Traceback (most recent call last):

19:22:09 O:     self.assertEqual(code, 0, err)

19:22:09 O: autopkgtest: DBG: build binaries: False
19:22:09 O: autopkgtest: DBG: testbed init

19:22:09 O: autopkgtest [19:22:06]: version 5.31.2

19:22:09 O: autopkgtest: DBG: got reply from testbed: ok
19:22:09 O: autopkgtest: DBG: testbed open, scratch=None
19:22:09 O: autopkgtest: DBG: sending command to testbed: open

19:22:09 O: autopkgtest: DBG: sending command to testbed: capabilities

19:22:09 O: autopkgtest: DBG: testbed command exited with code 0

19:22:09 O: autopkgtest: DBG: got reply from testbed: ok

19:22:09 O: autopkgtest: DBG: testbed command exited with code 0

19:22:09 O: autopkgtest: DBG: testbed command exited with code 0
19:22:09 O: autopkgtest: DBG: AutopkgtestError "sh -euc #!/bin/sh
19:22:09 O: # Copyright 2022 Simon McVittie
19:22:09 O: # SPDX-License-Identifier: GPL-2.0-or-later
19:22:09 O:
19:22:09 O: # create-normal-user [USERNAME]
19:22:09 O: # Create an ordinary, unprivileged user.
19:22:09 O:
19:22:09 O: set -eu
19:22:09 O:
19:22:09 O: usage () {
19:22:09 O:     echo "Usage: create-normal-user [USERNAME]" >&2
19:22:09 O:     exit 2
19:22:09 O: }
19:22:09 O:
19:22:09 O: create () {
19:22:09 O:     local user="$1"
19:22:09 O:     shift
19:22:09 O:
19:22:09 O:     if command -v adduser >/dev/null; then
19:22:09 O:         adduser \
19:22:09 O:             --disabled-login \
19:22:09 O:             --gecos 'Temporary autopkgtest user,,,' \
19:22:09 O:             "$user"
19:22:09 O:     elif command -v useradd >/dev/null; then
19:22:09 O:         useradd \
19:22:09 O:             --comment 'Temporary autopkgtest user' \
19:22:09 O:             --create-home \
19:22:09 O:             --expiredate '' \
19:22:09 O:             --user-group \
19:22:09 O:             "$user"
19:22:09 O:     else
19:22:09 O:         echo "Neither adduser nor useradd is installed" >&2
19:22:09 O:         return 1
19:22:09 O:     fi
19:22:09 O:
19:22:09 O:     echo "$user" > /run/autopkgtest-normal-user
19:22:09 O: }
19:22:09 O:
19:22:09 O: case "${1-}" in
19:22:09 O:     (--)
19:22:09 O:         shift
19:22:09 O:         ;;
19:22:09 O:
19:22:09 O:     (-*)
19:22:09 O:         usage
19:22:09 O:         ;;
19:22:09 O: esac
19:22:09 O:
19:22:09 O: if [ "$#" -gt 1 ]; then
19:22:09 O:     usage
19:22:09 O: fi
19:22:09 O:
19:22:09 O: if [ "$#" -eq 1 ]; then
19:22:09 O:     create "$1"
19:22:09 O:     exit 0
19:22:09 O: fi
19:22:09 O:
19:22:09 O: tries=20
19:22:09 O:
19:22:09 O: for i in $(seq 0 "$tries"); do
19:22:09 O:     if [ "$i" = 0 ]; then
19:22:09 O:         user="test"
19:22:09 O:     else
19:22:09 O:         random=$(mktemp /tmp/test-XXXXXX)
19:22:09 O:         user="$(basename "$random")"
19:22:09 O:         rm -f "$random"
19:22:09 O:     fi
19:22:09 O:
19:22:09 O:     if getent passwd "$user" >/dev/null; then
19:22:09 O:         echo "create-normal-user: '$user' already exists"
19:22:09 O:     else
19:22:09 O:         create "$user"
19:22:09 O:         exit 0
19:22:09 O:     fi
19:22:09 O: done
19:22:09 O:

19:22:09 O: exit 1

19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: "
19:22:09 O: autopkgtest: DBG: testbed stop

19:22:09 O: autopkgtest: DBG: sending command to testbed: close
19:22:09 O: autopkgtest: DBG: got reply from testbed: ok
19:22:09 O: autopkgtest: DBG: sending command to testbed: quit
19:22:09 O: autopkgtest [19:22:09]: ERROR: "sh -euc #!/bin/sh
19:22:09 O: # Copyright 2022 Simon McVittie
19:22:09 O: # SPDX-License-Identifier: GPL-2.0-or-later
19:22:09 O:
19:22:09 O: # create-normal-user [USERNAME]
19:22:09 O: # Create an ordinary, unprivileged user.
19:22:09 O:
19:22:09 O: set -eu
19:22:09 O:
19:22:09 O: usage () {
19:22:09 O:     echo "Usage: create-normal-user [USERNAME]" >&2
19:22:09 O:     exit 2
19:22:09 O: }
19:22:09 O:
19:22:09 O: create () {
19:22:09 O:     local user="$1"
19:22:09 O:     shift
19:22:09 O:
19:22:09 O:     if command -v adduser >/dev/null; then
19:22:09 O:         adduser \
19:22:09 O:             --disabled-login \
19:22:09 O:             --gecos 'Temporary autopkgtest user,,,' \
19:22:09 O:             "$user"
19:22:09 O:     elif command -v useradd >/dev/null; then
19:22:09 O:         useradd \
19:22:09 O:             --comment 'Temporary autopkgtest user' \
19:22:09 O:             --create-home \
19:22:09 O:             --expiredate '' \
19:22:09 O:             --user-group \
19:22:09 O:             "$user"
19:22:09 O:     else
19:22:09 O:         echo "Neither adduser nor useradd is installed" >&2
19:22:09 O:         return 1
19:22:09 O:     fi
19:22:09 O:
19:22:09 O:     echo "$user" > /run/autopkgtest-normal-user
19:22:09 O: }
19:22:09 O:
19:22:09 O: case "${1-}" in
19:22:09 O:     (--)
19:22:09 O:         shift
19:22:09 O:         ;;
19:22:09 O:
19:22:09 O:     (-*)
19:22:09 O:         usage
19:22:09 O:         ;;
19:22:09 O: esac
19:22:09 O:
19:22:09 O: if [ "$#" -gt 1 ]; then
19:22:09 O:     usage
19:22:09 O: fi
19:22:09 O:
19:22:09 O: if [ "$#" -eq 1 ]; then
19:22:09 O:     create "$1"
19:22:09 O:     exit 0
19:22:09 O: fi
19:22:09 O:
19:22:09 O: tries=20
19:22:09 O:
19:22:09 O: for i in $(seq 0 "$tries"); do
19:22:09 O:     if [ "$i" = 0 ]; then
19:22:09 O:         user="test"
19:22:09 O:     else
19:22:09 O:         random=$(mktemp /tmp/test-XXXXXX)
19:22:09 O:         user="$(basename "$random")"
19:22:09 O:         rm -f "$random"
19:22:09 O:     fi
19:22:09 O:
19:22:09 O:     if getent passwd "$user" >/dev/null; then
19:22:09 O:         echo "create-normal-user: '$user' already exists"
19:22:09 O:     else
19:22:09 O:         create "$user"
19:22:09 O:         exit 0
19:22:09 O:     fi
19:22:09 O: done
19:22:09 O:

19:22:09 O: exit 1

19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: logger: send message failed: Operation not permitted
19:22:09 O: "
19:22:09 O: autopkgtest: DBG: testbed stop
19:22:09 O:
19:22:09 O:

19:22:09 O: Ran 1 test in 3.249s
19:22:09 O:
19:22:09 O: FAILED (failures=1)
19:22:09 I: Finished with exitcode 1

19:22:05 I: Started ./tests/autopkgtest PodmanInitRunner.test_skippable_success 19:22:06 O: test_skippable_success (__main__.PodmanInitRunner.test_skippable_success) 19:22:09 O: ====================================================================== 19:22:09 O: FAIL: test_skippable_success (__main__.PodmanInitRunner.test_skippable_success) 19:22:09 O: ---------------------------------------------------------------------- 19:22:09 O: File "/tmp/autopkgtest.BNQ3Xt/build.9s6/real-tree/./tests/autopkgtest", line 455, in test_skippable_success 19:22:09 O: AssertionError: 20 != 0 : autopkgtest: DBG: autopkgtest options: Namespace(override_control=None, only_tests=[], skip_tests=None, built_binaries=False, packages=['/tmp/autopkgtest.test.e19zee88/testpkg'], output_dir=None, logfile=None, summary=None, verbosity=2, setup_commands=[], setup_commands_boot=[], add_apt_sources=[], add_apt_releases=[], pin_packages=[], apt_pocket=[], apt_default_release=None, enable_apt_fallback=True, copy=[], env=[], ignore_restrictions=[], user=None, gainroot=None, shell_fail=False, shell=False, timeout=0, timeout_short=None, timeout_copy=None, timeout_install=None, timeout_test=None, timeout_build=None, timeout_factor=1.0, set_lang=None, auto_control=True, build_parallel=None, needs_internet='run', validate=False) 19:22:09 O: autopkgtest: DBG: virt-runner arguments: ['podman', '--init', 'autopkgtest/systemd/debian:testing'] 19:22:09 O: autopkgtest: DBG: actions: [('unbuilt-tree', '/tmp/autopkgtest.test.e19zee88/testpkg', False)] 19:22:09 O: autopkgtest [19:22:06]: starting date and time: 2023-12-30 19:22:06+0000 19:22:09 O: autopkgtest [19:22:06]: host host; command line: /usr/bin/autopkgtest -d --no-built-binaries /tmp/autopkgtest.test.e19zee88/testpkg -- podman --init autopkgtest/systemd/debian:testing 19:22:09 O: autopkgtest: DBG: got reply from testbed: ok /tmp/autopkgtest-virt-docker.shared.3sui98zn/downtmp 19:22:09 O: autopkgtest: DBG: sending command to testbed: print-execute-command 19:22:09 O: autopkgtest: DBG: got reply from testbed: ok podman,exec,-i,2afe2dad7c01b2607f2184eb63ee03dee0172a73a104bee26d971fd1092a81df,env,-i,bash,-c,set%20-a%3B%20%5B%20-r%20/etc/environment%20%5D%20%26%26%20.%20/etc/environment%202%3E/dev/null%20%7C%7C%20true%3B%20%5B%20-r%20/etc/default/locale%20%5D%20%26%26%20.%20/etc/default/locale%202%3E/dev/null%20%7C%7C%20true%3B%20%5B%20-r%20/etc/profile%20%5D%20%26%26%20.%20/etc/profile%202%3E/dev/null%20%7C%7C%20true%3B%20set%20%2Ba%3B%22%24%40%22%3B%20RC%3D%24%3F%3B%20%5B%20%24RC%20%21%3D%20255%20%5D%20%7C%7C%20RC%3D253%3B%20set%20-e%3Bmyout%3D%24%28readlink%20/proc/%24%24/fd/1%29%3Bmyerr%3D%24%28readlink%20/proc/%24%24/fd/2%29%3Bmyout%3D%22%24%7Bmyout/%5B/%5C%5C%5B%7D%22%3B%20myout%3D%22%24%7Bmyout/%5D/%5C%5C%5D%7D%22%3Bmyerr%3D%22%24%7Bmyerr/%5B/%5C%5C%5B%7D%22%3B%20myerr%3D%22%24%7Bmyerr/%5D/%5C%5C%5D%7D%22%3BPS%3D%24%28ls%20-l%20/proc/%5B0-9%5D%2A/fd/%2A%202%3E/dev/null%20%7C%20sed%20-nr%20%27%5C%23%28%27%22%24myout%22%27%7C%27%22%24myerr%22%27%29%23%20%7B%20s%23%5E.%2A/proc/%28%5B0-9%5D%2B%29/.%2A%24%23%5C1%23%3B%20p%7D%27%7Csort%20-u%29%3BKILL%3D%22%22%3Bfor%20pid%20in%20%24PS%3B%20do%20%20%20%20%5B%20%24pid%20-ne%20%24%24%20%5D%20%26%26%20%5B%20%24pid%20-ne%20%24PPID%20%5D%20%7C%7C%20continue%3B%20%20%20%20KILL%3D%22%24KILL%20%24pid%22%3Bdone%3B%5B%20-z%20%22%24KILL%22%20%5D%20%7C%7C%20kill%20-9%20%24KILL%20%3E/dev/null%202%3E%261%20%7C%7C%20true%3Bexit%20%24RC,-- 19:22:09 O: autopkgtest: DBG: got reply from testbed: ok revert revert-full-system root-on-testbed isolation-container downtmp-host=/tmp/autopkgtest-virt-docker.shared.3sui98zn/downtmp 19:22:09 O: autopkgtest: DBG: testbed capabilities: ['revert', 'revert-full-system', 'root-on-testbed', 'isolation-container', 'downtmp-host=/tmp/autopkgtest-virt-docker.shared.3sui98zn/downtmp', 'has_internet'] 19:22:09 O: autopkgtest: DBG: testbed command ['mkdir', '-p', '/tmp/autopkgtest-virt-docker.shared.3sui98zn/downtmp'], kind short, sout raw, serr pipe, env [] 19:22:09 O: autopkgtest: DBG: sending command to testbed: copydown /usr/share/autopkgtest/lib/in-testbed/wrapper.sh /tmp/autopkgtest-virt-docker.shared.3sui98zn/downtmp/wrapper.sh 19:22:09 O: autopkgtest: DBG: testbed command ['chmod', '-R', '0755', '--', '/tmp/autopkgtest-virt-docker.shared.3sui98zn/downtmp/wrapper.sh'], kind short, sout raw, serr pipe, env [] 19:22:09 O: autopkgtest: DBG: testbed command ['sh', '-euc', '#!/bin/sh\n# Copyright 2022 Simon McVittie\n# SPDX-License-Identifier: GPL-2.0-or-later\n\n# create-normal-user [USERNAME]\n# Create an ordinary, unprivileged user.\n\nset -eu\n\nusage () {\n echo "Usage: create-normal-user [USERNAME]" >&2\n exit 2\n}\n\ncreate () {\n local user="$1"\n shift\n\n if command -v adduser >/dev/null; then\n adduser \\\n --disabled-login \\\n --gecos \'Temporary autopkgtest user,,,\' \\\n "$user"\n elif command -v useradd >/dev/null; then\n useradd \\\n --comment \'Temporary autopkgtest user\' \\\n --create-home \\\n --expiredate \'\' \\\n --user-group \\\n "$user"\n else\n echo "Neither adduser nor useradd is installed" >&2\n return 1\n fi\n\n echo "$user" > /run/autopkgtest-normal-user\n}\n\ncase "${1-}" in\n (--)\n shift\n ;;\n\n (-*)\n usage\n ;;\nesac\n\nif [ "$#" -gt 1 ]; then\n usage\nfi\n\nif [ "$#" -eq 1 ]; then\n create "$1"\n exit 0\nfi\n\ntries=20\n\nfor i in $(seq 0 "$tries"); do\n if [ "$i" = 0 ]; then\n user="test"\n else\n random=$(mktemp /tmp/test-XXXXXX)\n user="$(basename "$random")"\n rm -f "$random"\n fi\n\n if getent passwd "$user" >/dev/null; then\n echo "create-normal-user: \'$user\' already exists"\n else\n create "$user"\n exit 0\n fi\ndone\n\necho "create-normal-user: Unable to generate a new username (tried $tries times)" >&2\nexit 1\n'], kind short, sout raw, serr pipe, env [] 19:22:09 O: echo "create-normal-user: Unable to generate a new username (tried $tries times)" >&2 19:22:09 O: " failed with stderr "logger: send message failed: Operation not permitted 19:22:09 O: autopkgtest: DBG: testbed close, scratch=/tmp/autopkgtest-virt-docker.shared.3sui98zn/downtmp 19:22:09 O: echo "create-normal-user: Unable to generate a new username (tried $tries times)" >&2 19:22:09 O: " failed with stderr "logger: send message failed: Operation not permitted 19:22:09 O: ----------------------------------------------------------------------

OpenPGP_signature.asc
Description: OpenPGP digital signature