Re: [opensuse] udev causes continous access on/spinning up of floppy drive

4 Jan 2018

On Thu, 4 Jan 2018 10:50:06 +0300
Andrei Borzenkov &lt;arvidjaar(a)gmail.com&gt; wrote:

...
  03.01.2018 18:57, Paul Neuwirth пишет:
  journalctl shows best, that it is in fact
udevd..

 Actually udevd is probably just the messenger here. Annotated log

  Jan 03 11:25:27 kappa kernel: scsi 0:0:3:0:
Direct-Access     TEAC    FC-5     HGF  00 RV D PQ: 0 ANSI: 1 CCS
  Jan 03 11:25:27 kappa kernel: sd 0:0:3:0:
Attached scsi generic sg4
 type 0 Jan 03 11:25:27 kappa kernel: sd 0:0:3:0: Power-on or device
 reset    occurred
  Jan 03 11:25:27 kappa kernel: sd 0:0:3:0: [sdc]
Spinning up
 disk...    
 This comes from kernel directly. It does it as the first step when
 probing for new SCSI disk. Note that if device explicitly says that
 medium is not present, "Spinning up" is skipped.

  Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc]
Read Capacity(10)    failed: Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
  Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc]
Sense Key : Not
 Ready    [current]
  Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc]
Add. Sense:
 Logical    unit not ready, cause not reportable
  Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc]
Write Protect is on
 Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Mode Sense: 37 88
 80 08 Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc] Asking for
 cache data    failed
  Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc]
Assuming drive
 cache:    write through

 The above is executed only if driver thinks that medium is present
 (otherwise there is no point to even attempt to read capacity). Driver
 starts with assumption it is. Again - if device returns proper sense
 code indicating no medium is present, this step should have been
 skipped. Still, as READ CAPACITY fails we should have reset "medium
 present" indication ...

 ... and we announce block device sdc to user space (i.e. udevd) now.
 So udevd spawns handler thread.

  Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc]
Spinning up
 disk...    
 Still kernel directly.

  Jan 03 11:27:08 kappa kernel: sd 0:0:3:0: [sdc]
Spinning up
 disk...    
 And *this* comes from udevd handler trying to open device node. Which
 triggers device revalidation. And apparently it also resets "medium
 not present" flag back because driver has never received proper
 response from device. And because driver flips this flag from TRUE to
 FALSE it apparently generates change event. Which spawns yet another
 udevd handler which tries to open device node ... notice incrementing
 event numbers:

  Jan 03 11:28:09 kappa systemd-udevd[613]: seq
2990    '/devices/pci0000:00/0000:00:0a.0/0000:01:
 06.0/host0/target0:0:3/0:0:3:0/block/sdc' is taking a long time
  Jan 03 11:31:30 kappa systemd-udevd[613]: seq
2991    '/devices/pci0000:00/0000:00:0a.0/0000:01:
 06.0/host0/target0:0:3/0:0:3:0/block/sdc' is taking a long time
  Jan 03 11:36:31 kappa systemd-udevd[613]: seq
2992    '/devices/pci0000:00/0000:00:0a.0/0000:01:
 06.0/host0/target0:0:3/0:0:3:0/block/sdc' is taking a long time
  Jan 03 11:41:32 kappa systemd-udevd[613]: seq
2993    '/devices/pci0000:00/0000:00:0a.0/0000:01:
 06.0/host0/target0:0:3/0:0:3:0/block/sdc' is taking a long time

 Could you please reproduce it once more and provide output of "udevadm
 monitor -k" to confirm this.
  thank you for your help. just reloaded kernel modue, and output of command:

# udevadm monitor -k
monitor will print the received events for:
KERNEL - the kernel uevent

^Z
[1]+  Stopped                 udevadm monitor -k
 # rmmod aic7xxx
 # fg
udevadm monitor -k
KERNEL[487599.298381] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/bsg/0:0:0:0 (bsg)
KERNEL[487599.298422] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/scsi_generic/sg3
(scsi_generic)
KERNEL[487599.298440] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/scsi_device/0:0:0:0
(scsi_device)
KERNEL[487599.298465] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0 (scsi)
KERNEL[487599.298481] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/spi_transport/target0:0:0
(spi_transport)
KERNEL[487599.298506] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0 (scsi)
KERNEL[487599.298531] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/bsg/0:0:3:0 (bsg)
KERNEL[487599.298556] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_generic/sg4
(scsi_generic)
KERNEL[487599.298571] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_device/0:0:3:0
(scsi_device)
KERNEL[487599.298587] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_disk/0:0:3:0
(scsi_disk)
KERNEL[487599.298600] remove   /devices/virtual/bdi/8:32 (bdi)
KERNEL[487599.298624] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block)
KERNEL[487599.298646] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0 (scsi)
KERNEL[487599.298663] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/spi_transport/target0:0:3
(spi_transport)
KERNEL[487599.298685] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3 (scsi)
KERNEL[487599.298709] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/bsg/0:0:4:0 (bsg)
KERNEL[487599.298733] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/scsi_generic/sg5
(scsi_generic)
KERNEL[487599.298749] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/scsi_device/0:0:4:0
(scsi_device)
KERNEL[487599.298770] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0 (scsi)
KERNEL[487599.298785] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/spi_transport/target0:0:4
(spi_transport)
KERNEL[487599.298806] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4 (scsi)
KERNEL[487599.298830] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/bsg/0:0:5:0 (bsg)
KERNEL[487599.298856] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_generic/sg7
(scsi_generic)
KERNEL[487599.298871] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_device/0:0:5:0
(scsi_device)
KERNEL[487599.298894] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0
(scsi_tape)
KERNEL[487599.298918] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0
(scsi_tape)
KERNEL[487599.298941] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0l
(scsi_tape)
KERNEL[487599.298965] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0l
(scsi_tape)
KERNEL[487599.298990] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0m
(scsi_tape)
KERNEL[487599.299014] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0m
(scsi_tape)
KERNEL[487599.299038] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0a
(scsi_tape)
KERNEL[487599.299061] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0a
(scsi_tape)
KERNEL[487599.299083] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0 (scsi)
KERNEL[487599.299098] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/spi_transport/target0:0:5
(spi_transport)
KERNEL[487599.299119] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5 (scsi)
KERNEL[487599.299134] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/spi_host/host0 (spi_host)
KERNEL[487599.299148] remove  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/scsi_host/host0 (scsi_host)
KERNEL[487599.299168] remove   /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0 (scsi)
KERNEL[487599.299183] remove   /bus/pci/drivers/aic7xxx (drivers)
KERNEL[487599.299196] remove   /module/aic7xxx (module)
^Z
[1]+  Stopped                 udevadm monitor -k
 # modprobe aic7xxx; fg
udevadm monitor -k
KERNEL[487838.926097] add      /module/aic7xxx (module)
KERNEL[487838.926140] add      /devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0 (scsi)
KERNEL[487838.926157] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/scsi_host/host0 (scsi_host)
KERNEL[487838.926172] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/spi_host/host0 (spi_host)
KERNEL[487838.926199] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0 (scsi)
KERNEL[487838.926215] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/spi_transport/target0:0:0
(spi_transport)
KERNEL[487838.926238] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0 (scsi)
KERNEL[487838.926253] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/scsi_device/0:0:0:0
(scsi_device)
KERNEL[487838.926278] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/scsi_generic/sg3
(scsi_generic)
KERNEL[487838.926304] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:0/0:0:0:0/bsg/0:0:0:0 (bsg)
KERNEL[487838.926326] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3 (scsi)
KERNEL[487838.926340] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/spi_transport/target0:0:3
(spi_transport)
KERNEL[487838.926363] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0 (scsi)
KERNEL[487838.926378] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_disk/0:0:3:0
(scsi_disk)
KERNEL[487838.926392] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_device/0:0:3:0
(scsi_device)
KERNEL[487838.926415] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/scsi_generic/sg4
(scsi_generic)
KERNEL[487838.926440] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/bsg/0:0:3:0 (bsg)
KERNEL[487838.926465] change  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0 (scsi)
KERNEL[487838.926488] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4 (scsi)
KERNEL[487838.926503] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/spi_transport/target0:0:4
(spi_transport)
KERNEL[487838.926525] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0 (scsi)
KERNEL[487838.926540] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/scsi_device/0:0:4:0
(scsi_device)
KERNEL[487838.926563] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/scsi_generic/sg5
(scsi_generic)
KERNEL[487838.926587] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:4/0:0:4:0/bsg/0:0:4:0 (bsg)
KERNEL[487838.926609] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5 (scsi)
KERNEL[487838.926623] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/spi_transport/target0:0:5
(spi_transport)
KERNEL[487838.926645] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0 (scsi)
KERNEL[487838.926669] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0
(scsi_tape)
KERNEL[487838.926694] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0
(scsi_tape)
KERNEL[487838.926717] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0l
(scsi_tape)
KERNEL[487838.926741] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0l
(scsi_tape)
KERNEL[487838.926766] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0m
(scsi_tape)
KERNEL[487838.926790] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0m
(scsi_tape)
KERNEL[487838.926813] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/st0a
(scsi_tape)
KERNEL[487838.926838] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_tape/nst0a
(scsi_tape)
KERNEL[487838.926853] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_device/0:0:5:0
(scsi_device)
KERNEL[487838.926877] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/scsi_generic/sg7
(scsi_generic)
KERNEL[487838.926902] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:5/0:0:5:0/bsg/0:0:5:0 (bsg)
KERNEL[487838.926917] add      /bus/pci/drivers/aic7xxx (drivers)
KERNEL[487838.926930] add      /devices/virtual/bdi/8:32 (bdi)
KERNEL[487838.926954] add     
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block)
KERNEL[487838.926986] change  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block)
KERNEL[487838.927021] change  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block)
KERNEL[487838.927054] change  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block)
KERNEL[487939.384425] change  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block)
KERNEL[488039.884765] change  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block)
KERNEL[488039.895676] change  
/devices/pci0000:00/0000:00:0a.0/0000:01:06.0/host0/target0:0:3/0:0:3:0/block/sdc (block)

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

2005

2004

2003

2002

2001

2000

1999

1998

1997

1996

1995

1994

1993

1992

Re: [opensuse] udev causes continous access on/spinning up of floppy drive