udev rules wrongly match on monitor hub, wrong invocation of systemd unit, changes config files in udev rules

Bug #1433557 reported by Andreas Schultz
22
This bug affects 4 people
Affects Status Importance Assigned to Milestone
HPLIP
Fix Released
Undecided
Unassigned
hplip (Ubuntu)
Fix Released
High
Unassigned

Bug Description

During boot, systemd-udev-settle.service failes causing a 3min boot delay.

Journal report this:
> root@alice:~# journalctl -u systemd-udev-settle
> -- Logs begin at Wed 2015-03-18 12:38:16 CET, end at Wed 2015-03-18 12:47:32 CET. --
> Mar 18 12:38:16 alice systemd[1]: Starting udev Wait for Complete Device Initialization...
> Mar 18 12:41:16 alice systemd[1]: systemd-udev-settle.service start operation timed out. Terminating.
> Mar 18 12:41:16 alice systemd[1]: Failed to start udev Wait for Complete Device Initialization.
> Mar 18 12:41:16 alice systemd[1]: Unit systemd-udev-settle.service entered failed state.
> Mar 18 12:41:16 alice systemd[1]: systemd-udev-settle.service failed.
> Mar 18 12:41:17 alice systemd[1]: Starting udev Wait for Complete Device Initialization...
> Mar 18 12:41:18 alice systemd[1]: Started udev Wait for Complete Device Initialization.

The dmesg output arround that time is:

> [ 8.537560] Adding 16723964k swap on /dev/sda4. Priority:-1 extents:1 across:16723964k FS
> [ 9.559871] input: ST LIS3LV02DL Accelerometer as /devices/platform/lis3lv02d/input/input23
> [ 189.205551] Bluetooth: Core ver 2.20
> [ 189.205565] NET: Registered protocol family 31

ProblemType: Bug
DistroRelease: Ubuntu 15.04
Package: dbus 1.8.12-1ubuntu3
ProcVersionSignature: Ubuntu 3.19.0-9.9-generic 3.19.1
Uname: Linux 3.19.0-9-generic x86_64
NonfreeKernelModules: fglrx
ApportVersion: 2.16.2-0ubuntu3
Architecture: amd64
CurrentDesktop: XFCE
Date: Wed Mar 18 12:51:08 2015
SourcePackage: dbus
UpgradeStatus: Upgraded to vivid on 2015-03-02 (15 days ago)

Related branches

Revision history for this message
Andreas Schultz (aschultz) wrote :
tags: added: systemd-boot
Revision history for this message
Didier Roche-Tolomelli (didrocks) wrote :

It seems then that the accelerometer is taking a long time to initialize, right?

Mind starting a debug boot (systemd.log_level=debug in grub init line) and pasting the journactl -b output so that we get all related logs? Thanks!

Revision history for this message
Andreas Schultz (aschultz) wrote :

journal output attached.

Revision history for this message
Martin Pitt (pitti) wrote :

Can you please try this:

  sudo mv /lib/udev/rules.d/61-accelerometer.rules{,.disabled}

and check if that changes anything? If so, can you please give me the output of

  sudo SYSTEMD_LOG_LEVEL=debug /lib/udev/accelerometer /devices/platform/lis3lv02d/input/input23

? (It was input23 in your log; it could be a different number between boots, though, check in /sys/devices/platform/lis3lv02d/input)

Thanks!

affects: dbus (Ubuntu) → linux (Ubuntu)
Changed in linux (Ubuntu):
status: New → Incomplete
Changed in linux (Ubuntu):
importance: Undecided → Medium
Revision history for this message
Andreas Schultz (aschultz) wrote :

Disabling the udev rules fixed the delay.

Output for command:

  $ sudo SYSTEMD_LOG_LEVEL=debug /lib/udev/accelerometer /devices/platform/lis3lv02d/input/input23
  [sudo] password for aschultz:
  opening accelerometer device /dev/input/event17
  ID_INPUT_ACCELEROMETER_ORIENTATION=undefined

Revision history for this message
Martin Pitt (pitti) wrote :

Thanks. How long does the /lib/udev/accelerometer call take for you? (it should be more or less instantaneous). It seems it takes a lot longer when it runs during boot, so we need some better debugging there.

Could you re-enable /lib/udev/rules.d/61-accelerometer.rules and change it to this:

SUBSYSTEM=="input", ACTION!="remove", ENV{ID_INPUT_ACCELEROMETER}=="1", IMPORT{program}="/usr/bin/strace -fvvtts1024 -o /run/accel.trace /lib/udev/accelerometer %p"

then reboot, and attach /run/accel.trace here?

summary: - systemd-udev-settle.service failes, 3min boot delay
+ systemd-udev-settle.service fails when probing ST LIS3LV02DL
+ Accelerometer , 3min boot delay
Revision history for this message
Andreas Schultz (aschultz) wrote : Re: systemd-udev-settle.service fails when probing ST LIS3LV02DL Accelerometer , 3min boot delay

trace attached.

However, the trace shows that it existed almost instantly and normally. So I disabled the udev rule again and reboot. This time around it did again end up with the boot wait. So it seems that the accel udev rule is only a coincident.

Revision history for this message
Andreas Schultz (aschultz) wrote :

Got some more time to poke around the system. If did change the ExecStart in /lib/systemd/system/systemd-udevd.service to:

  ExecStart=/lib/systemd/systemd-udevd --debug

`journalctl -u systemd-udevd` now contains this:

  Apr 01 13:56:58 alice systemd-udevd[424]: worker [458] /devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.4/3-1.4.3 is taking a long time
  Apr 01 13:56:58 alice systemd-udevd[424]: worker [459] /devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.4/3-1.4.4 is taking a long time
  Apr 01 13:56:58 alice systemd-udevd[424]: worker [473] /devices/pci0000:00/0000:00:1d.0/usb4/4-1/4-1.6 is taking a long time

Those devices map to these usb devices:
  Bus 004 Device 004: ID 03f0:231d Hewlett-Packard 4 GB Flash Drive
  Bus 003 Device 010: ID 0a5c:2101 Broadcom Corp. BCM2045 Bluetooth
  Bus 003 Device 008: ID 03f0:2514 Hewlett-Packard

The Notebook is a HP EliteBook 8560w with integrated WLAN/Bluetooth.

I'm going to attach the systemd-udevd journal and lsusb -vvv output

Revision history for this message
Andreas Schultz (aschultz) wrote :
Revision history for this message
Andreas Schultz (aschultz) wrote :
Revision history for this message
Martin Pitt (pitti) wrote :

Ah-haa! For the first two workers I found these gems in the log:

Apr 01 13:58:57 alice systemd-udevd[458]: timeout '/bin/sh -c 'if [ -f /usr/bin/systemctl ]; then /usr/bin/systemctl --no-block start hplip-printer@003:006.service; else /usr/bin/nohup /usr/bin/hp-config_usb_printer 003:006 ; fi &''
Apr 01 13:58:57 alice systemd-udevd[458]: '/bin/sh -c 'grep -q ^#hpaio /etc/sane.d/dll.conf;if [ $? -eq 0 ];then sed -i -e s/^#hpaio/hpaio/ /etc/sane.d/dll.conf;else grep -q ^hpaio /etc/sane.d/dll.conf;if [ $? -ne 0 ];then echo hpaio >>/etc/sane.d/dll.conf;fi;fi'' [5784] exit with return code 0

sed'ing and writing files to /etc/ in udev rules is evil, bad, and wrong. also, calling systemctl in an udev rule is bound to fail, this should at least be ENV{SYSTEMD_WANTS}+="hplip-printer@003:006.service".

It seems you don't even have a HP printer, do you? Or is this

   Bus 003 Device 006: ID 03f0:2514 Hewlett-Packard

actually a printer in disguise? (lsusb says that it's a hub). If it's a printer, could you check if turning it off makes a difference?

Could you please check if moving /lib/udev/rules.d/56-hpmud.rules aside helps?

summary: - systemd-udev-settle.service fails when probing ST LIS3LV02DL
- Accelerometer , 3min boot delay
+ systemd-udev-settle.service times out on hplip rules
affects: linux (Ubuntu) → hplip (Ubuntu)
Changed in hplip (Ubuntu):
importance: Medium → High
Revision history for this message
Andreas Schultz (aschultz) wrote : Re: systemd-udev-settle.service times out on hplip rules

No HP printer in disguise, this

   Bus 003 Device 006: ID 03f0:2514 Hewlett-Packard

is a USB hub integrated into a HP ZR22w monitor.

Disabling /lib/udev/rules.d/56-hpmud.rules solved the problem, no delay anymore.

Revision history for this message
Till Kamppeter (till-kamppeter) wrote :

To the HPLIP developers at HP: Please make HPLIP more friendly to systemd-based distributions. Especially take into account comment #11.

Revision history for this message
Martin Pitt (pitti) wrote :

Thanks Andreas for confirming. I suggest you leave these rules disabled for now, you don't need them anyway.

summary: - systemd-udev-settle.service times out on hplip rules
+ udev rules wrongly match on monitor hub, wrong invocation of systemd
+ unit, changes config files in udev rules
Changed in hplip (Ubuntu):
status: Incomplete → Confirmed
Revision history for this message
Sanjay Kumar (sanjay-kumar14) wrote :

This issue is fixed in hplip-3.15.6.

Changed in hplip:
status: New → Fix Released
Martin Pitt (pitti)
Changed in hplip (Ubuntu):
status: Confirmed → In Progress
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package hplip - 3.15.6-0ubuntu1

---------------
hplip (3.15.6-0ubuntu1) wily; urgency=low

  * New upstream release
     - Added support for HP DeskJet 2130/2132/2546B/2546P/2546R/3630/3632
       All-in-One printer, HP OfficeJet 57444 e-All-in-One
     - Fixed: Error message is displayed while running "hp-diagnose_queues"
       in a terminal.
     - Fixed: UDEV rules wrongly match on monitor hub, wrong invocation of
       systemd unti, changes confi files in UDEV rules (LP: #1433557).
     - Fixed: hp-setup creates spurious cupsd process (LP: #1438456).
  * debian/patches/musb-c-do-not-crash-on-usb-failure.patch,
    debian/patches/pcardext-python3-workaround-upstream.patch,
    debian/patches/hp-plugin-download-fix.patch: Updated for new upstream
    code.

 -- Till Kamppeter <email address hidden> Thu, 11 Jun 2015 19:08:00 -0300

Changed in hplip (Ubuntu):
status: In Progress → Fix Released
Revision history for this message
Till Kamppeter (till-kamppeter) wrote :

pitti, this bug got automatically closed because the HPLIP developers at HP are claiming that the new upstream version fixes this bug. Please check whether this is really the case and whether your intended fix is different to the one applied by HP.

Revision history for this message
Martin Pitt (pitti) wrote :

I checked the diff, and the generic "match all HP devices" rule was restricted to only particular USB interfaces, which ought to fix the "matches on HP USB hub" problem. The sed'ing is also gone. Thanks!

Would be nice if Andreas could confirm that all is well with this version.

Revision history for this message
Jason Gunthorpe (jgunthorpe) wrote :

I hit this problem as well, booting on my system hangs for three minutes waiting for udev to settle. I have a HP keyboard.

Booting without the keyboard plugged in, or removing the hplip package solves the problem.

hplip version 3.15.2-0ubuntu4.1

$ lsusb
Bus 001 Device 002: ID 03f0:0024 Hewlett-Packard KU-0316 Keyboard

$ sudo systemd-analyze blame
       3min 40ms systemd-udev-settle.service

$ journalctl | grep -i udev
Jun 25 14:19:32 test-MSH87TN-00 systemd-udevd[265]: worker [283] /devices/pci0000:00/0000:00:14.0/usb1/1-1 is taking a long time
Jun 25 14:19:32 test-MSH87TN-00 systemd-udevd[265]: worker [285] /devices/pci0000:00/0000:00:14.0/usb1/1-3 is taking a long time
Jun 25 14:21:32 test-MSH87TN-00 systemd[1]: systemd-udev-settle.service start operation timed out. Terminating.
Jun 25 14:21:32 test-MSH87TN-00 systemd[1]: Failed to start udev Wait for Complete Device Initialization.
Jun 25 14:21:32 test-MSH87TN-00 systemd[1]: Unit systemd-udev-settle.service entered failed state.
Jun 25 14:21:32 test-MSH87TN-00 systemd[1]: systemd-udev-settle.service failed.
Jun 25 14:21:33 test-MSH87TN-00 systemd-udevd[283]: timeout '/bin/sh -c 'if [ -f /usr/bin/systemctl ]; then /usr/bin/systemctl --no-block start hplip-printer@001:002.service; else /usr/bin/nohup /usr/bin/hp-config_usb_printer 001:002 ; fi &''
Jun 25 14:21:33 test-MSH87TN-00 systemd-udevd[283]: timeout '/bin/sh -c 'grep -q ^#hpaio /etc/sane.d/dll.conf;if [ $? -eq 0 ];then sed -i -e s/^#hpaio/hpaio/ /etc/sane.d/dll.conf;else grep -q ^hpaio /etc/sane.d/dll.conf;if [ $? -ne 0 ];then echo hpaio >>/etc/sane.d/dll.conf;fi;fi''
Jun 25 14:21:33 test-MSH87TN-00 systemd-udevd[283]: slow: '/bin/sh -c 'grep -q ^#hpaio /etc/sane.d/dll.conf;if [ $? -eq 0 ];then sed -i -e s/^#hpaio/hpaio/ /etc/sane.d/dll.conf;else grep -q ^hpaio /etc/sane.d/dll.conf;if [ $? -ne 0 ];then echo hpaio >>/etc/sane.d/dll.conf;fi;fi'' [1011]
Jun 25 14:21:33 test-MSH87TN-00 systemd-udevd[285]: timeout '/bin/sh -c 'if [ -f /usr/bin/systemctl ]; then /usr/bin/systemctl --no-block start hplip-printer@001:003.service; else /usr/bin/nohup /usr/bin/hp-config_usb_printer 001:003 ; fi &''
Jun 25 14:21:33 test-MSH87TN-00 systemd-udevd[285]: timeout '/bin/sh -c 'grep -q ^#hpaio /etc/sane.d/dll.conf;if [ $? -eq 0 ];then sed -i -e s/^#hpaio/hpaio/ /etc/sane.d/dll.conf;else grep -q ^hpaio /etc/sane.d/dll.conf;if [ $? -ne 0 ];then echo hpaio >>/etc/sane.d/dll.conf;fi;fi''
Jun 25 14:21:33 test-MSH87TN-00 systemd-udevd[285]: slow: '/bin/sh -c 'grep -q ^#hpaio /etc/sane.d/dll.conf;if [ $? -eq 0 ];then sed -i -e s/^#hpaio/hpaio/ /etc/sane.d/dll.conf;else grep -q ^hpaio /etc/sane.d/dll.conf;if [ $? -ne 0 ];then echo hpaio >>/etc/sane.d/dll.conf;fi;fi'' [1012]

Revision history for this message
goutam (goutamkk) wrote :

Hi Jason,

This issue as been fixed in hplip 3.15.6 version. Can you please install the latest hplip-3.15.6 by downloading the package 'hplip-3.15.6.run' from http://hplipopensource.com/hplip-web/gethplip.html and run command 'sh hplip-3.15.6.run' to install.

Thanks,
Goutam

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.