Spurious fails in TEST-46-HOMED

[mrc0mmand]

systemd version the issue has been seen with

latest master

Used distribution

Arch Linux

In several latest CentOS CI results I noticed an intermittent fail in TEST-46-HOMED:

[   45.107852] testsuite-46.sh[246]: + diff -I '^\s*Disk \(Size\|Free\|Floor\|Ceiling\):' /tmp/a /tmp/b
[   45.108536] testsuite-46.sh[246]: + rm /tmp/a /tmp/b
[   45.111213] testsuite-46.sh[246]: + SYSTEMD_LOG_LEVEL=debug
[   45.111213] testsuite-46.sh[246]: + PASSWORD=yPN4N0fYNKUkOq
[   45.111213] testsuite-46.sh[246]: + NEWPASSWORD=xEhErW0ndafV4s
[   45.111213] testsuite-46.sh[246]: + homectl passwd test-user
[   45.118581] homectl[471]: Bus n/a: changing state UNSET → OPENING
[   45.119274] homectl[471]: sd-bus: starting bus by connecting to /run/dbus/system_bus_socket...
[   45.119401] homectl[471]: Bus n/a: changing state OPENING → AUTHENTICATING
[   45.120167] homectl[471]: Bus n/a: changing state AUTHENTICATING → HELLO
[   45.120278] homectl[471]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 signature=n/a error-name=n/a error-messa>
[   45.121201] homectl[471]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.16 path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=n/a error-message=n/a
[   45.121329] homectl[471]: Bus n/a: changing state HELLO → RUNNING
[   45.121737] homectl[471]: Sent message type=method_call sender=n/a destination=org.freedesktop.home1 path=/org/freedesktop/home1 interface=org.freedesktop.home1.Manager member=ChangePasswordHome cookie=2 reply_cookie=0 signature=sss er>
[   45.235877] systemd-homed[223]: test-user: changing state active → passwd-while-active
[   46.396633] systemd-homework[472]: No valid password for LUKS superblock.
[   48.259199] systemd-homed[223]: Change operation failed: Required key not available
[   48.259619] systemd-homed[223]: test-user: changing state passwd-while-active → active
[   48.259818] homectl[471]: Got message type=error sender=:1.0 destination=:1.16 path=n/a interface=n/a member=n/a cookie=114 reply_cookie=2 signature=s error-name=org.freedesktop.home1.BadPassword error-message=Password for home test-us>
[   48.262588] homectl[471]: Sent message type=method_call sender=n/a destination=org.freedesktop.home1 path=/org/freedesktop/home1 interface=org.freedesktop.home1.Manager member=ChangePasswordHome cookie=3 reply_cookie=0 signature=sss er>
[   48.482874] systemd-homed[223]: test-user: changing state active → passwd-while-active
[   50.521386] systemd-homework[473]: Discovered used LUKS device /dev/mapper/home-test-user, and validated password.
[   50.640260] systemd-homework[473]: Successfully re-activated LUKS device.
[   50.735247] systemd-homework[473]: Provided password unlocks user record.
[   50.735633] systemd-homework[473]: Discovered used loopback device /dev/loop0.
[   50.735796] systemd-homework[473]: Failed to open .identity file in home directory: Permission denied
[   50.739144] systemd-homed[223]: Change operation failed: Permission denied
[   50.739691] systemd-homed[223]: test-user: changing state passwd-while-active → active
[   50.739796] homectl[471]: Got message type=error sender=:1.0 destination=:1.16 path=n/a interface=n/a member=n/a cookie=117 reply_cookie=3 signature=s error-name=org.freedesktop.DBus.Error.AccessDenied error-message=Failed to execute o>
[   50.740123] homectl[471]: Operation on home test-user failed: Access denied
[   50.740241] homectl[471]: Bus n/a: changing state RUNNING → CLOSED

Full journal: system.journal.tar.gz

/cc @poettering

[mrc0mmand]

Looks like it's not intermittent, as after updating the Arch Linux image it seems to happen every time the test runs.

https://jenkins-systemd.apps.ocp.ci.centos.org/job/upstream-vagrant-archlinux/8354/artifact//systemd-centos-ci/index.html

[poettering]

my educated guess: the Arch Linux CI now uses a kernel that has uidmap support in its btrfs, and that triggers a new codepath that wasn't tested so far.

I'll update to kernel 5.15 to match what the Arch Linux CI has. Let's see if this allows me to reproduce this here.

[poettering]

yeah, this is 100% reproducible with kernel 5.15

[poettering]

(that said, our test suite doesn't pass with 5.15 otherwise currently, see #21503)

[mrc0mmand]

(that said, our test suite doesn't pass with 5.15 otherwise currently, see #21503)

Yeah, I had to drop the failing test in the Arch part of the CI (systemd/systemd-centos-ci@bb79a5d) because of that, but I'm glad I can revert it once #21503 gets merged.