blktests icon indicating copy to clipboard operation
blktests copied to clipboard
verified publisher icon osandov

blktests zbd/012 failed due to the scsi-debug removal failed

Open yizhanglinux opened this issue 1 month ago • 4 comments 

# uname -r
6.18.0-0.rc4.251106gdc77806cf3b47.40.fc44.s390x
# rpm -qa systemd
systemd-258.2-1.fc44.s390x

# ./check zbd/012
zbd/012 (test requeuing of zoned writes and queue freezing)  [failed]
    runtime  24.375s  ...  67.864s
    --- tests/zbd/012.out	2025-11-11 04:31:42.888824468 +0000
    +++ /root/blktests/results/nodev/zbd/012.out.bad	2025-11-13 04:45:30.692247722 +0000
    @@ -1,6 +1,8 @@
     Running zbd/012
     1
     2
    +modprobe: FATAL: Module scsi_debug is in use.
    +Unloading scsi_debug failed
     4
     8
    ...
    (Run 'diff -u tests/zbd/012.out /root/blktests/results/nodev/zbd/012.out.bad' to see the entire diff)

# cat /root/blktests/results/nodev/zbd/012.out.bad
Running zbd/012
1
2
modprobe: FATAL: Module scsi_debug is in use.
Unloading scsi_debug failed
4
8
16
Test complete

# cat results/nodev/zbd/012.full
brw-rw----. 1 root disk 8, 0 Nov 13 04:44 /dev/sda
requeuing-and-queue-freezing-1: (g=0): rw=randwrite, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=io_uring, iodepth=1
fio-3.40
Starting 1 process

requeuing-and-queue-freezing-1: (groupid=0, jobs=1): err= 0: pid=5908: Thu Nov 13 04:44:46 2025
  write: IOPS=3, BW=14.3KiB/s (14.6kB/s)(88.0KiB/6170msec); 0 zone resets
    slat (usec): min=26, max=100, avg=38.45, stdev=14.91
    clat (msec): min=149, max=509, avg=280.38, stdev=99.02
     lat (msec): min=150, max=509, avg=280.42, stdev=99.02
    clat percentiles (msec):
     |  1.00th=[  150],  5.00th=[  155], 10.00th=[  180], 20.00th=[  192],
     | 30.00th=[  220], 40.00th=[  249], 50.00th=[  251], 60.00th=[  309],
     | 70.00th=[  321], 80.00th=[  359], 90.00th=[  380], 95.00th=[  489],
     | 99.00th=[  510], 99.50th=[  510], 99.90th=[  510], 99.95th=[  510],
     | 99.99th=[  510]
   bw (  KiB/s): min=    8, max=   24, per=98.16%, avg=14.00, stdev= 4.97, samples=12
   iops        : min=    2, max=    6, avg= 3.50, stdev= 1.24, samples=12
  lat (msec)   : 250=50.00%, 500=45.45%, 750=4.55%
  cpu          : usr=0.00%, sys=0.02%, ctx=27, majf=0, minf=12
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,22,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
  WRITE: bw=14.3KiB/s (14.6kB/s), 14.3KiB/s-14.3KiB/s (14.6kB/s-14.6kB/s), io=88.0KiB (90.1kB), run=6170-6170msec

Disk stats (read/write):
  sda: ios=20/21, sectors=2560/168, merge=0/0, ticks=2333/3423, in_queue=5756, util=77.79%

modprobe: FATAL: Module scsi_debug is in use.       -----------> The scsi-debug module removal failed after fio test when qd=1

requeuing-and-queue-freezing-2: (g=0): rw=randwrite, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=io_uring, iodepth=2
fio-3.40
Starting 1 process

requeuing-and-queue-freezing-2: (groupid=0, jobs=1): err= 0: pid=6039: Thu Nov 13 04:44:59 2025
  write: IOPS=6, BW=26.7KiB/s (27.3kB/s)(168KiB/6295msec); 0 zone resets
    slat (nsec): min=2000, max=64000, avg=37428.57, stdev=10858.61
    clat (msec): min=93, max=497, avg=293.70, stdev=77.06
     lat (msec): min=93, max=497, avg=293.74, stdev=77.05
    clat percentiles (msec):
     |  1.00th=[   94],  5.00th=[  101], 10.00th=[  194], 20.00th=[  300],
     | 30.00th=[  300], 40.00th=[  300], 50.00th=[  309], 60.00th=[  313],
     | 70.00th=[  321], 80.00th=[  321], 90.00th=[  351], 95.00th=[  359],
     | 99.00th=[  498], 99.50th=[  498], 99.90th=[  498], 99.95th=[  498],
     | 99.99th=[  498]
   bw (  KiB/s): min=   15, max=   32, per=97.42%, avg=26.58, stdev= 6.39, samples=12
   iops        : min=    3, max=    8, avg= 6.58, stdev= 1.73, samples=12
  lat (msec)   : 100=9.52%, 250=4.76%, 500=85.71%
  cpu          : usr=0.02%, sys=0.03%, ctx=79, majf=0, minf=12
  IO depths    : 1=2.4%, 2=97.6%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,42,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=2

Run status group 0 (all jobs):
  WRITE: bw=26.7KiB/s (27.3kB/s), 26.7KiB/s-26.7KiB/s (27.3kB/s-27.3kB/s), io=168KiB (172kB), run=6295-6295msec

Disk stats (read/write):
  sda: ios=14/41, sectors=1792/328, merge=0/0, ticks=1401/4279, in_queue=5679, util=92.67%
tests/zbd/012: line 72: kill: (5845) - No such process
brw-rw----. 1 root disk 8, 0 Nov 13 04:45 /dev/sda
requeuing-and-queue-freezing-4: (g=0): rw=randwrite, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=4
fio-3.40
Starting 1 process

requeuing-and-queue-freezing-4: (groupid=0, jobs=1): err= 0: pid=6092: Thu Nov 13 04:45:12 2025
  write: IOPS=150, BW=602KiB/s (616kB/s)(3632KiB/6037msec); 0 zone resets
    slat (nsec): min=0, max=91069k, avg=2164552.86, stdev=11578258.62
    clat (usec): min=5, max=168540, avg=24171.91, stdev=39768.14
     lat (usec): min=9, max=168540, avg=26336.47, stdev=40142.27
    clat percentiles (usec):
     |  1.00th=[     8],  5.00th=[    11], 10.00th=[    12], 20.00th=[    17],
     | 30.00th=[    20], 40.00th=[    23], 50.00th=[    30], 60.00th=[    49],
     | 70.00th=[ 36963], 80.00th=[ 60031], 90.00th=[ 96994], 95.00th=[109577],
     | 99.00th=[139461], 99.50th=[154141], 99.90th=[168821], 99.95th=[168821],
     | 99.99th=[168821]
   bw (  KiB/s): min=  360, max= 1576, per=100.00%, avg=602.67, stdev=317.71, samples=12
   iops        : min=   90, max=  394, avg=150.67, stdev=79.43, samples=12
  lat (usec)   : 10=3.74%, 20=27.31%, 50=28.96%, 100=6.06%, 250=0.33%
  lat (usec)   : 500=0.44%, 750=0.77%, 1000=0.66%
  lat (msec)   : 20=0.11%, 50=9.80%, 100=13.55%, 250=8.26%
  cpu          : usr=0.05%, sys=0.12%, ctx=523, majf=0, minf=13
  IO depths    : 1=0.1%, 2=0.2%, 4=99.7%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,908,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=4

Run status group 0 (all jobs):
  WRITE: bw=602KiB/s (616kB/s), 602KiB/s-602KiB/s (616kB/s-616kB/s), io=3632KiB (3719kB), run=6037-6037msec

Disk stats (read/write):
  sda: ios=20/873, sectors=2560/7176, merge=0/24, ticks=207/11495, in_queue=11703, util=65.44%
brw-rw----. 1 root disk 8, 0 Nov 13 04:45 /dev/sda
requeuing-and-queue-freezing-8: (g=0): rw=randwrite, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=8
fio-3.40
Starting 1 process

requeuing-and-queue-freezing-8: (groupid=0, jobs=1): err= 0: pid=6253: Thu Nov 13 04:45:22 2025
  write: IOPS=5826, BW=22.8MiB/s (23.9MB/s)(137MiB/6016msec); 4 zone resets
    slat (nsec): min=0, max=112951k, avg=69890.43, stdev=2213667.08
    clat (nsec): min=2000, max=132833k, avg=1180658.38, stdev=8816574.00
     lat (usec): min=6, max=132834, avg=1250.55, stdev=9082.35
    clat percentiles (usec):
     |  1.00th=[    12],  5.00th=[    21], 10.00th=[    23], 20.00th=[    28],
     | 30.00th=[    29], 40.00th=[    31], 50.00th=[    33], 60.00th=[    35],
     | 70.00th=[    38], 80.00th=[    43], 90.00th=[    50], 95.00th=[    62],
     | 99.00th=[ 39584], 99.50th=[ 80217], 99.90th=[110625], 99.95th=[110625],
     | 99.99th=[132645]
   bw (  KiB/s): min= 4910, max=64120, per=100.00%, avg=23343.83, stdev=18473.94, samples=12
   iops        : min= 1227, max=16030, avg=5835.92, stdev=4618.53, samples=12
  lat (usec)   : 4=0.03%, 10=0.35%, 20=4.02%, 50=85.16%, 100=7.85%
  lat (usec)   : 250=0.29%, 500=0.05%, 750=0.06%, 1000=0.02%
  lat (msec)   : 2=0.01%, 4=0.01%, 20=0.27%, 50=1.08%, 100=0.56%
  lat (msec)   : 250=0.26%
  cpu          : usr=0.50%, sys=1.71%, ctx=22412, majf=0, minf=13
  IO depths    : 1=0.1%, 2=0.1%, 4=0.3%, 8=99.5%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.1%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,35054,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=8

Run status group 0 (all jobs):
  WRITE: bw=22.8MiB/s (23.9MB/s), 22.8MiB/s-22.8MiB/s (23.9MB/s-23.9MB/s), io=137MiB (144MB), run=6016-6016msec

Disk stats (read/write):
  sda: ios=20/32633, sectors=2560/269200, merge=0/1023, ticks=0/13105, in_queue=13105, util=58.64%
brw-rw----. 1 root disk 8, 0 Nov 13 04:45 /dev/sda
requeuing-and-queue-freezing-16: (g=0): rw=randwrite, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=16
fio-3.40
Starting 1 process

requeuing-and-queue-freezing-16: (groupid=0, jobs=1): err= 0: pid=6390: Thu Nov 13 04:45:30 2025
  write: IOPS=32.3k, BW=126MiB/s (132MB/s)(761MiB/6035msec); 46 zone resets
    slat (nsec): min=0, max=117053k, avg=15000.12, stdev=907940.37
    clat (nsec): min=1000, max=129985k, avg=330817.21, stdev=4044894.60
     lat (usec): min=6, max=129986, avg=345.82, stdev=4144.97
    clat percentiles (usec):
     |  1.00th=[    29],  5.00th=[    43], 10.00th=[    51], 20.00th=[    61],
     | 30.00th=[    64], 40.00th=[    67], 50.00th=[    68], 60.00th=[    71],
     | 70.00th=[    79], 80.00th=[    86], 90.00th=[    99], 95.00th=[   111],
     | 99.00th=[   151], 99.50th=[ 19006], 99.90th=[ 79168], 99.95th=[ 87557],
     | 99.99th=[129500]
   bw (  KiB/s): min=31040, max=247144, per=100.00%, avg=129848.00, stdev=80239.72, samples=12
   iops        : min= 7760, max=61786, avg=32462.00, stdev=20059.93, samples=12
  lat (usec)   : 2=0.01%, 4=0.01%, 10=0.10%, 20=0.23%, 50=8.57%
  lat (usec)   : 100=81.45%, 250=8.97%, 500=0.02%, 750=0.02%
  lat (msec)   : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.31%, 50=0.14%
  lat (msec)   : 100=0.15%, 250=0.03%
  cpu          : usr=2.65%, sys=9.58%, ctx=149861, majf=0, minf=13
  IO depths    : 1=0.1%, 2=0.2%, 4=0.3%, 8=0.7%, 16=98.7%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,194788,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=16

Run status group 0 (all jobs):
  WRITE: bw=126MiB/s (132MB/s), 126MiB/s-126MiB/s (132MB/s-132MB/s), io=761MiB (798MB), run=6035-6035msec

Disk stats (read/write):
  sda: ios=21/186454, sectors=2688/1558296, merge=0/8379, ticks=103/12384, in_queue=12487, util=56.94%

yizhanglinux avatar Nov 13 '25 04:11 yizhanglinux

I added some debug log and found that removing the scsi-debug takes about 6s.

diff --git a/check b/check
index 6d77d8e..e86c233 100755
--- a/check
+++ b/check
@@ -472,6 +472,7 @@ _unload_module() {
                reason=$(modprobe -r "$m" 2>&1)
                [ ! -e "/sys/module/$m" ] && return 0
                sleep .1
+               echo "========= unload_module:$m $i" >>/root/unload_module
        done
        echo "${reason}" >&2
        return 1
diff --git a/common/scsi_debug b/common/scsi_debug
index 78cc8b9..617dc51 100644
--- a/common/scsi_debug
+++ b/common/scsi_debug
@@ -179,8 +179,9 @@ _exit_scsi_debug() {
        unset SCSI_DEBUG_DEVICES
        udevadm settle

+       echo "_exit_scsi_debug: start remove scsi-debug after udevadm settle" >/dev/kmsg
        if _module_file_exists scsi_debug; then
-               _unload_module scsi_debug 10
+               _unload_module scsi_debug 100
                return
        fi

dmesg

[ 6729.004127] Before _exit_scsi_debug
[ 6729.058370] _exit_scsi_debug: start remove scsi-debug after udevadm settle
[ 6735.309066] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 6735.899662] End _exit_scsi_debug

# cat ../unload_module
========= unload_module:scsi_debug 100
---snip---
========= unload_module:scsi_debug 43
========= unload_module:scsi_debug 42

yizhanglinux avatar Nov 13 '25 04:11 yizhanglinux

Here is the journalctl log during the scsi-debug removal

Nov 13 05:05:49 systemd-udevd[5427]: Worker [8163] exited.
Nov 13 05:05:49 systemd-udevd[5427]: Worker [8161] exited.
Nov 13 05:05:49 systemd-udevd[5427]: Worker [8059] exited.
Nov 13 05:05:49 systemd-udevd[5427]: Worker [8164] exited.
Nov 13 05:05:49 systemd-udevd[5427]: Worker [8162] exited.
Nov 13 05:05:49 systemd-udevd[5427]: Cleaning up idle workers.
Nov 13 05:05:46 unknown: End _exit_scsi_debug
Nov 13 05:05:46 systemd-udevd[5427]: No events are queued, removed /run/udev/queue.
Nov 13 05:05:46 (udev-worker)[8164]: scsi_debug: sd-device-monitor(worker): Passed 162 byte to netlink monitor.
Nov 13 05:05:46 (udev-worker)[8164]: scsi_debug: Device processed (SEQNUM=2672, ACTION=remove)
Nov 13 05:05:46 (udev-worker)[8164]: scsi_debug: Processing device (SEQNUM=2672, ACTION=remove)
Nov 13 05:05:46 systemd-udevd[5427]: scsi_debug: sd-device-monitor(manager): Passed 162 byte to netlink monitor.
Nov 13 05:05:46 systemd-udevd[5427]: scsi_debug: Device ready for processing (SEQNUM=2672, ACTION=remove)
Nov 13 05:05:46 systemd-udevd[5427]: scsi_debug: Device is queued (SEQNUM=2672, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: No events are queued, removed /run/udev/queue.
Nov 13 05:05:45 (udev-worker)[8164]: pseudo: sd-device-monitor(worker): Passed 152 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: pseudo: Device processed (SEQNUM=2671, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: pseudo: Processing device (SEQNUM=2671, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: pseudo: sd-device-monitor(manager): Passed 152 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: pseudo: Device ready for processing (SEQNUM=2671, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8162]: scsi_debug: sd-device-monitor(worker): Passed 175 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8162]: scsi_debug: Device processed (SEQNUM=2670, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8162]: scsi_debug: Processing device (SEQNUM=2670, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: adapter0: sd-device-monitor(worker): Passed 170 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: adapter0: Device processed (SEQNUM=2669, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: adapter0: Processing device (SEQNUM=2669, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: adapter0: sd-device-monitor(manager): Passed 170 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: adapter0: Device ready for processing (SEQNUM=2669, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: adapter0: sd-device-monitor(worker): Passed 170 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: adapter0: Device processed (SEQNUM=2668, ACTION=unbind)
Nov 13 05:05:45 (udev-worker)[8164]: adapter0: Processing device (SEQNUM=2668, ACTION=unbind)
Nov 13 05:05:45 systemd-udevd[5427]: pseudo: SEQNUM=2671 blocked by SEQNUM=2670
Nov 13 05:05:45 systemd-udevd[5427]: scsi_debug: sd-device-monitor(manager): Passed 175 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: scsi_debug: Device ready for processing (SEQNUM=2670, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: adapter0: SEQNUM=2669 blocked by SEQNUM=2668
Nov 13 05:05:45 systemd-udevd[5427]: adapter0: sd-device-monitor(manager): Passed 170 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: adapter0: Device ready for processing (SEQNUM=2668, ACTION=unbind)
Nov 13 05:05:45 systemd-udevd[5427]: pseudo: Device is queued (SEQNUM=2671, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: scsi_debug: Device is queued (SEQNUM=2670, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: adapter0: Device is queued (SEQNUM=2669, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: adapter0: Device is queued (SEQNUM=2668, ACTION=unbind)
Nov 13 05:05:45 (udev-worker)[8164]: scsi_tmf_0: sd-device-monitor(worker): Passed 184 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: scsi_tmf_0: Device processed (SEQNUM=2667, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: scsi_tmf_0: Processing device (SEQNUM=2667, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: scsi_tmf_0: sd-device-monitor(manager): Passed 184 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: scsi_tmf_0: Device ready for processing (SEQNUM=2667, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: scsi_tmf_0: Device is queued (SEQNUM=2667, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: No events are queued, removed /run/udev/queue.
Nov 13 05:05:45 (udev-worker)[8164]: host0: sd-device-monitor(worker): Passed 192 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: host0: Device processed (SEQNUM=2666, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: host0: Processing device (SEQNUM=2666, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: host0: sd-device-monitor(manager): Passed 192 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: host0: Device ready for processing (SEQNUM=2666, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: host0: sd-device-monitor(worker): Passed 195 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: host0: Device processed (SEQNUM=2665, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: host0: Processing device (SEQNUM=2665, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: host0: SEQNUM=2666 blocked by SEQNUM=2665
Nov 13 05:05:45 systemd-udevd[5427]: host0: sd-device-monitor(manager): Passed 195 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: host0: Device ready for processing (SEQNUM=2665, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: host0: Device is queued (SEQNUM=2666, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: host0: Device is queued (SEQNUM=2665, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: No events are queued, removed /run/udev/queue.
Nov 13 05:05:45 (udev-worker)[8164]: target0:0:0: sd-device-monitor(worker): Passed 206 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: target0:0:0: Device processed (SEQNUM=2664, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: target0:0:0: Processing device (SEQNUM=2664, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: target0:0:0: sd-device-monitor(manager): Passed 206 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: target0:0:0: Device ready for processing (SEQNUM=2664, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: 0:0:0:0: sd-device-monitor(worker): Passed 235 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: 0:0:0:0: Device processed (SEQNUM=2663, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: 0:0:0:0: Processing device (SEQNUM=2663, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: sd-device-monitor(manager): Passed 235 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device ready for processing (SEQNUM=2663, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: 0:0:0:0: sd-device-monitor(worker): Passed 214 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: 0:0:0:0: Device processed (SEQNUM=2662, ACTION=unbind)
Nov 13 05:05:45 (udev-worker)[8164]: 0:0:0:0: Processing device (SEQNUM=2662, ACTION=unbind)
Nov 13 05:05:45 systemd-udevd[5427]: target0:0:0: SEQNUM=2664 blocked by SEQNUM=2662
Nov 13 05:05:45 systemd-udevd[5427]: target0:0:0: SEQNUM=2664 blocked by SEQNUM=2663
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: SEQNUM=2663 blocked by SEQNUM=2662
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: sd-device-monitor(manager): Passed 214 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device ready for processing (SEQNUM=2662, ACTION=unbind)
Nov 13 05:05:45 systemd-udevd[5427]: target0:0:0: Device is queued (SEQNUM=2664, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device is queued (SEQNUM=2663, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device is queued (SEQNUM=2662, ACTION=unbind)
Nov 13 05:05:45 kernel: sd 0:0:0:0: [sda] Synchronizing SCSI cache
Nov 13 05:05:45 systemd-udevd[5427]: No events are queued, removed /run/udev/queue.
Nov 13 05:05:45 (udev-worker)[8164]: sda: sd-device-monitor(worker): Passed 1188 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: sda: Device processed (SEQNUM=2661, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: sda: No reference left for '/dev/disk/by-diskseq/29', removing
Nov 13 05:05:45 (udev-worker)[8164]: sda: Symbolic link '/dev/disk/by-diskseq/29' points to '../../sda' which is outside of '/dev/', updating it.
Nov 13 05:05:45 (udev-worker)[8164]: sda: No reference left for '/dev/disk/by-id/wwn-0x33333330000007d0', removing
Nov 13 05:05:45 (udev-worker)[8164]: sda: Symbolic link '/dev/disk/by-id/wwn-0x33333330000007d0' points to '../../sda' which is outside of '/dev/', updating it.
Nov 13 05:05:45 (udev-worker)[8164]: sda: No reference left for '/dev/disk/by-id/scsi-333333330000007d0', removing
Nov 13 05:05:45 (udev-worker)[8164]: sda: Symbolic link '/dev/disk/by-id/scsi-333333330000007d0' points to '../../sda' which is outside of '/dev/', updating it.
Nov 13 05:05:45 (udev-worker)[8164]: sda: Processing device (SEQNUM=2661, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: sda: sd-device-monitor(manager): Passed 262 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: sda: Device ready for processing (SEQNUM=2661, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: sda: Device is queued (SEQNUM=2661, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: Received inotify event about removal of watch handle 39.
Nov 13 05:05:45 systemd-udevd[5427]: No events are queued, removed /run/udev/queue.
Nov 13 05:05:45 (udev-worker)[8059]: 0:0:0:0: sd-device-monitor(worker): Passed 248 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8059]: 0:0:0:0: Device processed (SEQNUM=2656, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8161]: sg0: sd-device-monitor(worker): Passed 253 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: 8:0: Worker [8164] is forked for processing SEQNUM=2660.
Nov 13 05:05:45 (udev-worker)[8161]: sg0: Device processed (SEQNUM=2657, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: Successfully forked off '(udev-worker)' as PID 8164.
Nov 13 05:05:45 (udev-worker)[8164]: 8:0: sd-device-monitor(worker): Passed 165 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8164]: 8:0: Device processed (SEQNUM=2660, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8164]: 8:0: Processing device (SEQNUM=2660, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8162]: 0:0:0:0: sd-device-monitor(worker): Passed 221 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8162]: 0:0:0:0: Device processed (SEQNUM=2658, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8163]: 0:0:0:0: sd-device-monitor(worker): Passed 217 byte to netlink monitor.
Nov 13 05:05:45 (udev-worker)[8163]: 0:0:0:0: Device processed (SEQNUM=2659, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8162]: 0:0:0:0: Processing device (SEQNUM=2658, ACTION=remove)
Nov 13 05:05:45 (udev-worker)[8163]: 0:0:0:0: Processing device (SEQNUM=2659, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 8:0: Device ready for processing (SEQNUM=2660, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 8:0: Device is queued (SEQNUM=2660, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Worker [8163] is forked for processing SEQNUM=2659.
Nov 13 05:05:45 systemd-udevd[5427]: Successfully forked off '(udev-worker)' as PID 8163.
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device ready for processing (SEQNUM=2659, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Worker [8162] is forked for processing SEQNUM=2658.
Nov 13 05:05:45 (udev-worker)[8161]: sg0: Processing device (SEQNUM=2657, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: Successfully forked off '(udev-worker)' as PID 8162.
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device ready for processing (SEQNUM=2658, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: sg0: Worker [8161] is forked for processing SEQNUM=2657.
Nov 13 05:05:45 systemd-udevd[5427]: Successfully forked off '(udev-worker)' as PID 8161.
Nov 13 05:05:45 (udev-worker)[8059]: 0:0:0:0: Processing device (SEQNUM=2656, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: sg0: Device ready for processing (SEQNUM=2657, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device is queued (SEQNUM=2659, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device is queued (SEQNUM=2658, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: sg0: Device is queued (SEQNUM=2657, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: sd-device-monitor(manager): Passed 248 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device ready for processing (SEQNUM=2656, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: 0:0:0:0: Device is queued (SEQNUM=2656, ACTION=remove)
Nov 13 05:05:45 systemd-udevd[5427]: No events are queued, removed /run/udev/queue.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/udev/rules.d/README' with unexpected suffix.
Nov 13 05:05:45 (udev-worker)[8059]: sda: sd-device-monitor(worker): Passed 1326 byte to netlink monitor.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/89-ethernet.network.example' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-wifi-station.network.example' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-wifi-ap.network.example' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-wifi-adhoc.network' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-vm-vt.network' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-namespace-ns.network' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-vz.network' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-ve.network' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-vb.network' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-host0.network' with unexpected suffix.
Nov 13 05:05:45 (udev-worker)[8059]: sda: Device processed (SEQNUM=2655, ACTION=change, UUID=8079a102-9378-44b7-9303-389dec26ecb4)
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-host0-tun.network' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-auto-link-local.network.example' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-6rd-tunnel.network' with unexpected suffix.
Nov 13 05:05:45 (udev-worker)[8059]: sda: sd-device: Created database file '/run/udev/data/b8:0' for '/devices/pseudo_0/adapter0/host0/target0:0:0/0:0:0:0/block/sda'.
Nov 13 05:05:45 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-namespace-ns-tun.network' with unexpected suffix.
Nov 13 05:05:45 systemd-udevd[5427]: sda: Adding watch on '/dev/sda'
Nov 13 05:05:45 (udev-worker)[8059]: sda: sd-device: Created database file '/run/udev/data/b8:0' for '/devices/pseudo_0/adapter0/host0/target0:0:0/0:0:0:0/block/sda'.
Nov 13 05:05:45 (udev-worker)[8059]: sda: Successfully created symlink '/dev/block/8:0' to '/dev/sda'
Nov 13 05:05:45 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/90-iocost.rules:18 IMPORT{builtin}="hwdb 'block::name:$env{.MODEL}:fwrev:$env{ID_REVISION}:'": Failed to run builtin "hwdb 'block::name:scsi_debug:fwrev:0191:'": No data available
Nov 13 05:05:45 (udev-worker)[8059]: sda: No entry found from hwdb.
Nov 13 05:05:45 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/90-iocost.rules:18 IMPORT{builtin}="hwdb 'block::name:$env{.MODEL}:fwrev:$env{ID_REVISION}:'": Importing properties from results of builtin command "hwdb 'block::name:scsi_debug:fwrev:0191:'".
Nov 13 05:05:45 (udev-worker)[8059]: sda: Process 'fc_wwpn_id /devices/pseudo_0/adapter0/host0/target0:0:0/0:0:0:0/block/sda' succeeded.
Nov 13 05:05:45 (udev-worker)[8059]: Successfully forked off '(spawn)' as PID 8157.
Nov 13 05:05:45 (udev-worker)[8059]: sda: Starting 'fc_wwpn_id /devices/pseudo_0/adapter0/host0/target0:0:0/0:0:0:0/block/sda'
Nov 13 05:05:45 (udev-worker)[8059]: sda: Found callout binary: "/usr/lib/udev/fc_wwpn_id".
Nov 13 05:05:45 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/63-fc-wwpn-id.rules:8 IMPORT{program}="fc_wwpn_id %p": Importing properties from results of "fc_wwpn_id /devices/pseudo_0/adapter0/host0/target0:0:0/0:0:0:0/block/sda"
Nov 13 05:05:45 (udev-worker)[8059]: sda: Process '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw' succeeded.
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw'(out) 'SCSI_IDENT_TARGET_NAME=naa.32222220000007CD'
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw'(out) 'SCSI_IDENT_TARGET_NAA_LOCAL=32222220000007cd'
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw'(out) 'SCSI_IDENT_PORT_TARGET_PORT_GROUP=0x100'
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw'(out) 'SCSI_IDENT_PORT_NAA_LOCAL=32222220000007ce'
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw'(out) 'SCSI_IDENT_PORT_RELATIVE=1'
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw'(out) 'SCSI_IDENT_LUN_NAA_LOCAL=33333330000007d0'
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw'(out) 'SCSI_IDENT_LUN_T10=Linux_scsi_debug_2000'
Nov 13 05:05:45 (udev-worker)[8059]: Successfully forked off '(spawn)' as PID 8156.
Nov 13 05:05:45 (udev-worker)[8059]: sda: Starting '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw'
Nov 13 05:05:45 (udev-worker)[8059]: sda: Found callout binary: "/usr/bin/sg_inq".
Nov 13 05:05:45 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/61-scsi-sg3_id.rules:57 IMPORT{program}="/usr/bin/sg_inq --export --inhex=$env{.SYSFS_PATH}/vpd_pg83 --raw": Importing properties from results of "/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg83 --raw"
Nov 13 05:05:45 (udev-worker)[8059]: sda: Process '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg80 --raw' succeeded.
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg80 --raw'(out) 'SCSI_IDENT_SERIAL=2000'
Nov 13 05:05:45 (udev-worker)[8059]: Successfully forked off '(spawn)' as PID 8155.
Nov 13 05:05:45 (udev-worker)[8059]: sda: Starting '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg80 --raw'
Nov 13 05:05:45 (udev-worker)[8059]: sda: Found callout binary: "/usr/bin/sg_inq".
Nov 13 05:05:45 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/61-scsi-sg3_id.rules:56 IMPORT{program}="/usr/bin/sg_inq --export --inhex=$env{.SYSFS_PATH}/vpd_pg80 --raw": Importing properties from results of "/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/vpd_pg80 --raw"
Nov 13 05:05:45 (udev-worker)[8059]: sda: Process '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/inquiry --raw' succeeded.
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/inquiry --raw'(out) 'SCSI_VENDOR_ENC=Linux\x20\x20\x20'
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/inquiry --raw'(out) 'SCSI_VENDOR=Linux'
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/inquiry --raw'(out) 'SCSI_TYPE=host managed zoned block'
Nov 13 05:05:45 (udev-worker)[8059]: sda: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/inquiry --raw'(out) 'SCSI_TPGS=0'
Nov 13 05:05:45 (udev-worker)[8059]: Successfully forked off '(spawn)' as PID 8154.
Nov 13 05:05:45 (udev-worker)[8059]: sda: Starting '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/inquiry --raw'
Nov 13 05:05:45 (udev-worker)[8059]: sda: Found callout binary: "/usr/bin/sg_inq".
Nov 13 05:05:45 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/61-scsi-sg3_id.rules:51 IMPORT{program}="/usr/bin/sg_inq --export --inhex=$env{.SYSFS_PATH}/inquiry --raw": Importing properties from results of "/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/0:0:0:0/device/inquiry --raw"
Nov 13 05:05:45 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/60-persistent-storage.rules:164 SYMLINK+="disk/by-diskseq/$env{DISKSEQ}$env{.PART_SUFFIX}": Added device node symlink "disk/by-diskseq/29".
Nov 13 05:05:45 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/60-persistent-storage.rules:142 SYMLINK+="disk/by-id/wwn-$env{ID_WWN_WITH_EXTENSION}$env{.PART_SUFFIX}": Added device node symlink "disk/by-id/wwn-0x33333330000007d0".
Nov 13 05:05:42 (udev-worker)[8059]: sda: Probe /dev/sda with raid and offset=0
Nov 13 05:05:42 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/60-persistent-storage.rules:133 IMPORT{builtin}="blkid": Importing properties from results of builtin command "blkid".
Nov 13 05:05:42 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/60-persistent-storage.rules:110 IMPORT{builtin}="path_id": Failed to run builtin "path_id": No such file or directory
Nov 13 05:05:42 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/60-persistent-storage.rules:110 IMPORT{builtin}="path_id": Importing properties from results of builtin command "path_id".
Nov 13 05:05:42 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/60-persistent-storage.rules:78 SYMLINK+="disk/by-id/$env{ID_BUS}-$env{ID_SERIAL}$env{.PART_SUFFIX}": Added device node symlink "disk/by-id/scsi-333333330000007d0".
Nov 13 05:05:42 (udev-worker)[8059]: sda: Process 'scsi_id --export --allowlisted -d /dev/sda' succeeded.
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_SCSI_SERIAL=2000'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_TARGET_PORT=100'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_WWN_WITH_EXTENSION=0x33333330000007d0'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_WWN=0x33333330000007d0'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_SERIAL_SHORT=33333330000007d0'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_SERIAL=333333330000007d0'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_TYPE=zbc'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_REVISION=0191'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_MODEL_ENC=scsi_debug\x20\x20\x20\x20\x20\x20'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_MODEL=scsi_debug'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_VENDOR_ENC=Linux\x20\x20\x20'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_VENDOR=Linux'
Nov 13 05:05:42 (udev-worker)[8059]: sda: 'scsi_id --export --allowlisted -d /dev/sda'(out) 'ID_SCSI=1'
Nov 13 05:05:42 (udev-worker)[8059]: Successfully forked off '(spawn)' as PID 8060.
Nov 13 05:05:42 (udev-worker)[8059]: sda: Starting 'scsi_id --export --allowlisted -d /dev/sda'
Nov 13 05:05:42 (udev-worker)[8059]: sda: Found callout binary: "/usr/lib/udev/scsi_id".
Nov 13 05:05:42 (udev-worker)[8059]: sda: /usr/lib/udev/rules.d/60-persistent-storage.rules:75 IMPORT{program}="scsi_id --export --allowlisted -d $devnode": Importing properties from results of "scsi_id --export --allowlisted -d /dev/sda"
Nov 13 05:05:42 (udev-worker)[8059]: sda: sd-device: Created database file '/run/udev/data/b8:0' for '/devices/pseudo_0/adapter0/host0/target0:0:0/0:0:0:0/block/sda'.
Nov 13 05:05:42 systemd-udevd[5427]: Received inotify event about removal of watch handle 38.
Nov 13 05:05:42 systemd-udevd[5427]: sda: Removing watch handle 38.
Nov 13 05:05:42 (udev-worker)[8059]: sda: Successfully took flock(LOCK_SH) for /dev/sda, it will be released after the event has been processed.
Nov 13 05:05:42 (udev-worker)[8059]: sda: Processing device (SEQNUM=2655, ACTION=change, UUID=8079a102-9378-44b7-9303-389dec26ecb4)
Nov 13 05:05:42 systemd-udevd[5427]: sda: Worker [8059] is forked for processing SEQNUM=2655.
Nov 13 05:05:42 systemd-udevd[5427]: Successfully forked off '(udev-worker)' as PID 8059.
Nov 13 05:05:42 systemd-udevd[5427]: sda: Device ready for processing (SEQNUM=2655, ACTION=change, UUID=8079a102-9378-44b7-9303-389dec26ecb4)
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/udev/rules.d/README' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/89-ethernet.network.example' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-wifi-station.network.example' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-wifi-ap.network.example' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-wifi-adhoc.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-vm-vt.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-namespace-ns.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-vz.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-ve.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-vb.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-host0.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-container-host0-tun.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-auto-link-local.network.example' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-6rd-tunnel.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: Skipping file '/usr/lib/systemd/network/80-namespace-ns-tun.network' with unexpected suffix.
Nov 13 05:05:42 systemd-udevd[5427]: sda: Device is queued (SEQNUM=2655, ACTION=change, UUID=8079a102-9378-44b7-9303-389dec26ecb4)
Nov 13 05:05:41 systemd-udevd[5427]: Worker [7891] exited.
Nov 13 05:05:41 systemd-udevd[5427]: Cleaning up idle workers.
Nov 13 05:05:38 _exit_scsi_debug: start remove scsi-debug after udevadm settle
Nov 13 05:05:38 _exit_scsi_debug: start udevadm settle
Nov 13 05:05:38 unknown: Before _exit_scsi_debug
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Changing state processing-disconnect → disconnected
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Changing state pending-disconnect → processing-disconnect
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Changing state idle-server → pending-disconnect
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Got POLLHUP from socket.
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Changing state processed-method → idle-server
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Changing state processing-method → processed-method
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Sending message: {"parameters":{}}
Nov 13 05:05:38 systemd-udevd[5427]: Received io.systemd.service.Ping
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Changing state idle-server → processing-method
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Received message: {"method":"io.systemd.service.Ping","parameters":{}}
Nov 13 05:05:38 systemd-udevd[5427]: varlink-43-43: Setting state idle-server
Nov 13 05:05:38 systemd-udevd[5427]: varlink: New incoming connection.

yizhanglinux avatar Nov 13 '25 05:11 yizhanglinux

I tried downgrading the systemd to systemd-257.9-2.fc42.s390x, and the scsi-debug can be quickly removed.

# rpm -qa systemd
systemd-257.9-2.fc42.s390x
[ 7905.585352] Before _exit_scsi_debug
[ 7905.585510] _exit_scsi_debug: start udevadm settle
[ 7911.628128] _exit_scsi_debug: start remove scsi-debug after udevadm settle
[ 7911.708438] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[ 7912.250177] End _exit_scsi_debug

yizhanglinux avatar Nov 13 '25 05:11 yizhanglinux

Filed one systemd issue to track it: http://github.com/systemd/systemd/issues/39711

yizhanglinux avatar Nov 13 '25 05:11 yizhanglinux