You are not logged in.

#1 2019-01-09 08:02:17

Kotrfa
Member
Registered: 2012-10-25
Posts: 162

Boot stuck on systemd 240 - A start job is running for device

Hi fellow Archers.

Yesterday, I updated my Arch system to the latest as I do every approx 3 days and stumbled upon a weird issue. When I wanted to turn off the PC after the upgrade, it hanged for 2min1s on a job with something like (didn't take the picture, unfortunately, but there wasn't info about what the job is, just that it's root user related)

A stop job is running for Session ... for user ...

and then it shutdown fine and it doesn't show up on consequent shutdowns/reboots. Looking at the journal, I found:


Jan 07 23:35:24 think460s systemd[1]: Unmounting /home/dan...
Jan 07 23:35:24 think460s systemd[1256]: Stopping Sound Service...
Jan 07 23:35:24 think460s systemd[1256]: Stopping Virtual filesystem service - disk device monitor...
Jan 07 23:35:24 think460s systemd[1256]: Stopping D-Bus User Message Bus...
Jan 07 23:35:24 think460s systemd[1256]: Stopping Accessibility services bus...
Jan 07 23:35:24 think460s audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck@dev-mapper-home\x2ddan\x2dencr comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jan 07 23:35:24 think460s umount[13213]: umount: /home/dan: target is busy.
Jan 07 23:35:24 think460s systemd[1256]: Stopping Virtual filesystem service...
Jan 07 23:35:24 think460s systemd[1256]: Stopped target Default.
Jan 07 23:35:24 think460s systemd[1]: home-dan.mount: Mount process exited, code=exited status=32
Jan 07 23:35:24 think460s systemd[1]: Failed unmounting /home/dan.
Jan 07 23:35:24 think460s systemd[1]: Stopped File System Check on /dev/mapper/home-dan-encr.
Jan 07 23:35:24 think460s systemd[1]: Unmounted /run/user/1000/gvfs.

When I booted my laptop (Thinkpad T460s) the next morning though, I got a following A start job is running for dev-mapper-homex2ddanx2dencr for 1m30s and then it timed out. This is my home partition encrypted via dmcrypt (which has been working fine for several months just fine). I can't say for sure these two are related, but it's very likely. It seems like there was something wrong during the last shutdown and now it has some issues with fscheck (which seems to go fine, just does not notify systemd correctly - the unit it says success, see below).

relevant part of the systemctl start boot log:

Jan 09 08:46:29 think460s systemd[1]: dev-mapper-home\x2ddan\x2dencr.device: Job dev-mapper-home\x2ddan\x2dencr.device/start timed out.
Jan 09 08:46:29 think460s systemd[1]: Timed out waiting for device /dev/mapper/home-dan-encr.
Jan 09 08:46:29 think460s systemd[1]: Dependency failed for /home/dan.
Jan 09 08:46:29 think460s systemd[1]: home-dan.mount: Job home-dan.mount/start failed with result 'dependency'.
Jan 09 08:46:29 think460s systemd[1]: Dependency failed for File System Check on /dev/mapper/home-dan-encr.
Jan 09 08:46:29 think460s systemd[1]: systemd-fsck@dev-mapper-home\x2ddan\x2dencr.service: Job systemd-fsck@dev-mapper-home\x2ddan\x2dencr.service/start failed with result 'dependency'.
Jan 09 08:46:29 think460s systemd[1]: dev-mapper-home\x2ddan\x2dencr.device: Job dev-mapper-home\x2ddan\x2dencr.device/start failed with result 'timeout'.
Jan 09 08:46:29 think460s systemd[1]: Reached target Local File Systems.

... few lines below...
Jan 09 08:46:40 think460s kernel: BTRFS: device fsid 83518ae3-55f8-48b2-abc6-39ffe70d0414 devid 1 transid 390001 /dev/dm-0
Jan 09 08:46:40 think460s systemd[1]: Found device /dev/mapper/home-dan-encr.
Jan 09 08:46:40 think460s systemd[1]: Starting File System Check on /dev/mapper/home-dan-encr...
Jan 09 08:46:40 think460s kernel: kauditd_printk_skb: 8 callbacks suppressed
Jan 09 08:46:40 think460s kernel: audit: type=1006 audit(1547020000.613:36): pid=943 uid=0 old-auid=4294967295 auid=1000 tty=tty1 old-ses=4294967295 ses=1 res=1
Jan 09 08:46:40 think460s login[943]: pam_unix(login:session): session opened for user dan by LOGIN(uid=0)
Jan 09 08:46:40 think460s systemd[1]: Created slice User Slice of UID 1000.
Jan 09 08:46:40 think460s systemd[1]: Starting User Runtime Directory /run/user/1000...
Jan 09 08:46:40 think460s systemd[1]: Started File System Check on /dev/mapper/home-dan-encr.
Jan 09 08:46:40 think460s audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck@dev-mapper-home\x2ddan\x2dencr comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

$ systemctl status systemd-fsck@dev-mapper-home\\x2ddan\\x2dencr.service

● systemd-fsck@dev-mapper-home\x2ddan\x2dencr.service - File System Check on /dev/mapper/home-dan-encr
   Loaded: loaded (/usr/lib/systemd/system/systemd-fsck@.service; static; vendor preset: disabled)
   Active: active (exited) since Wed 2019-01-09 08:46:40 CET; 9min ago
     Docs: man:systemd-fsck@.service(8)
  Process: 1239 ExecStart=/usr/lib/systemd/systemd-fsck /dev/mapper/home-dan-encr (code=exited, status=0/SUCCESS)
 Main PID: 1239 (code=exited, status=0/SUCCESS)

Jan 09 08:46:40 think460s systemd[1]: Starting File System Check on /dev/mapper/home-dan-encr...
Jan 09 08:46:40 think460s systemd[1]: Started File System Check on /dev/mapper/home-dan-encr.

The system boots in the end, but this is a nono thing I want to have. Additionally, the laptop keyboard just "randomly" stopped working 2/5 times when started to reboot under my regular user (dan), but I didn't reliably reproduced that (and works fine under root) and would rather solve the data issue first. Any ideas? Thanks a lot!

Last edited by Kotrfa (2019-01-12 16:17:01)

Offline

#2 2019-01-12 16:14:01

Kotrfa
Member
Registered: 2012-10-25
Posts: 162

Re: Boot stuck on systemd 240 - A start job is running for device

Anyone please? Here are those two suspected unit files generated by systemd-fstab. This problem occurred shortly after installing systemd 240.

$ systemctl cat home-dan.mount
# /run/systemd/generator/home-dan.mount
# Automatically generated by systemd-fstab-generator

[Unit]
SourcePath=/etc/fstab
Documentation=man:fstab(5) man:systemd-fstab-generator(8)
Requires=systemd-fsck@dev-mapper-home\x2ddan\x2dencr.service
After=systemd-fsck@dev-mapper-home\x2ddan\x2dencr.service

[Mount]
Where=/home/dan
What=/dev/mapper/home-dan-encr
Type=btrfs
Options=rw,noatime,nodiratime,ssd,space_cache,nofail,subvol=/,compress=lzo,subvolid=5


$ systemctl cat systemd-fsck@dev-mapper-home\x2ddan\x2dencr.service
# /usr/lib/systemd/system/systemd-fsck@.service
[Unit]
Description=File System Check on %f
Documentation=man:systemd-fsck@.service(8)
DefaultDependencies=no
BindsTo=%i.device
Conflicts=shutdown.target
After=%i.device systemd-fsck-root.service local-fs-pre.target
Before=systemd-quotacheck.service shutdown.target

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/usr/lib/systemd/systemd-fsck %f
TimeoutSec=0

$ cat /etc/fstab
...
# encrypted storage
/dev/mapper/home-dan-encr /home/dan btrfs	rw,noatime,nodiratime,ssd,space_cache,nofail,subvol=/,compress=lzo,subvolid=5	0 2
$ systemd-analyze critical-chain
...
                          └─local-fs.target @30.467s
                            └─home-dan.mount @41.792s +41ms
                              └─systemd-fsck@dev-mapper-home\x2ddan\x2dencr.service @41.779s +10ms
                                └─dev-mapper-home\x2ddan\x2dencr.device @41.778s

I was able to reduce the timeout to 10 sec instead of 90 secs by adding `,x-systemd.device-timeout=10` to the fstab options.

Last edited by Kotrfa (2019-01-12 16:47:24)

Offline

#3 2019-01-12 16:55:02

dmartins
Member
Registered: 2006-09-23
Posts: 331

Re: Boot stuck on systemd 240 - A start job is running for device

Could you post more complete boot logs to a pastebin (bpaste.net/gist.github.com/etc.)? I suspect if any problem is shown, it is a bit before what you shared already.


-- Dan

Offline

#4 2019-01-12 22:47:40

Kotrfa
Member
Registered: 2012-10-25
Posts: 162

Re: Boot stuck on systemd 240 - A start job is running for device

Offline

#5 2019-01-13 20:54:48

dmartins
Member
Registered: 2006-09-23
Posts: 331

Re: Boot stuck on systemd 240 - A start job is running for device

I can't find anything obvious there, but a new version of systemd has been moved to the core repo recently. Could you try updating your system?


-- Dan

Offline

Board footer

Powered by FluxBB