[systemd-devel] [systemd-219] Journal spamming by umount / high CPU usage

[Kai Krakow]

Lennart Poettering <lennart at poettering.net> schrieb:

>> To me it looks like the automounter tries to unmount unless there's still
>> references open in the filesystem. It does, however, no try to do this
>> after some timeout - which is fine. OTOH, this could be just an effect of
>> the mount point forcibly vanishing because the USB device
>> disconnected.
> 
> The kernel actually allows unmounting of mounts at any time, even if
> the backing device has vanished. (In fact, it particularly allows
> unmounting in that case...)

I had this case again. Since I wasn't booted with log_level=debug I simply 
turned the drive off, and now it gets intersting:

Apr 04 16:25:26 jupiter umount[3678]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter umount[3684]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter umount[3803]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter umount[3815]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter umount[3817]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter umount[3845]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter umount[3883]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter umount[3905]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter umount[3938]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter systemd-journal[436]: Suppressed 47447 messages from 
/user.slice/user-500.slice
Apr 04 16:25:26 jupiter umount[3941]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount 
process exited, code=exited status=1
Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount 
is bound to inactive unit. Stopping, too.
Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup...
Apr 04 16:25:26 jupiter umount[3943]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount 
process exited, code=exited status=1
Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount 
is bound to inactive unit. Stopping, too.
Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup...
Apr 04 16:25:26 jupiter umount[3945]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount 
process exited, code=exited status=1
Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount 
is bound to inactive unit. Stopping, too.
Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup...
Apr 04 16:25:26 jupiter umount[3947]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount 
process exited, code=exited status=1
Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount 
is bound to inactive unit. Stopping, too.
Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup...
Apr 04 16:25:26 jupiter umount[3948]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
[...repeated a few times...]
Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup...
Apr 04 16:25:26 jupiter umount[3959]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter umount[3961]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount 
process exited, code=exited status=1
Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount 
is bound to inactive unit. Stopping, too.
Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup...
Apr 04 16:25:26 jupiter umount[3963]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount 
process exited, code=exited status=1
Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount 
is bound to inactive unit. Stopping, too.
[...]
Apr 04 16:25:26 jupiter systemd-journal[436]: Suppressed 11231 messages from 
/user.slice/user-500.slice
Apr 04 16:25:26 jupiter systemd[817]: Failed unmounting /mnt/private/usb-
backup.
Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount 
is bound to inactive unit. Stopping, too.
Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup...
Apr 04 16:25:26 jupiter umount[3971]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount 
process exited, code=exited status=1
Apr 04 16:25:26 jupiter systemd[817]: Failed unmounting /mnt/private/usb-
backup.
Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount 
is bound to inactive unit. Stopping, too.
Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup...
Apr 04 16:25:26 jupiter umount[3974]: umount: /mnt/private/usb-backup: 
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount 
process exited, code=exited status=1
[...]

> Suppressed 11231 messages from /user.slice/user-500.slice

Why from user-500.slice? Is some process of my user trying to unmount this 
thing? That actually makes no sense...

It finally stops with btrfs removing the mount point:

Apr 04 16:25:26 jupiter kernel: BTRFS: error (device sda1) in 
__btrfs_free_extent:5990: errno=-5 IO failure
Apr 04 16:25:26 jupiter kernel: BTRFS info (device sda1): forced readonly
Apr 04 16:25:26 jupiter kernel: BTRFS: error (device sda1) in 
btrfs_run_delayed_refs:2792: errno=-5 IO failure
Apr 04 16:25:27 jupiter kernel: BTRFS warning (device sda1): Skipping commit 
of aborted transaction.
Apr 04 16:25:27 jupiter kernel: BTRFS: error (device sda1) in 
cleanup_transaction:1670: errno=-5 IO failure
Apr 04 16:25:27 jupiter kernel: BTRFS error (device sda1): commit super ret 
-5
Apr 04 16:25:26 jupiter systemd[1]: Unmounted /mnt/private/usb-backup.
Apr 04 16:25:27 jupiter systemd-udevd[470]: error opening USB device 
'descriptors' file

>> Maybe this is by kernel design? The filesystem forced itself read-only
>> (due to IO errors to an offlined/disconnected device), then went offline.
>> The kernel probably umounted it, and I believe that now another manual
>> umount results in EPERM, tho I cannot test that now. I can test it this
>> evening if it is of interested. I could also test other ideas to debug if
>> you instruct me.
> 
> I am pretty sure there's something weird going on here. Any chance you
> can boot with systemd.log_level=debug on the kernel cmdline, then
> reproduce the issue and paste the output this generates here?

I currently believe this is not a systemd bug per se...

-- 
Replies to list only preferred.