#1077876 autopkgtest shouldn't print warnings from adduser

Package:
autopkgtest
Source:
autopkgtest
Submitter:
Reinhard Tartler
Date:
2024-08-05 14:21:02 UTC
Severity:
normal
Tags:
#1077876#5
Date:
2024-08-03 21:29:26 UTC
From:
To:
Dear Maintainer,

I'm trying to use the autopkgtest podman server to run a test that
requires the capability "isolation-container". From the manpage, I
understand that I need to create a container image with like this:

 $ autopkgtest-build-podman  --init=systemd --apt-proxy " "
[...]
--> 080a41d72252
STEP 14/14: CMD ["/sbin/init"]
COMMIT autopkgtest/systemd/debian:unstable
--> 576ad2a556a1
Successfully tagged localhost/autopkgtest/systemd/debian:unstable
576ad2a556a11fb157f1668df1623712448c276b8213209292d16a3bae448876


Now I'm trying to use this image to run the etcd tests:

 $ autopkgtest --test-name=integration -B . -- podman --init localhost/autopkgtest/systemd/debian:unstable
autopkgtest [17:23:47]: starting date and time: 2024-08-03 17:23:47-0400
autopkgtest [17:23:47]: version 5.37
autopkgtest [17:23:47]: host x1; command line: /usr/bin/autopkgtest --test-name=integration -B . -- podman --init localhost/autopkgtest/systemd/debian:unstable
info: Adding user `test' ...
info: Selecting UID/GID from range 1000 to 59999 ...
info: Adding new group `test' (1000) ...
info: Adding new user `test' (1000) with group `test (1000)' ...
info: Creating home directory `/home/test' ...
info: Copying files from `/etc/skel' ...
info: Adding new user `test' to supplemental / extra groups `users' ...
info: Adding user `test' to group `users' ...
autopkgtest [17:23:49]: ERROR: "sh -euc #!/bin/sh
# Copyright 2022 Simon McVittie
# SPDX-License-Identifier: GPL-2.0-or-later

# create-normal-user [USERNAME]
# Create an ordinary, unprivileged user.

set -eu

usage () {
    echo "Usage: create-normal-user [USERNAME]" >&2
    exit 2
}

create () {
    # shellcheck disable=SC3043
    local user="$1"
    shift

    if command -v adduser >/dev/null; then
        adduser \
            --disabled-login \
            --gecos 'Temporary autopkgtest user,,,' \
            "$user"
    elif command -v useradd >/dev/null; then
        useradd \
            --comment 'Temporary autopkgtest user' \
            --create-home \
            --expiredate '' \
            --user-group \
            "$user"
    else
        echo "Neither adduser nor useradd is installed" >&2
        return 1
    fi

    echo "$user" > /run/autopkgtest-normal-user
}

case "${1-}" in
    (--)
        shift
        ;;

    (-*)
        usage
        ;;
esac

if [ "$#" -gt 1 ]; then
    usage
fi

if [ "$#" -eq 1 ]; then
    create "$1"
    exit 0
fi

tries=20

for i in $(seq 0 "$tries"); do
    if [ "$i" = 0 ]; then
        user="test"
    else
        random=$(mktemp /tmp/test-XXXXXX)
        user="$(basename "$random")"
        rm -f "$random"
    fi

    if getent passwd "$user" >/dev/null; then
        echo "create-normal-user: '$user' already exists"
    else
        create "$user"
        exit 0
    fi
done

echo "create-normal-user: Unable to generate a new username (tried $tries times)" >&2
exit 1
" failed with stderr "logger: send message failed: Operation not permitted
logger: send message failed: Operation not permitted
logger: send message failed: Operation not permitted
logger: send message failed: Operation not permitted
logger: send message failed: Operation not permitted
logger: send message failed: Operation not permitted
logger: send message failed: Operation not permitted
logger: send message failed: Operation not permitted
"

Where is this Operation not permitted coming from? Is there an issue
with the image creation or is this something else?

Best,
-rt

#1077876#10
Date:
2024-08-03 21:58:54 UTC
From:
To:
Would you consider the following patch? It makes autopkgtest work for me:

diff --git a/setup-commands/create-normal-user b/setup-commands/create-normal-user
index 0d0e828..9d66694 100755
--- a/setup-commands/create-normal-user
+++ b/setup-commands/create-normal-user
@@ -21,7 +21,7 @@ create () {
         adduser \
             --disabled-login \
             --gecos 'Temporary autopkgtest user,,,' \
-            "$user" 2>&1
+            "$user" 2>&1 | grep -v 'send message failed: Operation not permitted'
     elif command -v useradd >/dev/null; then
         useradd \
             --comment 'Temporary autopkgtest user' \

#1077876#17
Date:
2024-08-04 07:08:00 UTC
From:
To:
Hi Reinhard,

I'm puzzled.

On 03-08-2024 23:29, Reinhard Tartler wrote:
 > Package: autopkgtest
 > Version: 5.37

This "2>&1" was added in 5.38 to prevent the problem you're seeing. As
you see it redirects stderr to stdout, while the original report says it
fails because of output on stderr (which matches 5.37 behavior). Does
the 2>&1 not work? You're original report was against 5.37, your patch
is against 5.38.

Paul

#1077876#24
Date:
2024-08-04 11:40:03 UTC
From:
To:
I apologize, I was confused by the fact that this patch has not reached
sid yet.

With create-normal-user having the stderr output being redirect to
stdout using '2>&1',
the autopkgtest tool does now start executing tests. However,I still
observe confusing output:

autopkgtest [07:35:44]: host x1; command line: /usr/bin/autopkgtest
--test-name=functional -B . -- podman --init autopkgtest:etcd
info: Adding user `test' ...
logger: send message failed: Operation not permitted
info: Selecting UID/GID from range 1000 to 59999 ...
logger: send message failed: Operation not permitted
info: Adding new group `test' (1000) ...
logger: send message failed: Operation not permitted
info: Adding new user `test' (1000) with group `test (1000)' ...
logger: send message failed: Operation not permitted
info: Creating home directory `/home/test' ...
logger: send message failed: Operation not permitted
info: Copying files from `/etc/skel' ...
logger: send message failed: Operation not permitted
info: Adding new user `test' to supplemental / extra groups `users' ...
logger: send message failed: Operation not permitted
info: Adding user `test' to group `users' ...
logger: send message failed: Operation not permitted
autopkgtest [07:35:47]: testbed dpkg architecture: amd64
autopkgtest [07:35:47]: testbed apt version: 2.9.7
autopkgtest [07:35:47]: testbed running kernel: Linux 6.9.12-amd64 #1
SMP PREEMPT_DYNAMIC Debian 6.9.12-1 (2024-07-27)


None of that is particularly helpful and confusing at best. Filtering
out known harmless error message will avoid users scratching their
heads, wasting time on debugging and as such lead to better UX.

#1077876#29
Date:
2024-08-04 11:53:20 UTC
From:
To:
Hi,

No problem. I was hoping this would explain.

Great.

Agree. I'm a bit surprised it's printed, because I thought output to
stdout at that level would already be ignored (as you can see in my
comments in the merge request [1]). I'll think about the best solution
(probably just 2> /dev/null) as I don't think we want to maintain a list
of harmless messages to filter out.

Paul

[1] https://salsa.debian.org/ci-team/autopkgtest/-/merge_requests/379

#1077876#38
Date:
2024-08-04 12:29:52 UTC
From:
To:
Thank you so much! And to Simon and everyone else working on autopkgtest
and in particular its podman related parts. It is a big help to me for
writing, and more importantly validating, non-trivial autopkgtest script
for container related packages.

Please don't hesitate to reach out to me if there is anything I can do
in the Debian podman/libpod package to make your life/work easier!

Best,
-rt

#1077876#43
Date:
2024-08-04 13:43:03 UTC
From:
To:
The problem here is that we don't want to print spurious warnings from
adduser, but we do want to print fatal errors from adduser, and we also
do want to print non-spurious warnings from adduser
(for example "you're using the --hypothetical option which is deprecated
and will be removed in future" is the sort of warning that we *do*
want to see).

The underlying issue here is the adduser bug
<https://bugs.debian.org/1074567>, for which I summarized the adduser side
in <https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1074567#39>.

    smcv

#1077876#48
Date:
2024-08-05 12:52:04 UTC
From:
To:
On doing 2>/dev/null, I believe that a-v-unshare runs tests without a
populated /dev, so /dev/null is missing. In create-normal-user there are
other >/dev/null redirects, and unshare appears to be working, but it
could by chance.

However: maybe this is a bug in a-virt-unshare, missing a bind mount?

#1077876#53
Date:
2024-08-05 13:55:53 UTC
From:
To:
If true, then that's an important bug in a-v-unshare. Our testbeds
should all be tolerably realistic systems that meet the minimum "API"
requirements for a reasonable Debian chroot/container.

Concretely, I think all of our container backends should set up at least
a minimal /dev, something similar to
`bwrap --ro-bind / / --dev /dev ls /dev` in bubblewrap:

console
core -> /proc/kcore (I don't think this one is actually important)
fd -> /proc/self/fd
full
null
ptmx -> pts/ptmx
pts/
random
shm/
stderr -> /proc/self/fd/2
stdin -> /proc/self/fd/0
stdout -> /proc/self/fd/1
tty
urandom
zero

My understanding is that this is exactly the set of device nodes that it's
possible to set up by using user namespaces, without special privileges
(plus some easy symlinks). debootstrap and pbuilder create a similar set.

    smcv

#1077876#58
Date:
2024-08-05 14:17:52 UTC
From:
To:
https://salsa.debian.org/ci-team/autopkgtest/-/blob/30c9c0a589aa49bc86649b825b29a1be647d8c26/virt/autopkgtest-virt-unshare#L128

and it is during that early useradd call that /dev/null does not exist.
(I know because this causes issues in Ubuntu, with its patched useradd
assuming /dev/null exists.)

For the actual test run, unshare-helper takes care of creating /dev/null
and others:

https://salsa.debian.org/ci-team/autopkgtest/-/blob/30c9c0a589aa49bc86649b825b29a1be647d8c26/virt/autopkgtest-virt-unshare#L141

So: no need to worry about >/dev/null redirects in create-normal-user.