1

I got a problem when i am pluggin USB devices into my server. It looks like the USB devices repeatedly plugged in or re-assign the device letters sdb1: sdb1

The problem with that is that i execute a udev rule, every time a USB device is plugged in. The udev rule is now executed several times, every time the device letters is showing up. I have deactivated the custom udev rules to exclude this as the source of error. So all this effect and logs are created without any custom udev rule.

this effect only remains until I have mounted the device. After mounting the device, this messages stop.

This is the log, when i am connection a RDX-Device via USB but the effect is the same with USB-Sticks

/var/log/messages

2018-08-06T09:23:29.139628+02:00 SLES12RDX kernel: [241820.600269] sd 4:0:0:0: [sdb] 976764976 512-byte logical blocks: (500 GB/466 GiB)
2018-08-06T09:23:29.171622+02:00 SLES12RDX kernel: [241820.632581]  sdb: sdb1
2018-08-06T09:23:44.979634+02:00 SLES12RDX kernel: [241836.437561]  sdb: sdb1
2018-08-06T09:24:15.199624+02:00 SLES12RDX kernel: [241866.657525]  sdb: sdb1
2018-08-06T09:24:45.415636+02:00 SLES12RDX kernel: [241896.874298]  sdb: sdb1
2018-08-06T09:25:15.631630+02:00 SLES12RDX kernel: [241927.093221]  sdb: sdb1
2018-08-06T09:25:45.851637+02:00 SLES12RDX kernel: [241957.311295]  sdb: sdb1
2018-08-06T09:26:16.067646+02:00 SLES12RDX kernel: [241987.530071]  sdb: sdb1

dmesg

[241262.363311] usb 2-1.6: new high-speed USB device number 5 using ehci-pci
[241262.457475] usb 2-1.6: New USB device found, idVendor=1a5a, idProduct=0006
[241262.457487] usb 2-1.6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[241262.457488] usb 2-1.6: Product: RDX
[241262.457490] usb 2-1.6: Manufacturer: TANDBERG
[241262.457491] usb 2-1.6: SerialNumber: 032613566487
[241262.457917] usb-storage 2-1.6:1.0: USB Mass Storage device detected
[241262.458197] scsi host4: usb-storage 2-1.6:1.0
[241263.456000] scsi 4:0:0:0: Direct-Access      RDX              0227 PQ: 0 ANSI: 6
[241263.456240] sd 4:0:0:0: Attached scsi generic sg2 type 0
[241263.459249] sd 4:0:0:0: [sdb] Attached SCSI removable disk
[241288.618894] sd 4:0:0:0: [sdb] 976764976 512-byte logical blocks: (500 GB/466 GiB)
[241288.657955]  sdb: sdb1
[241294.065836]  sdb: sdb1
[241324.282380]  sdb: sdb1
[241766.323096] sd 4:0:0:0: [sdb] 976764976 512-byte logical blocks: (500 GB/466 GiB)
[241766.360054]  sdb: sdb1
[241776.112351]  sdb: sdb1
[241820.600269] sd 4:0:0:0: [sdb] 976764976 512-byte logical blocks: (500 GB/466 GiB)
[241820.632581]  sdb: sdb1
[241836.437561]  sdb: sdb1
[241866.657525]  sdb: sdb1
[241896.874298]  sdb: sdb1
[241927.093221]  sdb: sdb1
[241957.311295]  sdb: sdb1
[241987.530071]  sdb: sdb1
Improve this question
9
  • Some udev rules are wrong, if not the custom ones, then the existing ones. Debugging udev is a PITA, but you can e.g. restart udevd with verbose debug messages. You said you "deactivated udev", but I assumed you mean the custom rules.
    – dirkt
    Aug 6, 2018 at 8:14
  • Yes, i mean my custom udev rules. All i have now is a default '70-persistent-net.rules'. In addition, only the SUBSYSTEM="net" and KERNEL=="eth*" is affected by this rule and so dosen't seems to be wrong or the source of this issue.
    – Danloc
    Aug 6, 2018 at 8:35
  • As I wrote: If it's not custom rules, the default rules got messed up. For whatever reason. So have a look at these (/lib/udev). If you can't see anything obvious, debug, then you'll know which rules get executed, instead of having to guess.
    – dirkt
    Aug 6, 2018 at 9:09
  • So something is completely restarting the block device scanning operation, both in /dev/sda and /dev/sdb. Any error messages in dmesg you didn't tell us? Anything you have installed that could shut down hardware and put it up again? Does this also happen if no USB device is plugged in? Does it happen no matter which port the USB device is plugged in? Does it happen both for USB2 and USB3? (I'm suspecting some hardware glitch that somehow causes the rescan). Any loose cables somewhere?
    – dirkt
    Aug 6, 2018 at 12:10
  • Any error messages in dmesg you didn't tell us? No, there are no error. messages in dmesg. Anything you have installed that could shut down hardware and put it up again? not that I know of. Does this also happen if no USB device is plugged in? No. Does it happen no matter which port the USB device is plugged in? Yes, i tried all Ports. Does it happen both for USB2 and USB3? Yes, USB2&USB3. It also happens an several Servers. Alls this servers has the same System installed. Suse Linux Enterprise Server 12 SP2 - Kernel: 4.4.59-92.17-default
    – Danloc
    Aug 6, 2018 at 13:03

2 Answers 2

Reset to default
1

Partial answer:

I still don't know what causes this, but I can point you to the place(s) in the udevd debug log where it happens.

Namely, you get "inotify close" events both for /dev/sda and /dev/sdb: 

2018-08-06T16:20:28.414845+02:00 SLES12RDX systemd-udevd[429]: inotify event: 8 for /dev/sda
2018-08-06T16:20:28.416130+02:00 SLES12RDX systemd-udevd[429]: device /dev/sda closed, synthesising 'change'


2018-08-06T16:20:28.556561+02:00 SLES12RDX systemd-udevd[429]: inotify event: 8 for /dev/sdb
...
2018-08-06T16:20:28.566988+02:00 SLES12RDX systemd-udevd[429]: seq 2123 queued, 'remove' 'block'


2018-08-06T16:20:58.630120+02:00 SLES12RDX systemd-udevd[429]: inotify event: 8 for /dev/sda
...
2018-08-06T16:20:58.631408+02:00 SLES12RDX systemd-udevd[429]: device /dev/sda closed, synthesising 'change'

etc., etc., and the udev synthesizes "change" events, which cause the multiple rescans of the whole block device and all partitions.

I've never seen anything like this. inotify is for monitoring file system events, so it looks like these come from userspace.

I don't know how to track down what application causes this. Maybe file a bug on the udev bugtracking site, and see if they have any ideas how to track it down further?

Improve this answer
0

There are many udev events recieved, after pluggin the usb device. After a 15 - 20 seconds cycle the events looks like the device was plugged again. Output from udevadm monitor

KERNEL[249779.569894] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda (block)
KERNEL[249779.569949] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda1 (block)
KERNEL[249779.570075] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda2 (block)
KERNEL[249779.570123] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda5 (block)
KERNEL[249779.570245] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda6 (block)
KERNEL[249779.570296] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda7 (block)
UDEV  [249779.643535] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda (block)
UDEV  [249779.646294] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda1 (block)
UDEV  [249779.647536] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda5 (block)
UDEV  [249779.647693] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda7 (block)
UDEV  [249779.649616] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda2 (block)
UDEV  [249779.651444] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda6 (block)
KERNEL[249781.213738] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb (block)
KERNEL[249781.233201] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb (block)
KERNEL[249781.233309] add      /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb/sdb1 (block)
UDEV  [249781.495520] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb (block)
UDEV  [249781.604649] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb (block)
UDEV  [249781.712323] add      /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb/sdb1 (block)
KERNEL[249809.678044] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda (block)
KERNEL[249809.678154] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda1 (block)
KERNEL[249809.678211] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda2 (block)
KERNEL[249809.678292] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda5 (block)
KERNEL[249809.678410] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda6 (block)
KERNEL[249809.678455] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda7 (block)
UDEV  [249809.750877] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda (block)
UDEV  [249809.754139] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda1 (block)
UDEV  [249809.754325] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda5 (block)
UDEV  [249809.756127] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda2 (block)
UDEV  [249809.756270] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda7 (block)
UDEV  [249809.756438] change   /devices/pci0000:00/0000:00:1f.2/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda6 (block)
KERNEL[249809.788887] remove   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb/sdb1 (block)
KERNEL[249809.793174] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb (block)
KERNEL[249809.793338] add      /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb/sdb1 (block)
UDEV  [249809.795254] remove   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb/sdb1 (block)
UDEV  [249810.274418] change   /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb (block)
UDEV  [249810.391165] add      /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.6/2-1.6:1.0/host4/target4:0:0/4:0:0:0/block/sdb/sdb1 (block)

I activated the debug option in udev conf. The output from udev in /var/log/messages is now to huge, to post it here or seriously debug.

But this udev rule is 'fired' several times:

/usr/lib/udev/rules.d/60-persistent-storage.rules

and this error appears for sda and sdb. sda is not a USB device, its my HHD. Im not a expert in udev so i don't know, if that is 'normal':

2018-08-06T12:14:51.303326+02:00 SLES12RDX systemd-udevd[2977]: PROGRAM '/sbin/multipath -u -i sda' /usr/lib/udev/rules.d/56-multipath.rules:25
2018-08-06T12:14:51.303516+02:00 SLES12RDX systemd-udevd[2978]: starting '/sbin/multipath -u -i sda'
2018-08-06T12:14:51.365860+02:00 SLES12RDX systemd-udevd[2977]: '/sbin/multipath -u -i sda'(out) 'sda is not a valid multipath device path'
2018-08-06T12:14:51.366082+02:00 SLES12RDX systemd-udevd[2977]: Process '/sbin/multipath -u -i sda' failed with exit code 1.

2018-08-06T12:14:51.441033+02:00 SLES12RDX systemd-udevd[2989]: PROGRAM '/sbin/multipath -u -i sdb' /usr/lib/udev/rules.d/56-multipath.rules:25
2018-08-06T12:14:51.441168+02:00 SLES12RDX systemd-udevd[2990]: starting '/sbin/multipath -u -i sdb'
2018-08-06T12:14:51.468823+02:00 SLES12RDX systemd-udevd[2989]: '/sbin/multipath -u -i sdb'(out) 'sdb is not a valid multipath device path'
2018-08-06T12:14:51.469024+02:00 SLES12RDX systemd-udevd[2989]: Process '/sbin/multipath -u -i sdb' failed with exit code 1.
Improve this answer

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .