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.