udevd stop my HDD from spinning down

[zhangyoufu]

systemd version the issue has been seen with

255

Used distribution

Arch Linux

Linux kernel version used

6.8.9-arch1-2

CPU architectures issue was seen on

None

Component

systemd-udevd

Expected behaviour you didn't see

I could spin-down my SAS HDD and then remove it safely.

Unexpected behaviour you saw

After spin-down my SAS HDD, it starts spinning again immediately.

Steps to reproduce the problem

# sg_start --stop /dev/sdd

then dmesg shows

[Sun May 12 12:08:27 2024] sd 12:0:0:0: [sdd] Spinning up disk...
[Sun May 12 12:08:28 2024] ...........ready

The Spinning up disk... message comes from kernel.
The call stack is sd_open -> sd_revalidate_disk -> sd_spinup_disk.
It's systemd-udevd who is triggering this.

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

May 12 12:08:27 nas systemd-udevd[282449]: sdd: Received inotify event for /dev/sdd.
May 12 12:08:38 nas systemd-udevd[282449]: sdd: device is closed, synthesising 'change' on /sys/devices/pci0000:00/0000:00:02.1/0000:01:00.0/0000:02:08.0/0000:05:00.0/0000:06:00.0/0000:07:00.0/host12/port-12:0/end_device-12:0/target12:0:0/12:0:0:0/block/sdd
May 12 12:08:38 nas systemd-udevd[282449]: sdd: Device is queued (SEQNUM=8347, ACTION=change)
May 12 12:08:38 nas systemd-udevd[282449]: sdd: Device ready for processing (SEQNUM=8347, ACTION=change)
May 12 12:08:38 nas systemd-udevd[282449]: Successfully forked off '(udev-worker)' as PID 282458.
May 12 12:08:38 nas systemd-udevd[282449]: sdd: Worker [282458] is forked for processing SEQNUM=8347.
May 12 12:08:38 nas (udev-worker)[282458]: sdd: Processing device (SEQNUM=8347, ACTION=change)
May 12 12:08:38 nas (udev-worker)[282458]: sdd: Removing watch handle 7.
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/60-persistent-storage.rules:75 Importing properties from results of 'scsi_id --export --allowlisted -d /dev/sdd'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: Starting 'scsi_id --export --allowlisted -d /dev/sdd'
May 12 12:08:38 nas (udev-worker)[282458]: Successfully forked off '(spawn)' as PID 282459.
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_SCSI=1'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_VENDOR=WDC'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_VENDOR_ENC=WDC\x20\x20\x20\x20\x20'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_MODEL=WUH721818AL4206'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_MODEL_ENC=WUH721818AL4206\x20'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_REVISION=H2A0'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_TYPE=disk'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_SERIAL=REDACTED'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_SERIAL_SHORT=REDACTED'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_WWN=REDACTED'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_WWN_WITH_EXTENSION=REDACTED'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: 'scsi_id --export --allowlisted -d /dev/sdd'(out) 'ID_SCSI_SERIAL=REDACTED        '
May 12 12:08:38 nas (udev-worker)[282458]: sdd: Process 'scsi_id --export --allowlisted -d /dev/sdd' succeeded.
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/60-persistent-storage.rules:78 Added SYMLINK 'disk/by-id/scsi-REDACTED'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/60-persistent-storage.rules:110 Importing properties from results of builtin command 'path_id'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/60-persistent-storage.rules:114 Added SYMLINK 'disk/by-path/pci-0000:07:00.0-sas-phy0-lun-0'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/60-persistent-storage.rules:133 Importing properties from results of builtin command 'blkid'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: Probe /dev/sdd with raid and offset=0
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/60-persistent-storage.rules:138 Added SYMLINK 'disk/by-uuid/REDACTED'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/60-persistent-storage.rules:142 Added SYMLINK 'disk/by-id/REDACTED'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/60-persistent-storage.rules:151 Added SYMLINK 'disk/by-diskseq/5'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/90-iocost.rules:18 Importing properties from results of builtin command 'hwdb 'block::name:WUH721818AL4206:fwrev:H2A0:''
May 12 12:08:38 nas (udev-worker)[282458]: sdd: No entry found from hwdb.
May 12 12:08:38 nas (udev-worker)[282458]: sdd: /usr/lib/udev/rules.d/90-iocost.rules:18 Failed to run builtin 'hwdb 'block::name:WUH721818AL4206:fwrev:H2A0:'': No data available
May 12 12:08:38 nas (udev-worker)[282458]: sdd: Successfully created symlink '/dev/block/8:48' to '/dev/sdd'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: sd-device: Created db file '/run/udev/data/b8:48' for '/devices/pci0000:00/0000:00:02.1/0000:01:00.0/0000:02:08.0/0000:05:00.0/0000:06:00.0/0000:07:00.0/host12/port-12:0/end_device-12:0/target12:0:0/12:0:0:0/block/sdd'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: Adding watch on '/dev/sdd'
May 12 12:08:38 nas (udev-worker)[282458]: sdd: Device processed (SEQNUM=8347, ACTION=change)
May 12 12:08:38 nas (udev-worker)[282458]: sdd: sd-device-monitor(worker): Passed 1279 byte to netlink monitor.
May 12 12:08:38 nas systemd-udevd[282449]: No events are queued, removing /run/udev/queue.
May 12 12:08:41 nas systemd-udevd[282449]: Cleanup idle workers
May 12 12:08:41 nas systemd-udevd[282449]: Worker [282458] exited.
May 12 12:08:45 nas systemd-udevd[282449]: Cleanup idle workers

[poettering]

These lines are relevant:

May 12 12:08:27 nas systemd-udevd[282449]: sdd: Received inotify event for /dev/sdd.
May 12 12:08:38 nas systemd-udevd[282449]: sdd: device is closed, synthesising 'change' on /sys/devices/pci0000:00/0000:00:02.1/0000:01:00.0/0000:02:08.0/0000:05:00.0/0000:06:00.0/0000:07:00.0/host12/port-12:0/end_device-12:0/target12:0:0/12:0:0:0/block/sdd

So udev watches block devices via inotify for IN_CLOSE_WRITE events: i.e. whenever a block device that was opened by userspace for writing is closed, we'll retrigger the device so that the partition table is reread and similar things.

hence, figure out what tool is responsible for opening the block device writable.

udev itself never opens a block device writable, it just probes it in read-only mode. Hence it must be some other component of your OS. Once you fix that, then udev won't do a thing anymore either.

Closing, since this isn't a systemd problem, but some other tool is triggering this.

[zhangyoufu]

This device is not mounted, and this is a headless server with no such userspace program which would open the block device in write mode (except sg_start itself).

strace shows that sg_start opens the HDD in read-write mode by default. After sg_start closes the fd, systemd-udevd rechecks the partition table which triggers unexpected spin-up.

Fortunately, sg_start has an option --readonly, -r which opens the block device in read-only mode. But still, the interaction between sg_start and systemd-udevd worth some documentation.

I opened an issue in sg3_utils asking if it's possible to make sg_start read-only by default.

[mwilck]

Can you check which command run by udev actually causes the call to sd_revalidate_disk? Is it the scsi_id call?

Fortunately, sg_start has an option --readonly, -r which opens the block device in read-only mode.

Right. Looking at it this way, runningn sg_start --stop without --readonly may be considered a user error. Note that the "nuisance spin-up" is actually mentioned in the sg_start man page.

But still, the interaction between sg_start and systemd-udevd worth some documentation.

udevd's close-after-write behavior is documented, although not very prominently. Search for watch in udev(7). If you don't want this, you can set OPTIONS:="nowatch" in a custom udev rule.

This is not the only use case in which udev's watch mechanism is causing unexpected effects. But there are only very few reports of this kind, so it doesn't seem to be a big problem for most users. OTOH, it makes sure that the OS notices partition table changes, which is a nice feature that would be thoroughly missed by users if it didn't exist.

[zhangyoufu]

Can you check which command run by udev actually causes the call to sd_revalidate_disk? Is it the scsi_id call?

Last time I checked via kernel ftrace, userland process was systemd-udevd. Double checked by commenting out scsi_id line in udev rule file, restart systemd-udevd, and execute sg_start --stop, the issue still exists.

[yuwata]

Yeah, we should check if the disk is stopped before running scsi_id or blkid. But how?

[zhangyoufu]

I disagree that we should change the behavior of ata_id / scsi_id / blkid when the disk is stopped. I am not aware of reliable ways to detect disk spinning status.

IMHO nothing could be done on systemd-udevd side for this issue, as long as we still want to monitor partition table change, using inotify IN_CLOSE_WRITE event.

I'm fine with the workaround sg_start --readonly sending ioctl via read-only fd. In Linux kernel, START_STOP SCSI command is explicitly allowed on read-only fds.

[mwilck]

Last time I checked via kernel ftrace, userland process was systemd-udevd.

systemd-udevd opens the device in the worker_lock_whole_disk() code path. Maybe that's already sufficient for the kernel to try to revalidate it.