HPLIP

  1. Bug #341827
  2. Comment #17

Comment 17 for bug 341827

Revision history for this message
In , Ted (ted-redhat-bugs) wrote :

Description of problem:

Print jobs occasionally fail to print to a USB-connected HP PhotoSmart 2575,
requiring a cupsrestart to complete the job.

Versions of various components which have exhibited the problem:

$ uname -a
Linux topaz.bugfinder.co.uk 2.6.27.25-170.2.72.fc10.i686 #1 SMP Sun Jun 21 19:03:24 EDT 2009 i686 i686 i386 GNU/Linux

$ rpm -q cups glibc hal hplip hpijs foomatic
cups-1.3.10-5.fc10.i386
glibc-2.9-3.i686
hal-0.5.12-14.20081027git.fc10.i386
hplip-2.8.12-6b.fc10.i386
hpijs-2.8.12-6b.fc10.i386
foomatic-3.0.2-70.fc10.i386

Occasionally, and there doesn't appear to be a specific way of triggering the bug as far as I can tell, a submitted print job will stall in the print queue, usually after at least one page of a multi-page job has printed.

At that point, in the syslog, we usually see the following set of messages:

Aug 4 11:30:55 topaz kernel: usblp0: removed
Aug 4 11:30:55 topaz hal_lpadmin: Running hal_lpadmin
Aug 4 11:30:56 topaz hal_lpadmin: hal_lpadmin triggered by usblp kernel module
Aug 4 11:30:56 topaz hal_lpadmin: Using device ID from HAL database entry
Aug 4 11:30:56 topaz hal_lpadmin: remove
Aug 4 11:30:56 topaz hal_lpadmin: Found configured printer: Photosmart_2570_series
Aug 4 11:31:26 topaz kernel: usb 1-7: reset high speed USB device using ehci_hcd and address 3
Aug 4 11:31:26 topaz kernel: usblp0: USB Bidirectional printer dev 3 if 1 alt 0 proto 2 vid 0x03F0 pid 0x4E11
Aug 4 11:31:26 topaz kernel: usb 1-7: usbfs: process 10998 (hp) did not claim interface 1 before use
Aug 4 11:31:26 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 1024: bulk_write failed buf=0xbf988b3c size=512 len=-16: No data available
Aug 4 11:31:26 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 1386: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: No data available
Aug 4 11:31:26 topaz kernel: usb 1-7: usbfs: process 10905 (hp) did not claim interface 1 before use
Aug 4 11:31:26 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 726: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Aug 4 11:31:26 topaz hal_lpadmin: Running hal_lpadmin
Aug 4 11:31:27 topaz hal_lpadmin: hal_lpadmin triggered by usblp kernel module
Aug 4 11:31:27 topaz hal_lpadmin: Using device ID from HAL database entry
Aug 4 11:31:27 topaz hal_lpadmin: add
Aug 4 11:31:27 topaz hal_lpadmin: URIs: ['hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY', 'usb://HP/Photosmart%202570%20series?serial=MY65T112BM04DY', 'hal:///org/freedesktop/Hal/devices/usb_device_3f0_4e11_MY65T112BM04DY_if1_printer_MY65T112BM04DY']
Aug 4 11:31:27 topaz hal_lpadmin: HPLIP Fax URIs: None
Aug 4 11:31:27 topaz hal_lpadmin: Not adding printer: Photosmart_2570_series already exists
Aug 4 11:31:36 topaz kernel: usb 1-7: usbfs: process 10905 (hp) did not claim interface 0 before use
Aug 4 11:31:36 topaz kernel: usb 1-7: usbfs: process 11008 (hp) did not claim interface 1 before use
Aug 4 11:31:36 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 1024: bulk_write failed buf=0xbf988b3c size=512 len=-16: Device or resource busy
Aug 4 11:31:36 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 1386: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or resource busy
Aug 4 11:31:36 topaz kernel: usb 1-7: usbfs: process 10905 (hp) did not claim interface 1 before use
Aug 4 11:31:36 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 726: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Aug 4 11:31:46 topaz kernel: usb 1-7: usbfs: process 11040 (hp) did not claim interface 1 before use
Aug 4 11:31:46 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 1024: bulk_write failed buf=0xbf988b3c size=512 len=-16: Device or resource busy
Aug 4 11:31:46 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 1386: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or resource busy

It should be noted that when I originally found this problem a while ago, the syslog filled up at the rate of several gigabytes an hour as all the "hpmud" messages were not rate-limited.

To reduce the extent to which the bug could flatten my log partition, I patched the hplip source code with:

$ more hplip-2.8.12-hpmud-bugthrottle.patch
diff -uNr hplip-2.8.12.orig/io/hpmud/hpmudi.h hplip-2.8.12/io/hpmud/hpmudi.h
--- hplip-2.8.12.orig/io/hpmud/hpmudi.h 2008-12-17 20:41:08.000000000 +0000
+++ hplip-2.8.12/io/hpmud/hpmudi.h 2009-06-07 10:23:56.000000000 +0100
@@ -60,6 +60,9 @@
 #define _STRINGIZE(x) #x
 #define STRINGIZE(x) _STRINGIZE(x)

+// Impose a throttle on any BUG related error messages to avoid disk overflow ...
+#define HPMUD_BUG_THROTTLE 10000000 /* microseconds */
+#define HPMUD_BUG_SEC_THROTTLE 10 /* seconds */
 #define BUG(args...) syslog(LOG_ERR, __FILE__ " " STRINGIZE(__LINE__) ": " args)

 #ifdef HPMUD_DEBUG
diff -uNr hplip-2.8.12.orig/io/hpmud/musb.c hplip-2.8.12/io/hpmud/musb.c
--- hplip-2.8.12.orig/io/hpmud/musb.c 2008-12-17 20:41:08.000000000 +0000
+++ hplip-2.8.12/io/hpmud/musb.c 2009-06-07 10:27:59.000000000 +0100
@@ -125,6 +125,7 @@
       {
          /* This retry is necessary for lj1000 and lj1005. des 12/12/07 */
          BUG("get_string_descriptor zero result, retrying...");
+ sleep(HPMUD_BUG_SEC_THROTTLE);
          continue;
       }
       break;
@@ -723,6 +724,7 @@
    {
       /* Following retry is necessary for a firmware problem with PS A420 products. DES 4/17/07 */
       BUG("invalid deviceid wIndex=%x, retrying wIndex=%x: %m\n", interface, interface << 8);
+ sleep(HPMUD_BUG_SEC_THROTTLE);
       rlen = usb_control_msg(hd,
              USB_ENDPOINT_IN | USB_TYPE_CLASS | USB_RECIP_INTERFACE, /* bmRequestType */
              USB_REQ_GET_STATUS, /* bRequest */
$

The one extra piece of diagnostic is that a restart of CUPS is seemingly sufficient the fix the problem. Usually, this then means that the stuck print job is resubmitted to the printer and usually then completes Ok.

At that point we get the following in syslog:

...
Aug 4 11:32:16 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 726: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Aug 4 11:32:26 topaz kernel: usb 1-7: usbfs: process 11054 (hp) did not claim interface 1 before use
Aug 4 11:32:26 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 1024: bulk_write failed buf=0xbf988b3c size=512 len=-16: Device or resource busy
Aug 4 11:32:26 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 1386: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or resource busy
Aug 4 11:32:26 topaz kernel: usb 1-7: usbfs: process 10905 (hp) did not claim interface 1 before use
Aug 4 11:32:26 topaz Photosmart_2570_series?serial=MY65T112BM04DY: io/hpmud/musb.c 726: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Aug 4 11:32:34 topaz sudo: ejtr : TTY=pts/3 ; PWD=/home/ejtr ; USER=root ; COMMAND=/usr/local/bin/cupsrestart
Aug 4 11:32:35 topaz kernel: usblp0: removed
Aug 4 11:32:35 topaz hal_lpadmin: Running hal_lpadmin
Aug 4 11:32:36 topaz hal_lpadmin: hal_lpadmin triggered by usblp kernel module
Aug 4 11:32:36 topaz hal_lpadmin: Using device ID from HAL database entry
Aug 4 11:32:36 topaz hal_lpadmin: remove
Aug 4 11:32:36 topaz hal_lpadmin: Found configured printer: Photosmart_2570_series
Aug 4 11:36:32 topaz syslog-ng[2040]: Log statistics; processed='center(queued)=4035', processed='center(received)=1567', processed='destination(d_boot)=0', processed='destination(d_auth)=8', processed='destination(d_debug)=1372', processed='destination(d_cron)=40', processed='destination(d_mlal)=0', processed='destination(d_errors)=1151', processed='destination(d_mesg)=1138', processed='destination(d_smoothwall)=195', processed='destination(d_cons)=0', processed='destination(d_spol)=0', processed='destination(d_mail)=131', processed='source(s_remote)=195', processed='source(s_sys)=1372'

I note that F11 has a much more recent version of hplip, so I may well try backporting that to F10 to see whether the issue is resolved. At the moment, I presume the bug to be in hplip, but it may well be that the real problem is in the usb drivers in the kernel itself.