[systemd-homed] On shutdown, homed resizes until it gets killed

[nils-werner]

systemd version the issue has been seen with

systemd 250 (250.4-2-arch)

Used distribution

Arch Linux

Linux kernel version used (uname -a)

5.16.16-zen1-1-zen

CPU architecture issue was seen on

Intel 64bit

Expected behaviour you didn't see

Home Activation Service shuts down in time

Unexpected behaviour you saw

Home Activation Service halts shutdown until it gets killed

Steps to reproduce the problem

Unknown

Additional program output to the terminal or log subsystem illustrating the issue

Output of sudo journalctl -b-1, with unrelated lines removed

Mär 29 17:21:07 nils-desktop systemd[1]: Stopping Home Area Activation...
Mär 29 17:21:07 nils-desktop systemd-homed[513]: Automatically deactivating home of user nils.
Mär 29 17:21:09 nils-desktop systemd-homework[32694]: Discarded unused 153.2G.
Mär 29 17:21:10 nils-desktop systemd-homework[32694]: Syncing completed.
Mär 29 17:21:10 nils-desktop systemd-homework[32694]: Discovered used LUKS device /dev/mapper/home-nils, and validated password.
Mär 29 17:21:11 nils-desktop systemd-homework[32694]: Successfully re-activated LUKS device.
Mär 29 17:21:11 nils-desktop systemd-homework[32694]: Discovered used loopback device /dev/loop0.
Mär 29 17:21:11 nils-desktop systemd-homework[32694]: offset = 1048576, size = 425047027712, image = 425048920064
Mär 29 17:21:13 nils-desktop systemd-homework[32694]: Ready to resize image size 395.8G → 242.8G, partition size 395.8G → 242.8G, file system size 395.8G → 242.8G.
Mär 29 17:21:13 nils-desktop systemd-homework[32694]: Allocated additional 153.2G.
Mär 29 17:21:13 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 260949671936 flags metadata|dup
Mär 29 17:21:14 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:21:33 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 259875930112 flags data
Mär 29 17:21:39 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:21:56 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 259875930112 flags data
Mär 29 17:21:57 nils-desktop systemd-homed[513]: Rebalancing complete.
Mär 29 17:22:01 nils-desktop kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-nils (devid 1) from 425030250496 to 342888390656
Mär 29 17:22:01 nils-desktop kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-nils (devid 1) from 342888390656 to 301817462784
Mär 29 17:22:01 nils-desktop kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-nils (devid 1) from 301817462784 to 281281998848
Mär 29 17:22:02 nils-desktop kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-nils (devid 1) from 281281998848 to 271014264832
Mär 29 17:22:02 nils-desktop kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-nils (devid 1) from 271014264832 to 265880399872
Mär 29 17:22:02 nils-desktop kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-nils (devid 1) from 265880399872 to 263313465344
Mär 29 17:22:02 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:22:19 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:22:36 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:22:37 nils-desktop systemd[1]: systemd-homed-activate.service: Stopping timed out. Terminating.
Mär 29 17:22:37 nils-desktop systemd[1]: systemd-homed-activate.service: Control process exited, code=killed, status=15/TERM
Mär 29 17:22:37 nils-desktop systemd[1]: systemd-homed-activate.service: Failed with result 'timeout'.
Mär 29 17:22:37 nils-desktop systemd[1]: Stopped Home Area Activation.
Mär 29 17:22:37 nils-desktop audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-homed-activate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Mär 29 17:22:37 nils-desktop systemd[1]: Stopping Home Area Manager...
Mär 29 17:22:37 nils-desktop systemd-homed[513]: Worker process for home nils is still running while exiting. Waiting for it to finish.
Mär 29 17:22:37 nils-desktop kernel: kauditd_printk_skb: 20 callbacks suppressed
Mär 29 17:22:37 nils-desktop kernel: audit: type=1131 audit(1648567357.129:225): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-homed-activate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Mär 29 17:22:52 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:23:09 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:23:25 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:23:42 nils-desktop kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-nils (devid 1) from 263313465344 to 263153029120
Mär 29 17:23:42 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:23:59 nils-desktop kernel: BTRFS info (device dm-0): relocating block group 258802188288 flags data
Mär 29 17:24:07 nils-desktop systemd[1]: systemd-homed.service: State 'stop-sigterm' timed out. Killing.
Mär 29 17:24:07 nils-desktop systemd[1]: systemd-homed.service: Killing process 513 (systemd-homed) with signal SIGKILL.
Mär 29 17:24:07 nils-desktop systemd[1]: systemd-homed.service: Killing process 32694 (systemd-homewor) with signal SIGKILL.
Mär 29 17:24:07 nils-desktop systemd[1]: systemd-homed.service: Main process exited, code=killed, status=9/KILL
Mär 29 17:24:07 nils-desktop systemd[1]: systemd-homed.service: Killing process 32694 (systemd-homewor) with signal SIGKILL.
Mär 29 17:24:07 nils-desktop systemd[1]: systemd-homed.service: Failed with result 'timeout'.
Mär 29 17:24:07 nils-desktop systemd[1]: systemd-homed.service: Unit process 32694 (systemd-homewor) remains running after unit stopped.
Mär 29 17:24:07 nils-desktop systemd[1]: Stopped Home Area Manager.

Output of journalctl -ru systemd-homed-activate.service

Mär 29 17:22:37 nils-desktop systemd[1]: Stopped Home Area Activation.
Mär 29 17:22:37 nils-desktop systemd[1]: systemd-homed-activate.service: Failed with result 'timeout'.
Mär 29 17:22:37 nils-desktop systemd[1]: systemd-homed-activate.service: Control process exited, code=killed, status=15/TERM
Mär 29 17:22:37 nils-desktop systemd[1]: systemd-homed-activate.service: Stopping timed out. Terminating.
Mär 29 17:21:07 nils-desktop systemd[1]: Stopping Home Area Activation...
Mär 29 16:52:01 nils-desktop systemd[1]: Finished Home Area Activation.

[pryre]

I think I am seeing the same issue, logs for additional information if it will help:

Mar 28 21:57:28 ren systemd[1]: Stopping Home Area Activation...
Mar 28 21:57:28 ren systemd[1]: Stopping Network Name Resolution...
Mar 28 21:57:28 ren kernel: wlan0: deauthenticating from d4:6e:0e:36:3f:8c by local choice (Reason: 3=DEAUTH_LEAVING)
Mar 28 21:57:28 ren systemd-homed[625]: Automatically deactivating home of user pryre.
Mar 28 21:57:28 ren systemd-networkd[459]: wlan0: Link DOWN
Mar 28 21:57:28 ren systemd-networkd[459]: wlan0: Lost carrier
Mar 28 21:57:28 ren systemd[1]: systemd-resolved.service: Deactivated successfully.
Mar 28 21:57:28 ren systemd[1]: Stopped Network Name Resolution.
Mar 28 21:57:28 ren audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-resolved comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 28 21:57:28 ren systemd[1]: Stopping Network Configuration...
Mar 28 21:57:28 ren audit: BPF prog-id=0 op=UNLOAD
Mar 28 21:57:28 ren systemd-networkd[459]: bond0: DHCP lease lost
Mar 28 21:57:28 ren systemd-timesyncd[606]: No network connectivity, watching for changes.
Mar 28 21:57:28 ren systemd-networkd[459]: bond0: DHCPv6 lease lost
Mar 28 21:57:28 ren systemd[1]: systemd-networkd.service: Deactivated successfully.
Mar 28 21:57:28 ren systemd[1]: Stopped Network Configuration.
Mar 28 21:57:28 ren audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-networkd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 28 21:57:28 ren systemd[1]: systemd-networkd.service: Consumed 1.027s CPU time.
Mar 28 21:57:28 ren audit: BPF prog-id=0 op=UNLOAD
Mar 28 21:57:28 ren systemd[1]: systemd-random-seed.service: Deactivated successfully.
Mar 28 21:57:28 ren systemd[1]: Stopped Load/Save Random Seed.
Mar 28 21:57:28 ren audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-random-seed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 28 21:57:28 ren kernel: bond0: (slave wlan0): link status definitely down, disabling slave
Mar 28 21:57:28 ren kernel: bond0: now running without any active interface!
Mar 28 21:57:28 ren systemd-homework[19249]: Discarded unused 26.5G.
Mar 28 21:57:28 ren systemd-homework[19249]: Syncing completed.
Mar 28 21:57:29 ren iwd[617]: Removing scan context for wdev 3
Mar 28 21:57:29 ren iwd[617]: D-Bus disconnected, quitting...
Mar 28 21:57:29 ren systemd[1]: iwd.service: Deactivated successfully.
Mar 28 21:57:29 ren systemd[1]: Stopped Wireless service.
Mar 28 21:57:29 ren audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=iwd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 28 21:57:29 ren audit: BPF prog-id=0 op=UNLOAD
Mar 28 21:57:29 ren kernel: bond0: (slave wlan0): Releasing backup interface
Mar 28 21:57:29 ren systemd-homework[19249]: Discovered used LUKS device /dev/mapper/home-pryre, and validated password.
Mar 28 21:57:29 ren systemd-homework[19249]: Successfully re-activated LUKS device.
Mar 28 21:57:29 ren systemd-homework[19249]: Discovered used loopback device /dev/loop0.
Mar 28 21:57:29 ren systemd-homework[19249]: offset = 1048576, size = 49018032128, image = 49019101184
Mar 28 21:57:29 ren systemd-homework[19249]: Ready to resize image size 45.6G → 19.1G, partition size 45.6G → 19.1G, file system size 45.6G → 19.0G.
Mar 28 21:57:30 ren systemd-homework[19249]: Allocated additional 26.4G.
Mar 28 21:57:30 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:57:42 ren kernel: BTRFS info (device dm-0): relocating block group 23083941888 flags data
Mar 28 21:57:47 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:57:56 ren kernel: BTRFS info (device dm-0): relocating block group 23083941888 flags data
Mar 28 21:58:04 ren kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-pryre (devid 1) from 49001254912 to 34750382080
Mar 28 21:58:04 ren kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-pryre (devid 1) from 34750382080 to 27624943616
Mar 28 21:58:04 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:58:12 ren kernel: BTRFS info (device dm-0): relocating block group 23083941888 flags data
Mar 28 21:58:18 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:58:29 ren kernel: BTRFS info (device dm-0): relocating block group 23083941888 flags data
Mar 28 21:58:36 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:58:43 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:58:46 ren kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-pryre (devid 1) from 27624943616 to 26734264320
Mar 28 21:58:46 ren kernel: BTRFS info (device dm-0): resize device /dev/mapper/home-pryre (devid 1) from 26734264320 to 26288922624
Mar 28 21:58:46 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:58:49 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:58:53 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:58:57 ren kernel: BTRFS info (device dm-0): relocating block group 24426119168 flags data
Mar 28 21:58:58 ren systemd[1]: systemd-homed-activate.service: Stopping timed out. Terminating.
Mar 28 21:58:58 ren systemd[1]: systemd-homed-activate.service: Control process exited, code=killed, status=15/TERM
Mar 28 21:58:58 ren systemd[1]: systemd-homed-activate.service: Failed with result 'timeout'.
Mar 28 21:58:58 ren systemd[1]: Stopped Home Area Activation.
Mar 28 21:58:58 ren audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-homed-activate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Mar 28 21:58:58 ren systemd[1]: Stopping Home Area Manager...
Mar 28 21:58:58 ren systemd-homed[625]: Worker process for home pryre is still running while exiting. Waiting for it to finish.
Mar 28 21:58:58 ren kernel: kauditd_printk_skb: 22 callbacks suppressed
Mar 28 21:58:58 ren kernel: audit: type=1131 audit(1648468738.434:3742): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-homed-activate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'

[nils-werner]

After setting

# /etc/systemd/system/systemd-homed-activate.service.d/override.conf
[Service]
TimeoutStopSec=infinity

and

# /etc/systemd/system/systemd-homed.service.d/override.conf
[Service]
TimeoutStopSec=infinity
WatchdogSec=10min

the services shut down correctly and I see kernel log messages

Mär 30 19:40:13 nils-desktop systemd-homework[3304]: File system resizing from 395.8G to 245.0G completed.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Synchronized disk.
Mär 30 19:40:14 nils-desktop kernel: BTRFS info (device dm-0): devid 1 device path /dev/mapper/home-nils changed to /dev/dm-0 scanned by systemd-udevd (3348)
Mär 30 19:40:14 nils-desktop kernel: BTRFS info (device dm-0): devid 1 device path /dev/dm-0 changed to /dev/mapper/home-nils scanned by systemd-udevd (3348)
Mär 30 19:40:14 nils-desktop kernel: BTRFS info (device dm-0): devid 1 device path /dev/mapper/home-nils changed to /dev/dm-0 scanned by systemd-udevd (3348)
Mär 30 19:40:14 nils-desktop kernel: BTRFS info (device dm-0): devid 1 device path /dev/dm-0 changed to /dev/mapper/home-nils scanned by systemd-udevd (3348)
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: LUKS device shrinking completed.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Refreshing loop device size completed.
Mär 30 19:40:14 nils-desktop kernel: loop0: detected capacity change from 830174016 to 513910784
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Shrinking of image file completed.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Shrinking of partition completed.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Synchronized disk.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Resizing completed.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Image size is 245.0G, file system size is 245.0G, file system payload size is 245.0G, file system free is 2.2G.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Unmounting completed.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Discovered used LUKS device /dev/mapper/home-nils.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Device home-nils is not active.
Mär 30 19:40:14 nils-desktop systemd-homework[3304]: Everything completed.
Mär 30 19:40:14 nils-desktop systemd[1]: systemd-homed.service: Deactivated successfully.
Mär 30 19:40:14 nils-desktop systemd[1]: Stopped Home Area Manager.
Mär 30 19:40:14 nils-desktop systemd[1]: systemd-homed.service: Consumed 9.947s CPU time.

However upon the next shutdown, the same disk shrinking it taking place again, consuming the same amount of time again.