[REGRESSION] Services asked for by UDEV do not get triggered

[Till Kamppeter]

The packages system-config-printer-udev and ippusbxd are installed, having the following UDEV rule files:

/lib/udev/rules.d/70-printers.rules

----------
# Low-level USB device add trigger
ACTION=="add", SUBSYSTEM=="usb", ENV{DEVTYPE}=="usb_device", ENV{ID_USB_INTERFACES}=="*:0701??:*", TAG+="udev-configure-printer", TAG+="systemd", PROGRAM="/bin/systemd-escape --template=udev-configure-printer@.service %p", ENV{SYSTEMD_WANTS}+="%c"
# Low-level USB device remove trigger
ACTION=="remove", SUBSYSTEM=="usb", ENV{DEVTYPE}=="usb_device", ENV{ID_USB_INTERFACES}=="*:0701*:*", RUN+="udev-configure-printer remove %p"
----------

/lib/udev/rules.d/55-ippusbxd.rules

----------
# ippusbxd udev rules file

ACTION=="add", SUBSYSTEM=="usb", ENV{DEVTYPE}=="usb_device" ENV{ID_USB_INTERFACES}=="*:070104:*", OWNER="root", GROUP="lp", MODE="0664", PROGRAM="/bin/systemd-escape --template=ippusbxd@.service $env{BUSNUM}:$env{DEVNUM}", ENV{SYSTEMD_WANTS}+="%c"
----------

If I turn on an appropriate printer (USB, supporting IPP-over-USB, here the HP DeskJet 2540) I get in the output of "udevadm monitor --environment"

----------
UDEV [17527.514150] add /devices/pci0000:00/0000:00:14.0/usb2/2-2 (usb)
ACTION=add
BUSNUM=002
DEVNAME=/dev/bus/usb/002/033
DEVNUM=033
DEVPATH=/devices/pci0000:00/0000:00:14.0/usb2/2-2
DEVTYPE=usb_device
DRIVER=usb
ID_BUS=usb
ID_MODEL=Deskjet_2540_series
ID_MODEL_ENC=Deskjet\x202540\x20series
ID_MODEL_ID=c211
ID_REVISION=0100
ID_SERIAL=HP_Deskjet_2540_series_BR54BFB02C05XK
ID_SERIAL_SHORT=BR54BFB02C05XK
ID_USB_INTERFACES=:ffcc00:070104:070102:ff0401:
ID_VENDOR=HP
ID_VENDOR_ENC=HP
ID_VENDOR_FROM_DATABASE=Hewlett-Packard
ID_VENDOR_ID=03f0
MAJOR=189
MINOR=160
PRODUCT=3f0/c211/100
SEQNUM=9891
SUBSYSTEM=usb
SYSTEMD_WANTS=ippusbxd@002:033.service udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2\x2d2.service printer.target
TAGS=:udev-configure-printer:systemd:
TYPE=0/0/0
USEC_INITIALIZED=17527513940

UDEV [17527.517724] add /devices/pci0000:00/0000:00:14.0/usb2/2-2/2-2:1.0 (usb)
.MM_USBIFNUM=00
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:14.0/usb2/2-2/2-2:1.0
DEVTYPE=usb_interface
ID_VENDOR_FROM_DATABASE=Hewlett-Packard
INTERFACE=255/204/0
MODALIAS=usb:v03F0pC211d0100dc00dsc00dp00icFFiscCCip00in00
PRODUCT=3f0/c211/100
SEQNUM=9892
SUBSYSTEM=usb
TYPE=0/0/0
USEC_INITIALIZED=17527517478

UDEV [17527.522565] add /devices/pci0000:00/0000:00:14.0/usb2/2-2/2-2:1.2 (usb)
.MM_USBIFNUM=02
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:14.0/usb2/2-2/2-2:1.2
DEVTYPE=usb_interface
ID_VENDOR_FROM_DATABASE=Hewlett-Packard
INTERFACE=255/4/1
MODALIAS=usb:v03F0pC211d0100dc00dsc00dp00icFFisc04ip01in02
PRODUCT=3f0/c211/100
SEQNUM=9895
SUBSYSTEM=usb
TYPE=0/0/0
USEC_INITIALIZED=17527522332

UDEV [17527.523761] add /devices/pci0000:00/0000:00:14.0/usb2/2-2/2-2:1.1 (usb)
.MM_USBIFNUM=01
ACTION=add
DEVPATH=/devices/pci0000:00/0000:00:14.0/usb2/2-2/2-2:1.1
DEVTYPE=usb_interface
DRIVER=usblp
ID_VENDOR_FROM_DATABASE=Hewlett-Packard
INTERFACE=7/1/2
MODALIAS=usb:v03F0pC211d0100dc00dsc00dp00ic07isc01ip02in01
PRODUCT=3f0/c211/100
SEQNUM=9893
SUBSYSTEM=usb
TYPE=0/0/0
USEC_INITIALIZED=17527523500

UDEV [17527.527275] add /devices/pci0000:00/0000:00:14.0/usb2/2-2/2-2:1.1/usbmisc/lp1 (usbmisc)
.MM_USBIFNUM=01
ACTION=add
DEVNAME=/dev/usb/lp1
DEVPATH=/devices/pci0000:00/0000:00:14.0/usb2/2-2/2-2:1.1/usbmisc/lp1
MAJOR=180
MINOR=1
SEQNUM=9894
SUBSYSTEM=usbmisc
USEC_INITIALIZED=17527527175
----------

Here one can see that the UDEV rules files are correct, leading to the correct systemd services being requested

SYSTEMD_WANTS=ippusbxd@002:033.service udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2\x2d2.service printer.target

but neither the service ippusbxd@002:033.service nor the service udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2\x2d2.service get started (note that I have put the .service file for ippusbxd in place by "sudo cp /usr/share/doc/ippusbxd/examples/ippusbxd@.service /lib/systemd/system/").

I can start each of these services manually though:

sudo systemctl start 'udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2\x2d2.service'

sudo systemctl start ippusbxd@002:033.service

In each case ippusbxd gets started for this printer and a print queue auto-created.

What I expect is that the services get automatically started (and that worked in 17.04) so that after plugging in an USB printer I can immediately print as the print queue gets created automatically.

The "udev-configure-printer..." service works for all USB printers, not only IPP-over-USB (it automatically recognizes the printer typ and does an appropriate setup).

This is a regression as we had always automatic setup of USB printers.

[Till Kamppeter (till-kamppeter)]

Some discussion with xnox on IRC helped me to get to a possible cause of the problem:

journalctl -u udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2x2d2.service > journalctl-u.txt

gives (file redirection prevents trimming ;lines to terminal width):

----------
-- Logs begin at Mon 2017-10-09 09:07:44 -03, end at Mon 2017-10-09 12:17:45 -03. --
Oct 09 11:29:17 till-x1carbon systemd[1]: Starting Automatic USB/Bluetooth printer setup (-devices-pci0000:00-0000:00:14.0-usb2-2x2d2)...
Oct 09 11:29:17 till-x1carbon udev-configure-printer[23296]: add /devices/pci0000:00/0000:00:14.0/usb2/2x2d2
Oct 09 11:29:17 till-x1carbon udev-configure-printer[23296]: unable to access /sys/devices/pci0000:00/0000:00:14.0/usb2/2x2d2
Oct 09 11:29:17 till-x1carbon systemd[1]: udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2x2d2.service: Control process exited, code=exited status=1
Oct 09 11:29:17 till-x1carbon systemd[1]: Failed to start Automatic USB/Bluetooth printer setup (-devices-pci0000:00-0000:00:14.0-usb2-2x2d2).
Oct 09 11:29:17 till-x1carbon systemd[1]: udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2x2d2.service: Unit entered failed state.
Oct 09 11:29:17 till-x1carbon systemd[1]: udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2x2d2.service: Failed with result 'exit-code'.
----------

The directory which needs to get accessed by udev-configure-printer is: /sys/devices/pci0000:00/0000:00:14.0/usb2/2-2, note that the second last character is a dash. UDEV/systemd(?) inserts for the %i in the second line of the /lib/systemd/system/udev-configure-printer@.service file: -devices-pci0000:00-0000:00:14.0-usb2-2x2d2, replacing each slash by a dash and the original dash by "x2d" (should it not be "\x2d"? Not sure what gets inserted for the %I in the ExecStart line, but udev-configure-printer ends up with a /sys/devices/pci0000:00/0000:00:14.0/usb2/2x2d2 which it does not find as the "x2d" is not turned back into a dash.

This worked in 17.04 so it is a regression.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Till Kamppeter (till-kamppeter)]

It seems that with a 70-printers.rules as follows at least a correct service name is generated

----------
# Low-level USB device add trigger
ACTION=="add", SUBSYSTEM=="usb", ENV{DEVTYPE}=="usb_device", ENV{ID_USB_INTERFACES}=="*:0701??:*", TAG+="udev-configure-printer", TAG+="systemd", PROGRAM="/bin/systemd-escape --template=udev-configure-printer@.service %p", ENV{SYSTEMD_WANTS}+="'%c'"
# Low-level USB device remove trigger
ACTION=="remove", SUBSYSTEM=="usb", ENV{DEVTYPE}=="usb_device", ENV{ID_USB_INTERFACES}=="*:0701*:*", RUN+="udev-configure-printer remove %p"
----------

Note that in the first rule the systemd-escape command has NO "-p" option and that the %c for ENV{SYSTEMD_WANTS} has extra single quotes. Compared to the original file only these single quotes got added.

After restarting UDEV with

sudo udevadm control --reload

and re-plugging the printer in most cases the service does not get started.

systemctl status 'udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2\x2d2.service' > status.txt

gives something like

----------
● udev-configure-printer@devices-pci0000:00-0000:00:14.0-usb2-2\x2d2.service - Automatic USB/Bluetooth printer setup (devices-pci0000:00-0000:00:14.0-usb2-2\x2d2)
   Loaded: loaded (/lib/systemd/system/udev-configure-printer@.service; static; vendor preset: enabled)
   Active: inactive (dead)
----------

In such a case one can start the service manually with

sudo systemctl start 'udev-configure-printer@-devices-pci0000:00-0000:00:14.0-usb2-2\x2d2.service'

and this starts correctly udev-configure printer which sets up the printer (and starts ippusbxd if needed).

In some very few cases the service actually gets correctly started (and the printer set up) when one plugs the printer, but this happens rarely (can there be some kind of race condition?).

So this only rarely happening automatic start of the printer setup service is now the problem. The escaping seems to be fixed by the extra single quotes.

[Dimitri John Ledkov (xnox)]

This is not critical. The service is started, but the encoding/decoding of the %i name appears to be not round-trip safe.

[Dimitri John Ledkov (xnox)]

Given that the service is oneshot, I need a full output of the journal to see what has happened to said service.

[Dimitri John Ledkov (xnox)]

Could you please record udevmock dump of plugging in and out a USB printer and attach the udevmock file here?

https://www.piware.de/2013/02/umockdev-record-and-mock-hardware-for-debugging-and-testing/

[Till Kamppeter (till-kamppeter)]

I have looked through Pitti's (upstream author) instructions of the tool, ut it seems that it only works on the already running device and that there is no way to capture the startup and shutdown sequences.

I have recorded the main record of the device this way:

till@till-x1carbon:~$ lsusb
[...]
Bus 002 Device 009: ID 03f0:c211 Hewlett-Packard
[...]
till@till-x1carbon:~$ sudo umockdev-record /dev/bus/usb/002/009 > deskjet-2540.umockdev

I have attached the file.

One can record device operations, but only those which can get triggered by a shell command, not those who are triggered by a manual operation on the device (plug/unplug, power-cycle, press button, ...).

Is there a shell command which triggers a shutdown, start-up, or reboot of the printer? Especially one has to take into account that the device keeps only its bus ID and the device ID increments by 1.

@pitti, is there a way to record start-up or shutdown of a USB device?

[Till Kamppeter (till-kamppeter)]

I have tried recording startup and shutdown now by recording with the command "sleep 10" and doing the manual operation (plugging/unplugging USB) during the sleep delay. Unfortunately, it does not work.

For unplugging I did

sudo umockdev-record --ioctl=/dev/bus/usb/002/009=deskjet-2540-ioctl-shutdown.log sleep 10

and unplugged the USB plug right after pressing Enter. After waiting for the command to exit I did not get a deskjet-2540-ioctl-shutdown.log file.

For plugging I did

sudo umockdev-record --ioctl=/dev/bus/usb/002/010=deskjet-2540-ioctl-startup.log sleep 10

with the intention to plug the printer right after issuing the command.

Note that after repugging the printer will appear under Bus:Device 002:010 so I used /dev/bus/usb/002/010. As the printer is still unplugged when issuing the command there is not yet a /dev/bus/usb/002/010 file and the program exists immediately complaining because of that and does not run "sleep 10".

So any help to record start-up and shutdown of a USB device is appreciated.

[Till Kamppeter (till-kamppeter)]

Here is the systemd journal of plugging the printer, taken with

journalctl -o verbose -f 2>&1 | tee systemd-journal-plug.log

After issuing the command (with printer unplugged) I waited some seconds to see that there is no further output happening. Then I plugged the printer and waited for no further output happening again and stopped the command with Ctrl+C. Output is attached.

[Till Kamppeter (till-kamppeter)]

Now I have proceeded as described in the previous comment for unplugging the printer, issuing this command with the printer still plugged:

journalctl -o verbose -f 2>&1 | tee systemd-journal-unplug.log

waited some seconds, unplugged the printer, waited some seconds, Ctrl+C. Output attached.

[Sebastien Bacher (seb128)]

Till, you should perhaps open a bug on systemd upstream on github since it's likely an issue there? There might have a clue about it or people who are available to debug the issue...

[Till Kamppeter (till-kamppeter)]

Reported this bug upstream:

https://github.com/systemd/systemd/issues/7109

[Till Kamppeter (till-kamppeter)]

Now in Bionic the only systemd problem known to me is the quoting/unquoting turnaround problem mentioned here.

In system-config-printer this problem got worked around upstream by calling the systemd service with the simpler bus and device IDs and not with the device path. This works reliably in Bionic and probably also in Artful.

Another, more severe severe systemd problem in Artful was that systemd did not unregister (at least some) USB devices when they got unplugged. This problem went away in Bionic.

So in Bionic I do not have any problems with USB printer auto-setup any more.