[cups-devel] [UNKN] STR #4707: Possible race condition (?) leads to USB backend eating up 100% CPU

Fabian Greffrath noreply at cups.org
Tue Sep 1 05:48:06 PDT 2015


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

DO NOT REPLY TO THIS MESSAGE.  INSTEAD, POST ANY RESPONSES TO THE LINK BELOW.

[STR New]

Hi there,

I have filed this as a bug in the Debian BTS before [1], but I believe it
makes sense to condense all the information I have gathered so far here in
the upstream bug tracker. Information about the printer I use, although I
doubt it makes a difference in this case, can be found below [2].

Well, sometimes it happens that I print a file to a USB-attached printer
and instead of printing, the "usb" process eats up 100% CPU. Nothing else
happens, apart from some GNOME window popping up and asking if my printer
is actually connected. In fact, it is.

This is what strace says the offending "usb" process does all the time:

ioctl(15, USBDEVFS_CLAIMINTERFACE, 0x7fffad353bfc) = -1 EBUSY (Device or
resource busy)

This repeasts endlessly.

If I kill the offensive process by "sudo killall -9 usb", another GNOME
windows pops up and tells me that printing did not
succeed. If I restart printing from my application, then, it succeeds
without any further issues.

Regarding this happening "sometimes": First, this also happened with CUPS
1.x. I just didn't find the time and nerves to report the bug, because "it
sometimes dosn't work" isn't a good bug description to start with. Second,
I suspect that "sometimes" is related to Windows 7 running (or not) as a
guest system in VirtualBox and trying to access the USB ports of my host
system which is running Debian and thus CUPS. I thus suspect that this is a
race condition between the CUPS "usb" backend and Windows 7 from the
VirtualBox trying to access the USB port.

Further on, I believe that the code which causes this is the following in
backend/usb-libusb.c:1515:

  while ((errcode = libusb_claim_interface(printer->handle, number1)) < 0)
  {
    if (errcode != LIBUSB_ERROR_BUSY)
    {
      fprintf(stderr,
              "DEBUG: Failed to claim interface %d for %04x:%04x: %s\n",
              number1, devdesc.idVendor, devdesc.idProduct,
strerror(errno));

      goto error;
    }
  }

So, what it does is trying to claim the USB interface and if the error code
isn't LIBUSB_ERROR_BUSY it busts out. But what if the error code actually
is LIBUSB_ERROR_BUSY? Then the code is dead-locked in this loop and tries
to claim the interface endlessly. I think this is what I see in the strace
output on my system.

Well, it's not that easy. Actually, LIBUSB_ERROR_BUSY is only returned if
the USB interface is already claimed, e.g. by a kernel driver. This is
checked earlier in the code in line 1437: If the return value of
libusb_kernel_driver_active() is 1 then a kernel driver is active and
libusb_detach_kernel_driver() is called. So, it should be impossible for
the interface to be already claimed when the code reaches line 1515 and
enters the llop in question. But, one never knows, and repeatedly calling
libusb_claim_interface() over and over again won't help if the errcode is
LIBUSB_ERROR_BUSY, which is actually never checked for.

Thus, I assume that the attached patch might work, but I am not 100% sure
yet, because, you know, it only happens "sometimes". ;) I also added a
sleep(1) call to prevent this loop from eating up 100% CPU as it currently
does.

However, I am 99% sure that this is the correct approach: The other day, my
printing was hanging again with the "usb" process eating up 100% CPU. It's
process ID was 24901 and so I attached GDB to it. Look what happened:

$ sudo gdb /usr/lib/cups/backend-available/usb --pid 24901
[...]
(gdb) bt
#0  0x00007f7884939c17 in ioctl () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007f78850ad4d1 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#2  0x00007f78850a7950 in libusb_claim_interface () from
/lib/x86_64-linux-gnu/libusb-1.0.so.0
#3  0x00007f78854e0ee8 in open_device (printer=0x7f78856e51c0 <printer>,
verbose=1)
    at usb-libusb.c:1515
#4  find_device (cb=0x7f78854e0900 <print_cb>, data=0x7f7885e3c630) at
usb-libusb.c:942
#5  0x00007f78854e1a98 in print_device (uri=0x7f7885e3c630
"usb://Kyocera/FS-1120D?serial=Q5Y1358476", 
    hostname=<optimized out>, resource=<optimized out>, options=<optimized
out>, print_fd=0, copies=1, 
    argc=6, argv=0x7ffd7b31d838) at usb-libusb.c:220
#6  0x00007f78854df603 in main (argc=6, argv=0x7ffd7b31d838) at usb.c:248

(gdb) frame 3
#3  0x00007f78854e0ee8 in open_device (printer=0x7f78856e51c0 <printer>,
verbose=1)
    at usb-libusb.c:1515
1515	usb-libusb.c: Datei oder Verzeichnis nicht gefunden.

So, it was hanging in line 1515 of usb-libusb.c, just as I suspected.

(gdb) p printer
$1 = (usb_printer_t *) 0x7f78856e51c0 <printer>
(gdb) p *printer
$2 = {device = 0x7f7885e3fde0, conf = 0, origconf = 0, iface = 0, altset =
0, write_endp = 0, 
  read_endp = 1, protocol = 2, usblp_attached = 0, reset_after_job = 0,
quirks = 0, 
  handle = 0x7f7885e43f00}

This was just a test to see if the struct was still intact, all looked
good.

(gdb) p libusb_detach_kernel_driver(printer->handle,
printer->iface)libusb_claim_interface
$3 = 0
(gdb) c
Continuing.

And indeed, it broke the loop and printing continued! So, it makes sense to
check if the error code of libusb_claim_interface() is indeed
LIBUSB_ERROR_BUSY and add another call to libusb_detach_kernel_driver()
if it is. I have no idea, though, why it is possible that the device is
reported busy at this stage, as it is already checked earlier in the code
and clearly *shouldn't* be at this point, but apparently it is possible and
calling libusb_detach_kernel_driver() again is a means to fix this.

Thank you very much for your patience and for considering my patch!

Cheers,

Fabian

[1] https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=791766
[2] The printer is a Kyocera FS-1120D

$ lsusb | grep -i kyocera
Bus 004 Device 017: ID 0482:0407 Kyocera Corp.

$ sudo /usr/lib/cups/backend/usb
DEBUG: Loading USB quirks from "/usr/share/cups/usb".
DEBUG: Loaded 114 quirks.
DEBUG: list_devices
DEBUG: libusb_get_device_list=15
DEBUG2: Printer found with device ID:
ID:FS-1120D;MFG:Kyocera;CMD:PCLXL,PostScript
Emulation,PCL5E,PJL;MDL:FS-1120D;CLS:PRINTER;DES:Kyocera FS-1120D; Device
URI: usb://Kyocera/FS-1120D?serial=Q5Y1358476
direct usb://Kyocera/FS-1120D?serial=Q5Y1358476 "Kyocera FS-1120D" "Kyocera
FS-1120D" "ID:FS-1120D;MFG:Kyocera;CMD:PCLXL,PostScript
Emulation,PCL5E,PJL;MDL:FS-1120D;CLS:PRINTER;DES:Kyocera FS-1120D;" ""

Link: https://www.cups.org/str.php?L4707
Version: 2.0.3
Attachment: https://www.cups.org/strfiles.php/3560/cups-libusb.patch
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.14 (GNU/Linux)
Comment: GPGTools - https://gpgtools.org

iQIcBAEBCgAGBQJV5Z6GAAoJENujp6sI12IjcOAP/RElnXMIrwAouApWs3HLWMIT
74b4o3aDO7gLfpEYthJkHHBCbvoRJcQct+Bx/xz5zQqOm97/DUrtVf2xbhiPc2Xc
zxEp2/oLjHI62TIXw8kfqBA5pOT0xJ4DDXQ++7Z77nZSfNLHJv3TQ5KGXXkrDwoq
5EwwAqjn6gxaxCidW/luDMYvb8TC2rWyPzF/CkZb3KOM3dyn3Qqn623dHGHkEZx3
Oc5GSMKlQXjlp3AJ84w0d0XxTo+19GOmEDxnsblIyHsA8Wm8nqm1gbBZ+aSLIsVx
7Y9Y0qjswULt8y/T82VIPGlLTQufCPnFtxoHBnMFji4qqtshhi39ZTbJNDcojbOq
ri2yZef6ql9em7y2KpKoh8xG6uJeuLyvdMYk2spGl36jhoj5jE5cqE5W2UXBkr5q
vyIAajocYIdLZZ65M613CFwje4cEi4oNw/SQEixW3WZ7AP5ap2shqEnNrMjDtx9O
dc1sgA8beNY6KBz6Ue0vqFUZL12qBQUKdbRs2SWcEZvG8W6DIBOmdNVo4sk0+EWJ
Um227Cxa9+JKwxFA6yO51aZkib8nG2Yr/QTsLM6b9BVWPXgnWIEf1O3OEyH0AbFe
xNHKvUBSbBis2JsV9MnP0s3puKdVqawavmhy490KYcDe41lHTcs72y7Il7I00dg0
ReuO0KzOSEUecnwXOEqo
=7u7e
-----END PGP SIGNATURE-----




More information about the cups mailing list