Среда: время опять чинить систему, поломанную systemd.
История простая: перезагрузился, перестали монтироваться по клику в Dolphin LUKS контейнеры.
Подкапотный udisksctl наглухо зависает.
Оказыватеся, cryptsetup никогда не завершается:
root@optiplex:/home/aidaho# cryptsetup luksOpen /dev/disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0\:0 armor --debug
# cryptsetup 2.1.0 processing "cryptsetup luksOpen /dev/disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0:0 armor --debug"
# Running command open.
# Locking memory.
# Installing SIGINT/SIGTERM handler.
# Unblocking interruption on signal.
# Allocating context for crypt device /dev/disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0:0.
# Trying to open and read device /dev/disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0:0 with direct-io.
# Initialising device-mapper backend library.
# Trying to load any crypt type from device /dev/disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0:0.
# Crypto backend (OpenSSL 1.1.1d 10 Sep 2019) initialized in cryptsetup library version 2.1.0.
# Detected kernel Linux 4.19.0-12-amd64 x86_64.
# PBKDF pbkdf2, hash sha256, time_ms 2000 (iterations 0), max_memory_kb 0, parallel_threads 0.
# Reading LUKS header of size 1024 from device /dev/disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0:0
# Key length 32, device size 9767541168 sectors, header size 2050 sectors.
# Activating volume armor using token -1.
# Interactive passphrase entry requested.
Enter passphrase for /dev/disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0:0:
# Activating volume armor [keyslot -1] using passphrase.
# dm version [ opencount flush ] [16384] (*1)
# dm versions [ opencount flush ] [16384] (*1)
# Detected dm-ioctl version 4.39.0.
# Detected dm-crypt version 1.18.1.
# Device-mapper backend running with UDEV support enabled.
# dm status armor [ opencount noflush ] [16384] (*1)
# Trying to open key slot 0 [ACTIVE_LAST].
# Reading key slot 0 area.
# Using userspace crypto wrapper to access keyslot area.
# dm versions [ opencount flush ] [16384] (*1)
# dm status armor [ opencount noflush ] [16384] (*1)
# Calculated device size is 9767538096 sectors (RW), offset 3072.
# DM-UUID is CRYPT-LUKS1-94bd2ae6fb3b4098802fda26255ed489-armor
# Udev cookie 0xd4d875e (semid 360450) created
# Udev cookie 0xd4d875e (semid 360450) incremented to 1
# Udev cookie 0xd4d875e (semid 360450) incremented to 2
# Udev cookie 0xd4d875e (semid 360450) assigned to CREATE task(0) with flags DISABLE_LIBRARY_FALLBACK (0x20)
# dm create armor CRYPT-LUKS1-94bd2ae6fb3b4098802fda26255ed489-armor [ opencount flush ] [16384] (*1)
# dm reload armor [ opencount flush securedata ] [16384] (*1)
# dm resume armor [ opencount flush securedata ] [16384] (*1)
# armor: Stacking NODE_ADD (253,1) 0:6 0660 [trust_udev]
# armor: Stacking NODE_READ_AHEAD 256 (flags=1)
# Udev cookie 0xd4d875e (semid 360450) decremented to 1
# Udev cookie 0xd4d875e (semid 360450) waiting for zero
Нужное правило udev вроде на месте:
root@optiplex:/home/aidaho# cat /lib/udev/rules.d/95-dm-notify.rules
# Copyright (C) 2009 Red Hat, Inc. All rights reserved.
#
# This file is part of LVM2.
# Udev rules for device-mapper devices.
#
# These rules are responsible for sending a notification to a process
# waiting for completion of udev rules. The process is identified by
# a cookie value sent within "change" and "remove" events (the cookie
# value is set before by that process for every action requested).
ENV{DM_COOKIE}=="?*", RUN+="/sbin/dmsetup udevcomplete $env{DM_COOKIE}"
И systemd рапортует, что выполнил его:
root@optiplex:/home/aidaho# journalctl -f | grep udev
Nov 18 09:37:43 optiplex systemd-udevd[14601]: sdb: Inotify event: 8 for /dev/sdb
Nov 18 09:37:43 optiplex systemd-udevd[14601]: Device '/dev/sdb' is closed, synthesising 'change'
Nov 18 09:37:43 optiplex systemd-udevd[14601]: 253:1: Device (SEQNUM=4776, ACTION=add) is queued
Nov 18 09:37:43 optiplex systemd-udevd[14601]: Validate module index
Nov 18 09:37:43 optiplex systemd-udevd[14601]: Check if link configuration needs reloading.
Nov 18 09:37:43 optiplex systemd-udevd[14601]: Successfully forked off 'n/a' as PID 13360.
Nov 18 09:37:43 optiplex systemd-udevd[14601]: 253:1: Worker [13360] is forked for processing SEQNUM=4776.
Nov 18 09:37:43 optiplex systemd-udevd[14601]: dm-1: Device (SEQNUM=4777, ACTION=add) is queued
Nov 18 09:37:43 optiplex systemd-udevd[14601]: Successfully forked off 'n/a' as PID 13361.
Nov 18 09:37:43 optiplex systemd-udevd[14601]: dm-1: Worker [13361] is forked for processing SEQNUM=4777.
Nov 18 09:37:43 optiplex systemd-udevd[13360]: 253:1: Processing device (SEQNUM=4776, ACTION=add)
Nov 18 09:37:43 optiplex systemd-udevd[14601]: sdb: Device (SEQNUM=4778, ACTION=change) is queued
Nov 18 09:37:43 optiplex systemd-udevd[13361]: dm-1: Processing device (SEQNUM=4777, ACTION=add)
Nov 18 09:37:43 optiplex systemd-udevd[14601]: Successfully forked off 'n/a' as PID 13362.
Nov 18 09:37:43 optiplex systemd-udevd[13360]: 253:1: Device (SEQNUM=4776, ACTION=add) processed
Nov 18 09:37:43 optiplex systemd-udevd[14601]: sdb: Worker [13362] is forked for processing SEQNUM=4778.
Nov 18 09:37:43 optiplex systemd-udevd[13360]: 253:1: sd-device-monitor: Passed 140 byte to netlink monitor
Nov 18 09:37:43 optiplex systemd-udevd[13361]: dm-1: GROUP 6 /lib/udev/rules.d/50-udev-default.rules:59
Nov 18 09:37:43 optiplex systemd-udevd[13361]: dm-1: Handling device node '/dev/dm-1', devnum=b253:1, mode=0660, uid=0, gid=6
Nov 18 09:37:43 optiplex systemd-udevd[13361]: dm-1: Setting permissions /dev/dm-1, 060660, uid=0, gid=6
Nov 18 09:37:43 optiplex systemd-udevd[13361]: dm-1: Creating symlink '/dev/block/253:1' to '../dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13361]: dm-1: sd-device: Created db file '/run/udev/data/b253:1' for '/devices/virtual/block/dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13361]: dm-1: Device (SEQNUM=4777, ACTION=add) processed
Nov 18 09:37:43 optiplex systemd-udevd[13361]: dm-1: sd-device-monitor: Passed 331 byte to netlink monitor
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Processing device (SEQNUM=4778, ACTION=change)
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Removing watch
Nov 18 09:37:43 optiplex systemd-udevd[14601]: dm-1: Device (SEQNUM=4779, ACTION=change) is queued
Nov 18 09:37:43 optiplex systemd-udevd[14601]: dm-1: sd-device-monitor: Passed 213 byte to netlink monitor
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: IMPORT 'ata_id --export /dev/sdb' /lib/udev/rules.d/60-persistent-storage.rules:46
Nov 18 09:37:43 optiplex systemd-udevd[13362]: Starting 'ata_id --export /dev/sdb'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: Successfully forked off '(spawn)' as PID 13363.
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Processing device (SEQNUM=4779, ACTION=change)
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: IMPORT '/sbin/dmsetup udevflags 6326110' /lib/udev/rules.d/55-dm.rules:52
Nov 18 09:37:43 optiplex systemd-udevd[13360]: Starting '/sbin/dmsetup udevflags 6326110'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: Successfully forked off '(spawn)' as PID 13364.
Nov 18 09:37:43 optiplex systemd-udevd[13360]: '/sbin/dmsetup udevflags 6326110'(out) 'DM_UDEV_DISABLE_LIBRARY_FALLBACK_FLAG='1''
Nov 18 09:37:43 optiplex systemd-udevd[13360]: '/sbin/dmsetup udevflags 6326110'(out) 'DM_UDEV_PRIMARY_SOURCE_FLAG='1''
Nov 18 09:37:43 optiplex systemd-udevd[13360]: Process '/sbin/dmsetup udevflags 6326110' succeeded.
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: LINK 'mapper/armor' /lib/udev/rules.d/55-dm.rules:136
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: LINK 'disk/by-id/dm-name-armor' /lib/udev/rules.d/60-persistent-storage-dm.rules:17
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: LINK 'disk/by-id/dm-uuid-CRYPT-LUKS1-94bd2ae6fb3b4098802fda26255ed489-armor' /lib/udev/rules.d/60-persistent-storage-dm.rules:18
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: IMPORT builtin 'blkid' /lib/udev/rules.d/60-persistent-storage-dm.rules:23
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Probe /dev/dm-1 with raid and offset=0
Nov 18 09:37:43 optiplex systemd-udevd[13362]: Process 'ata_id --export /dev/sdb' failed with exit code 2.
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: IMPORT builtin 'usb_id' /lib/udev/rules.d/60-persistent-storage.rules:49
Nov 18 09:37:43 optiplex systemd-udevd[13362]: 2-3.1.1:1.0: if_class:8 protocol:6
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: LINK 'disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0:0' /lib/udev/rules.d/60-persistent-storage.rules:54
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: IMPORT builtin 'path_id' /lib/udev/rules.d/60-persistent-storage.rules:78
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: LINK 'disk/by-path/pci-0000:00:14.0-usb-0:3.1.1:1.0-scsi-0:0:0:0' /lib/udev/rules.d/60-persistent-storage.rules:80
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: IMPORT builtin 'blkid' /lib/udev/rules.d/60-persistent-storage.rules:95
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Probe /dev/sdb with raid and offset=0
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: LINK 'disk/by-uuid/94bd2ae6-fb3b-4098-802f-da26255ed489' /lib/udev/rules.d/60-persistent-storage.rules:98
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: ATTR '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3/2-3.1/2-3.1.1/2-3.1.1:1.0/host4/target4:0:0/4:0:0:0/block/sdb/queue/scheduler' writing 'bfq' /etc/udev/rules.d/60-scheduler.rules:2
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: RUN '/etc/intelpwm' /etc/udev/rules.d/99-intel-pwm.rules:2
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Handling device node '/dev/sdb', devnum=b8:16, mode=0600, uid=0, gid=0
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Preserve already existing symlink '/dev/block/8:16' to '../sdb'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Found 'b8:16' claiming '/run/udev/links/\x2fdisk\x2fby-path\x2fpci-0000:00:14.0-usb-0:3.1.1:1.0-scsi-0:0:0:0'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Preserve already existing symlink '/dev/disk/by-path/pci-0000:00:14.0-usb-0:3.1.1:1.0-scsi-0:0:0:0' to '../../sdb'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Found 'b8:16' claiming '/run/udev/links/\x2fdisk\x2fby-uuid\x2f94bd2ae6-fb3b-4098-802f-da26255ed489'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Preserve already existing symlink '/dev/disk/by-uuid/94bd2ae6-fb3b-4098-802f-da26255ed489' to '../../sdb'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Found 'b8:16' claiming '/run/udev/links/\x2fdisk\x2fby-id\x2fusb-PHD_3.0_Silicon-Power_18008895038160000017-0:0'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Preserve already existing symlink '/dev/disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0:0' to '../../sdb'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: sd-device: Created db file '/run/udev/data/b8:16' for '/devices/pci0000:00/0000:00:14.0/usb2/2-3/2-3.1/2-3.1.1/2-3.1.1:1.0/host4/target4:0:0/4:0:0:0/block/sdb'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: Starting '/etc/intelpwm'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: Successfully forked off '(spawn)' as PID 13365.
Nov 18 09:37:43 optiplex systemd-udevd[13362]: Process '/etc/intelpwm' failed with exit code 1.
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Adding watch on '/dev/sdb'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: sd-device: Created db file '/run/udev/data/b8:16' for '/devices/pci0000:00/0000:00:14.0/usb2/2-3/2-3.1/2-3.1.1/2-3.1.1:1.0/host4/target4:0:0/4:0:0:0/block/sdb'
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: Device (SEQNUM=4778, ACTION=change) processed
Nov 18 09:37:43 optiplex systemd-udevd[13362]: sdb: sd-device-monitor: Passed 1132 byte to netlink monitor
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: LINK 'disk/by-uuid/8b3064bc-ae9d-49c5-8d85-2d68d15d3f69' /lib/udev/rules.d/60-persistent-storage-dm.rules:25
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: LINK 'disk/by-label/armor' /lib/udev/rules.d/60-persistent-storage-dm.rules:26
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: RUN 'btrfs ready /dev/mapper/$env{DM_NAME}' /lib/udev/rules.d/64-btrfs-dm.rules:8
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: IMPORT builtin 'btrfs' /lib/udev/rules.d/64-btrfs.rules:9
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: RUN '/bin/udevadm trigger -s block -p ID_BTRFS_READY=0' /lib/udev/rules.d/64-btrfs.rules:15
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: RUN '/sbin/dmsetup udevcomplete $env{DM_COOKIE}' /lib/udev/rules.d/95-dm-notify.rules:12
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: RUN '/etc/intelpwm' /etc/udev/rules.d/99-intel-pwm.rules:2
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Handling device node '/dev/dm-1', devnum=b253:1, mode=0600, uid=0, gid=0
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Preserve already existing symlink '/dev/block/253:1' to '../dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Creating symlink '/dev/disk/by-id/dm-name-armor' to '../../dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Creating symlink '/dev/disk/by-uuid/8b3064bc-ae9d-49c5-8d85-2d68d15d3f69' to '../../dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Creating symlink '/dev/mapper/armor' to '../dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Creating symlink '/dev/disk/by-label/armor' to '../../dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Creating symlink '/dev/disk/by-id/dm-uuid-CRYPT-LUKS1-94bd2ae6fb3b4098802fda26255ed489-armor' to '../../dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: sd-device: Created db file '/run/udev/data/b253:1' for '/devices/virtual/block/dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: Starting '/etc/intelpwm'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: Successfully forked off '(spawn)' as PID 13366.
Nov 18 09:37:43 optiplex systemd-udevd[13360]: Process '/etc/intelpwm' failed with exit code 1.
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Adding watch on '/dev/dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: sd-device: Created db file '/run/udev/data/b253:1' for '/devices/virtual/block/dm-1'
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: Device (SEQNUM=4779, ACTION=change) processed
Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: sd-device-monitor: Passed 955 byte to netlink monitor
Nov 18 09:37:46 optiplex systemd-udevd[14601]: Cleanup idle workers
Nov 18 09:37:46 optiplex systemd-udevd[13361]: Unload module index
Nov 18 09:37:46 optiplex systemd-udevd[13362]: Unload module index
Nov 18 09:37:46 optiplex systemd-udevd[13360]: Unload module index
Nov 18 09:37:46 optiplex systemd-udevd[13361]: Unloaded link configuration context.
Nov 18 09:37:46 optiplex systemd-udevd[13362]: Unloaded link configuration context.
Nov 18 09:37:46 optiplex systemd-udevd[13360]: Unloaded link configuration context.
Nov 18 09:37:46 optiplex systemd-udevd[14601]: Worker [13360] exited
Nov 18 09:37:46 optiplex systemd-udevd[14601]: Worker [13361] exited
Nov 18 09:37:46 optiplex systemd-udevd[14601]: Worker [13362] exited
(всё внимание на Nov 18 09:37:43 optiplex systemd-udevd[13360]: dm-1: RUN '/sbin/dmsetup udevcomplete $env{DM_COOKIE}' /lib/udev/rules.d/95-dm-notify.rules:12
)
Но если вручную скомандовать dmsetup udevcomplete 0xd4d875e
, то cryptsetup тут же отвисает:
# Udev cookie 0xd4d875e (semid 360450) destroyed
# armor: Skipping NODE_ADD (253,1) 0:6 0660 [trust_udev]
# armor: Processing NODE_READ_AHEAD 256 (flags=1)
# armor (253:1): read ahead is 256
# armor: retaining kernel read ahead of 256 (requested 256)
Key slot 0 unlocked.
# Releasing crypt device /dev/disk/by-id/usb-PHD_3.0_Silicon-Power_18008895038160000017-0:0 context.
# Releasing device-mapper backend.
# Unlocking memory.
Command successful.
Вроде додебажил проблему до сути, но дальше не знаю что делать.
systemd-udevd рапортует что всё делает, но на самом деле нет.