FS#73208 - Systemd-homed fails with systemd-250

Attached to Project: Arch Linux
Opened by Gael (Mploppy) - Friday, 31 December 2021, 19:08 GMT
Last edited by Toolybird (Toolybird) - Saturday, 15 April 2023, 22:45 GMT
Task Type Bug Report
Category Packages: Core
Status Closed
Assigned To Christian Hesse (eworm)
Architecture All
Severity Critical
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 4
Private No

Details

Description:

Systemd-homed fails to do anything (systemd v. 250).

Downgrading to 249.7-2 solves the problem.


Additional info:

Dec 31 18:34:25 heaven systemd-homed[766]: mploppy: changing state dirty → activating-for-acquire
Dec 31 18:34:25 heaven systemd-homework[1558]: None of the supplied plaintext passwords unlock the user record's hashed passwords.
Dec 31 18:34:25 heaven systemd-homed[766]: Activation failed: Required key not available
Dec 31 18:34:25 heaven systemd-homed[766]: mploppy: changing state activating-for-acquire → dirty
Dec 31 18:34:25 heaven systemd-homed[766]: Got notification that all sessions of user mploppy ended, deactivating automatically.
Dec 31 18:34:25 heaven systemd-homed[766]: Home mploppy already deactivated, no automatic deactivation needed.
Dec 31 18:34:27 heaven systemd-homed[766]: mploppy: changing state dirty → activating-for-acquire
Dec 31 18:34:27 heaven systemd-homework[1559]: Provided password unlocks user record.
Dec 31 18:34:27 heaven systemd-homework[1559]: Successfully locked image file '/home/mploppy.home'.
Dec 31 18:34:27 heaven systemd-homework[1559]: Backing file is fully allocated already.
Dec 31 18:34:27 heaven systemd-homework[1559]: Setting up loopback device /dev/loop0 completed.
Dec 31 18:34:27 heaven kernel: loop0: detected capacity change from 0 to 1677719519
Dec 31 18:34:27 heaven kernel: blk_update_request: I/O error, dev loop0, sector 1677719512 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
Dec 31 18:34:27 heaven kernel: blk_update_request: I/O error, dev loop0, sector 1677719512 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
Dec 31 18:34:27 heaven kernel: Buffer I/O error on dev loop0, logical block 209714939, async page read
Dec 31 18:34:27 heaven kernel: blk_update_request: I/O error, dev loop0, sector 1677719512 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
Dec 31 18:34:27 heaven kernel: Buffer I/O error on dev loop0, logical block 209714939, async page read
Dec 31 18:34:27 heaven kernel: blk_update_request: I/O error, dev loop0, sector 1677719512 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
Dec 31 18:34:27 heaven kernel: Buffer I/O error on dev loop0, logical block 209714939, async page read
Dec 31 18:34:27 heaven kernel: device-mapper: table: 254:1: len=1677686751 not aligned to h/w logical block size 4096 of loop0
Dec 31 18:34:27 heaven kernel: device-mapper: core: Cannot calculate initial queue limits
Dec 31 18:34:27 heaven kernel: device-mapper: ioctl: unable to set up device queue for new table.
Dec 31 18:34:27 heaven systemd-homework[1559]: device-mapper: reload ioctl on home-mploppy (254:1) failed: Invalid argument
Dec 31 18:34:27 heaven systemd-homework[1559]: Failed to unlock LUKS superblock: No such device
Dec 31 18:34:27 heaven kernel: blk_update_request: I/O error, dev loop0, sector 1677719512 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
Dec 31 18:34:27 heaven kernel: Buffer I/O error on dev loop0, logical block 209714939, async page read
Dec 31 18:34:28 heaven systemd-homed[766]: block device /sys/devices/virtual/block/loop0 has been removed.
Dec 31 18:34:28 heaven systemd-homed[766]: Activation failed: No such device
Dec 31 18:34:28 heaven systemd-homed[766]: mploppy: changing state activating-for-acquire → dirty
Dec 31 18:34:28 heaven login[1552]: pam_systemd_home(login:auth): Failed to acquire home for user mploppy: Failed to execute operation: No such device
Dec 31 18:34:28 heaven systemd-homed[766]: Got notification that all sessions of user mploppy ended, deactivating automatically.


Steps to reproduce:

* Create a homed user.
* Update to systemd v250.
* Reboot
* Try to log in.

Again, downgrading to v249 makes everything work again.
This task depends upon

Closed by  Toolybird (Toolybird)
Saturday, 15 April 2023, 22:45 GMT
Reason for closing:  Upstream
Additional comments about closing:  We can revisit if upstream ever get around to fixing. At least there is a workaround mentioned in the upstream ticket.
Comment by ned (ned) - Saturday, 01 January 2022, 04:21 GMT
as you can see the problem is in loop0. Why did it appear and how do you boot the system?
Comment by Gael (Mploppy) - Monday, 03 January 2022, 17:10 GMT
> as you can see the problem is in loop0

Yes and how I get there determines whether or not this is a bug.

> Why did it appear

$ sudo homectl activate mploppy

Using gdm with pam does the exact same thing (i.e. I see the same exact thing in the logs besides time stamps and PIDs).

> and how do you boot the system?

With systemd 249,

1. I push the power button
2. I enter my user name and password in GDM (for whatever reason GDM does not remember my systemd-homed username)
3. Everything gets unlocked and I can transparently use my home area.

With systemd 250,

1. I push the power button
2. I enter my user name and password in GDM (for whatever reason GDM does not remember my systemd-homed username)
3. Nothing gets unlocked and I get those entries in the log.

After downgrade (pacman -U /var/cache/pacman/pkg/systemd*249.7-2*.tar.zst) and reboot:

1. I push the power button
2. I enter my user name and password in GDM (for whatever reason GDM does not remember my systemd-homed username)
3. Everything gets unlocked and I can transparently use my home area.

(^ not trying to be offensive, just making sure you understand that absolutely nothing changed besides those 4 packages: if I upgrade again, nothing unlocks and log messages are back)


Packages that got downgraded (ls /var/cache/pacman/pkg/systemd*249.7-2*.tar.zst):

/var/cache/pacman/pkg/systemd-249.7-2-x86_64.pkg.tar.zst
/var/cache/pacman/pkg/systemd-libs-249.7-2-x86_64.pkg.tar.zst
/var/cache/pacman/pkg/systemd-resolvconf-249.7-2-x86_64.pkg.tar.zst
/var/cache/pacman/pkg/systemd-sysvcompat-249.7-2-x86_64.pkg.tar.zst


Now the funny part: I created a new user under systemd v250 and that new user works. It's only the one created in v249 that doesn't.

Something that might be worth noting: I skipped the updates between 249.7 and 250.4 (did not use that computer for 2 weeks). There might have been some migration things that I did not get.

In practice now I have migrated my old home area to a new one (no trouble manually mounting that loopback interface) but I would like to get reasonably sure this won't happen at every major systemd update.
Comment by Janis König (LeonardK) - Wednesday, 05 January 2022, 23:56 GMT
I'm having the same issue with the 249.7-2 -> 250.1-1 transition.
Comment by GreyXor (GreyXor) - Thursday, 06 January 2022, 16:03 GMT
I'm having the same issue.

workaround : Create my user space with v249 and then upgrade to v250
Comment by Janis König (LeonardK) - Tuesday, 11 January 2022, 20:31 GMT
The issue still persists with 250.2-2. @GreyXor what do you mean with "create user space"? Re-Create the systemd homed user?
Comment by Janis König (LeonardK) - Wednesday, 12 January 2022, 08:35 GMT
Additional information: A system setup last year on 2021-09-29 with systemd-294.4-1 with homed does not have the issue. Will test on the other systemd with SYSTEMD_LOG_LEVEL=debug soon, and also report the homed version where I set up the "faulty" .home
Comment by Janis König (LeonardK) - Wednesday, 12 January 2022, 19:16 GMT
My non-working system sadly only has logs back to March last year and my faulty home was created before that. I've also attached a debug log when activating the home. I spent quite some time debugging but I can't really figure it out.
Comment by GreyXor (GreyXor) - Friday, 14 January 2022, 00:09 GMT
@LeonardK yes, with "create user space" i mean `homectl create greyxor`

I just tried on a freshly new arch and same error.

After Arch Linux installation I had to first downgrade to 249, launch my `homectl create greyxor` and only after that I could upgrade to 250 and use my system normally
Comment by Janis König (LeonardK) - Friday, 14 January 2022, 10:09 GMT
@GreyXor ah, so (re-)creating the home and copying all data. hmm.

Do you happen to know which systemd version you had when you ran `homectl create` the first time? I.e., what was the fresh archlinux installations' version? Since I can create a home with 250.2-2 and activate it completely fine.
Comment by GreyXor (GreyXor) - Friday, 14 January 2022, 10:24 GMT
@LeonardK i don't "(re-)creating the home"

From a fresh Arch Linux installation i only have the root user on it. then I downgrade the `systemd` package to version 249.7-2 (i choose this one because is the last stable before 250), create the home with `homectl create greyxor` and do a pacman -Syu to update systemd. and that's it, on reboot everything works normally. so I execute the `homectl create greyxor` command only once in the whole process.

And I use exactly this version : https://archive.archlinux.org/packages/s/systemd/systemd-249.7-2-x86_64.pkg.tar.zst

Tell me if it is not clear I will gladly answer your questions
Comment by Gael (Mploppy) - Friday, 14 January 2022, 14:08 GMT
Might be related, might be unrelated (given how systemd complains about updating sectors) but I can't resize my home image. Systemd is just saying "Couldn't change image size."... This is for a home area created with the latest systemd-homed.

This might be unrelated but since v250 introduced a lot of automatic resizing logic the whole thing might be related to a single bug.
Comment by Gael (Mploppy) - Friday, 14 January 2022, 15:42 GMT
Ok, so, again, may or may not be related...

By default, on XFS at least, systemd-homed allocates the whole disk sparsely using the .home file.

So if you type

$ ls -hals

You should get a capacity on the right that corresponds to how much space the home file is actually taking and on that same line on the left, how much space has been (sparsely) pre-allocated.

It turns out, after login in and out that the sparse allocation took almost all the disk.

When trying to resize that same home area, systemd-homed using the (sparse) pre-allocated size and says it cannot actually allocate anything because the disk is full.

I'm going to open a bug report upstream on this specific issue.
Comment by Gael (Mploppy) - Friday, 14 January 2022, 16:17 GMT
@LeonardK my experience has been the reverse: the user created under v249.7 does not work while the one created under v250.1 does...
Comment by Janis König (LeonardK) - Saturday, 22 January 2022, 15:57 GMT
@Geal, that's the same for me: "Since I can create a home with 250.2-2 and activate it completely fine." == Interestingly @GreyXor needs to create their home in 249. For me I can't upgrade anymore to any recent systemd version.
Comment by Jukka Palko (jpalko) - Wednesday, 26 January 2022, 09:01 GMT
I've done a completely fresh install with newest live iso on a KVM machine that has two 20G drives made into a RAID1 array to use as the home disk and I can't activate the user home via:
[root@arch-homed ~]# homectl activate jpalko
🔐 Please enter password for user jpalko: **************
Operation on home jpalko failed: Failed to execute operation: Invalid argument
This results in the following log events shown in my pastebin: https://pastebin.com/BnV9iX78

User was created using the command:
homectl create jpalko -c "Jukka Palko" -G wheel,lp,network,scanner,power --shell=/bin/zsh --storage=luks --image-path=/dev/md/home --fs-type=btrfs

I can however mount the home directory by executing:
[root@arch-homed ~]# cryptsetup open /dev/md/home1 home-jpalko
Enter passphrase for /dev/md/home1:
[root@arch-homed ~]# mount -o subvol=jpalko /dev/mapper/home-jpalko /mnt/
[root@arch-homed ~]# ls -larth /mnt/
total 32K
-rw-r--r-- 1 nobody nobody 141 Jan 8 20:31 .bashrc
-rw-r--r-- 1 nobody nobody 57 Jan 8 20:31 .bash_profile
-rw-r--r-- 1 nobody nobody 21 Jan 8 20:31 .bash_logout
drwxr-xr-x 1 root root 142 Jan 26 10:41 ..
-rw------- 1 nobody nobody 831 Jan 26 10:49 .identity
drwx------ 1 nobody nobody 82 Jan 26 10:49 .
Comment by GreyXor (GreyXor) - Tuesday, 14 June 2022, 13:03 GMT
I opened a bug on systemd upstream https://github.com/systemd/systemd/issues/23740
Comment by soloturn (soloturn) - Wednesday, 12 April 2023, 09:35 GMT
would you be so kind to lower the priority from "critical" or close it?

Loading...