If you remove the system-config-printer-udev package are you still able to reproduce the problem?

The syslog shows some sort of conflict there for a short while, which is ultimately resolved by the 'device-reconnected' patch which convinces HPLIP that the device handle is no longer valid.

The main problem here seems to be that the printer is disconnecting from the host in the first place.

Do you have any logs which cover the time of the *disconnection*?  The particular line indication it would look like:

usb 3-2: USB disconnect, address 2

(but with different numbers)

The only USB disconnect message I've seen in the last month was apparently when I unplugged my USB mouse at one point:

...
Feb 20 09:51:14 topaz kernel: usb 7-1.2: USB disconnect, address 3
...

$ lsusb 
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 005 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 007 Device 004: ID 05ac:020c Apple, Inc. Extended Keyboard [Mitsumi]
Bus 007 Device 003: ID 0458:0007 KYE Systems Corp. (Mouse Systems) 
Bus 007 Device 002: ID 05ac:1003 Apple, Inc. Hub in Pro Keyboard [Mitsumi, A1048]
Bus 007 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 006 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 009 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 008 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 004: ID 03f0:4e11 Hewlett-Packard PhotoSmart 2570 series
Bus 001 Device 002: ID 07ff:00ff Unknown Portable Hard Drive
$ 


The log snippet previously was from /var/log/messages. I've found the equivalent set of messages from /var/log/debug which contains a little more information using this syslog-ng rule:

$ grep debug /etc/syslog-ng/syslog-ng.conf | grep -v "^#"
destination d_debug { file("/var/log/debug"); };
filter f_filter9   { level(debug..emerg); };
filter f_debugonly { filter(f_filter9); };
log { source(s_sys); filter(f_debugonly); destination(d_debug); };
$ 



...
Feb 17 20:39:13 topaz kernel: usblp0: removed
Feb 17 20:39:51 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 3
Feb 17 20:39:51 topaz kernel: usblp0: USB Bidirectional printer dev 3 if 1 alt 0 proto 2 vid 0x03F0 pid 0x4E11
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5677 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5382 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5382 (hp) did not claim interface 0 before use
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbfabfb64 size=7680 len=-16: No data available
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: No data ava
ilable
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5679 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5382 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbfabfb64 size=7680 len=-16: Device or resource busy
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or r
esource busy
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5680 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5382 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbfabfb64 size=7680 len=-16: Device or resource busy
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or r
esource busy
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5681 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5382 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbfabfb64 size=7680 len=-16: Device or resource busy
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or r
esource busy
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5682 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz kernel: usb 1-4: usbfs: process 5382 (hp) did not claim interface 1 before use
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbfabfb64 size=7680 len=-16: Device or resource busy
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or r
esource busy
Feb 17 20:39:51 topaz hp[5382]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 17 20:39:51 topaz hp[5382]: prnt/backend/hp.c 812: ERROR: device reconnected?
Feb 17 20:39:51 topaz udev-configure-printer: add /devices/pci0000:00/0000:00:1d.7/usb1/1-4/1-4:1.1/usb/lp0
Feb 17 20:39:51 topaz udev-configure-printer: parent devpath is /devices/pci0000:00/0000:00:1d.7/usb1/1-4
Feb 17 20:39:51 topaz udev-configure-printer: MFG:HP MDL:Photosmart 2570 series SERN:MY65T112BM04DY serial:MY65T112BM04DY
Feb 17 20:39:52 topaz kernel: info: ACCEPT: IN= OUT=lo SRC=0000:0000:0000:0000:0000:0000:0000:0001 DST=0000:0000:0000:0000:0000:0000:0000:00
01 LEN=80 TC=0 HOPLIMIT=64 FLOWLBL=0 PROTO=TCP SPT=44686 DPT=631 WINDOW=32752 RES=0x00 SYN URGP=0 
Feb 17 20:39:52 topaz hp[5689]: io/hpmud/pp.c 627: unable to read device-id ret=-1
Feb 17 20:39:53 topaz python: io/hpmud/pp.c 627: unable to read device-id ret=-1
Feb 17 20:40:01 topaz CROND[5695]: (root) CMD (/usr/lib/sa/sa1 -S DISK 1 1)
Feb 17 20:40:07 topaz kernel: info: ACCEPT: IN= OUT=lo SRC=0000:0000:0000:0000:0000:0000:0000:0001 DST=0000:0000:0000:0000:0000:0000:0000:00
01 LEN=80 TC=0 HOPLIMIT=64 FLOWLBL=0 PROTO=TCP SPT=44688 DPT=631 WINDOW=32752 RES=0x00 SYN URGP=0 
Feb 17 20:40:07 topaz udev-configure-printer: SERN fields match
Feb 17 20:40:07 topaz udev-configure-printer: URI match: usb://HP/Photosmart%202570%20series?serial=MY65T112BM04DY
Feb 17 20:40:07 topaz udev-configure-printer: SERN fields match
Feb 17 20:40:07 topaz udev-configure-printer: URI match: hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY
Feb 17 20:46:15 topaz kernel: warning: DROP: IN=eth0 OUT= MAC=ff:ff:ff:ff:ff:ff:00:1e:35:e6:6f:c1:08:00 SRC=0.0.0.0 DST=255.255.255.255 LEN=
328 TOS=0x00 PREC=0x00 TTL=64 ID=1322 PROTO=UDP SPT=68 DPT=67 LEN=308 
Feb 17 20:47:46 topaz sudo:     ejtr : TTY=pts/0 ; PWD=/home/ejtr ; USER=root ; COMMAND=/usr/local/bin/cupsrestart
Feb 17 20:47:47 topaz kernel: usblp0: removed
Feb 17 20:48:36 topaz sudo:     ejtr : TTY=pts/0 ; PWD=/home/ejtr ; USER=root ; COMMAND=/sbin/service cups restart
Feb 17 20:48:37 topaz kernel: info: ACCEPT: IN=eth0 OUT= MAC=00:26:18:cd:b7:d8:00:1c:b3:c6:78:a1:08:00 SRC=172.27.2.106 DST=172.27.2.1 LEN=6
4 TOS=0x00 PREC=0x00 TTL=64 ID=50105 DF PROTO=TCP SPT=57903 DPT=631 WINDOW=65535 RES=0x00 SYN URGP=0 
Feb 17 20:48:37 topaz kernel: info: ACCEPT: IN=eth0 OUT= MAC=00:26:18:cd:b7:d8:00:1c:b3:c6:78:a1:08:00 SRC=172.27.2.106 DST=172.27.2.1 LEN=6
4 TOS=0x00 PREC=0x00 TTL=64 ID=44509 DF PROTO=TCP SPT=57904 DPT=631 WINDOW=65535 RES=0x00 SYN URGP=0 
Feb 17 20:48:37 topaz kernel: info: ACCEPT: IN=eth0 OUT= MAC=00:26:18:cd:b7:d8:00:1c:b3:c6:78:a1:08:00 SRC=172.27.2.106 DST=172.27.2.1 LEN=6
4 TOS=0x00 PREC=0x00 TTL=64 ID=16596 DF PROTO=TCP SPT=57905 DPT=631 WINDOW=65535 RES=0x00 SYN URGP=0 
Feb 17 20:48:37 topaz kernel: info: ACCEPT: IN=eth0 OUT= MAC=00:26:18:cd:b7:d8:00:1c:b3:c6:78:a1:08:00 SRC=172.27.2.106 DST=172.27.2.1 LEN=6
4 TOS=0x00 PREC=0x00 TTL=64 ID=43186 DF PROTO=TCP SPT=57906 DPT=631 WINDOW=65535 RES=0x00 SYN URGP=0 
Feb 17 20:48:40 topaz hp[9388]: prnt/backend/hp.c 838: ERROR: null print job total=0
Feb 17 20:48:43 topaz kernel: info: ACCEPT: IN=eth0 OUT= MAC=00:26:18:cd:b7:d8:00:1c:b3:c6:78:a1:08:00 SRC=172.27.2.106 DST=172.27.2.1 LEN=6
4 TOS=0x00 PREC=0x00 TTL=64 ID=6875 DF PROTO=TCP SPT=57907 DPT=631 WINDOW=65535 RES=0x00 SYN URGP=0 
Feb 17 20:50:01 topaz CROND[9823]: (root) CMD (/usr/lib/sa/sa1 -S DISK 1 1)
Feb 17 20:50:13 topaz kernel: warning: DROP: IN=eth0 OUT= MAC=01:00:5e:00:00:fb:00:1c:b3:c6:78:a1:08:00 SRC=172.27.2.106 DST=224.0.0.251 LEN
=145 TOS=0x00 PREC=0x00 TTL=255 ID=577 PROTO=UDP SPT=5353 DPT=5353 LEN=125 
Feb 17 20:50:17 topaz kernel: info: ACCEPT: IN=eth0 OUT= MAC=00:26:18:cd:b7:d8:00:1c:b3:c6:78:a1:08:00 SRC=172.27.2.106 DST=172.27.2.1 LEN=6
4 TOS=0x00 PREC=0x00 TTL=64 ID=24938 DF PROTO=TCP SPT=57909 DPT=631 WINDOW=65535 RES=0x00 SYN URGP=0 
Feb 17 20:54:29 topaz kernel: info: ACCEPT: IN=eth0 OUT= MAC=00:26:18:cd:b7:d8:00:1c:b3:c6:78:a1:08:00 SRC=172.27.2.106 DST=172.27.2.1 LEN=6
4 TOS=0x00 PREC=0x00 TTL=64 ID=13246 DF PROTO=TCP SPT=57925 DPT=631 WINDOW=65535 RES=0x00 SYN URGP=0 
Feb 17 20:54:30 topaz kernel: nf_ct_tcp: invalid packet ignored IN= OUT= SRC=172.27.2.106 DST=172.27.2.1 LEN=64 TOS=0x00 PREC=0x00 TTL=64 ID
=48820 DF PROTO=TCP SPT=57925 DPT=631 SEQ=3689158530 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 OPT (020405B4010303030101080A3DAC5CF300000000040
20000) 
Feb 17 20:58:15 topaz kernel: warning: DROP: IN=eth0 OUT= MAC=ff:ff:ff:ff:ff:ff:00:1e:35:e6:6f:c1:08:00 SRC=0.0.0.0 DST=255.255.255.255 LEN=
328 TOS=0x00 PREC=0x00 TTL=64 ID=1330 PROTO=UDP SPT=68 DPT=67 LEN=308
...


Another more recent incident has a similar pattern:

...
Feb 22 11:04:40 topaz kernel: usblp0: removed
Feb 22 11:10:01 topaz CROND[6813]: (root) CMD (/usr/lib/sa/sa1 -S DISK 1 1)
Feb 22 11:20:01 topaz CROND[6928]: (root) CMD (/usr/lib/sa/sa1 -S DISK 1 1)
Feb 22 11:30:01 topaz CROND[7042]: (root) CMD (/usr/lib/sa/sa1 -S DISK 1 1)
Feb 22 11:40:01 topaz CROND[7180]: (root) CMD (/usr/lib/sa/sa1 -S DISK 1 1)
Feb 22 11:43:00 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Feb 22 11:46:47 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Feb 22 11:46:47 topaz kernel: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x03F0 pid 0x4E11
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7389 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7306 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7306 (hp) did not claim interface 0 before use
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf965284 size=7680 len=-16: No data available
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: No data available
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7391 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf965284 size=7680 len=-16: Device or resource busy
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or resource busy
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7306 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7392 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf965284 size=7680 len=-16: Device or resource busy
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or resource busy
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7306 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7393 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf965284 size=7680 len=-16: Device or resource busy
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or resource busy
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7306 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7394 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf965284 size=7680 len=-16: Device or resource busy
Feb 22 11:46:47 topaz kernel: usb 1-4: usbfs: process 7306 (hp) did not claim interface 1 before use
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or resource busy
Feb 22 11:46:47 topaz hp[7306]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 22 11:46:47 topaz hp[7306]: prnt/backend/hp.c 812: ERROR: device reconnected?
Feb 22 11:46:47 topaz udev-configure-printer: add /devices/pci0000:00/0000:00:1d.7/usb1/1-4/1-4:1.1/usb/lp0
Feb 22 11:46:47 topaz udev-configure-printer: parent devpath is /devices/pci0000:00/0000:00:1d.7/usb1/1-4
Feb 22 11:46:47 topaz udev-configure-printer: MFG:HP MDL:Photosmart 2570 series SERN:MY65T112BM04DY serial:MY65T112BM04DY
Feb 22 11:46:48 topaz kernel: info: ACCEPT: IN= OUT=lo SRC=0000:0000:0000:0000:0000:0000:0000:0001 DST=0000:0000:0000:0000:0000:0000:0000:0001 LEN=80 TC=0 HOPLIMIT=64 FLOWLBL=0 PROTO=TCP SPT=53353 DPT=631 WINDOW=32752 RES=0x00 SYN URGP=0 
Feb 22 11:46:49 topaz hp[7401]: io/hpmud/pp.c 627: unable to read device-id ret=-1
Feb 22 11:46:49 topaz kernel: warning: DROP: IN=eth0 OUT= MAC= SRC=172.27.2.1 DST=224.0.0.251 LEN=147 TOS=0x00 PREC=0x00 TTL=255 ID=0 DF PROTO=UDP SPT=5353 DPT=5353 LEN=127 
Feb 22 11:46:49 topaz python: io/hpmud/pp.c 627: unable to read device-id ret=-1
Feb 22 11:46:50 topaz kernel: warning: DROP: IN=eth0 OUT= MAC= SRC=172.27.2.1 DST=224.0.0.251 LEN=147 TOS=0x00 PREC=0x00 TTL=255 ID=0 DF PROTO=UDP SPT=5353 DPT=5353 LEN=127 
Feb 22 11:47:03 topaz udev-configure-printer: SERN fields match
Feb 22 11:47:03 topaz udev-configure-printer: URI match: usb://HP/Photosmart%202570%20series?serial=MY65T112BM04DY
Feb 22 11:47:03 topaz udev-configure-printer: SERN fields match
Feb 22 11:47:03 topaz udev-configure-printer: URI match: hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY
Feb 22 11:47:04 topaz kernel: info: ACCEPT: IN= OUT=lo SRC=0000:0000:0000:0000:0000:0000:0000:0001 DST=0000:0000:0000:0000:0000:0000:0000:0001 LEN=80 TC=0 HOPLIMIT=64 FLOWLBL=0 PROTO=TCP SPT=53355 DPT=631 WINDOW=32752 RES=0x00 SYN URGP=0 
Feb 22 11:47:09 topaz sudo:     anne : TTY=pts/0 ; PWD=/home/anne ; USER=root ; COMMAND=/usr/local/bin/cupsrestart
Feb 22 11:47:09 topaz kernel: nf_ct_tcp: invalid RST IN= OUT= SRC=81.187.30.17 DST=172.27.2.1 LEN=40 TOS=0x00 PREC=0x00 TTL=57 ID=0 DF PROTO=TCP SPT=25 DPT=56217 SEQ=1852690657 ACK=0 WINDOW=0 RES=0x00 RST URGP=0 
Feb 22 11:47:10 topaz kernel: nf_ct_tcp: invalid RST IN= OUT= SRC=81.187.30.18 DST=172.27.2.1 LEN=40 TOS=0x00 PREC=0x00 TTL=57 ID=0 DF PROTO=TCP SPT=25 DPT=35628 SEQ=715446468 ACK=0 WINDOW=0 RES=0x00 RST URGP=0 
Feb 22 11:50:01 topaz CROND[7509]: (root) CMD (/usr/lib/sa/sa1 -S DISK 1 1)
... 



FWIW, the cupsrestart program currently contains:

$ cat /usr/local/bin/cupsrestart 
#!/bin/sh

currentid=`id -un`

if [ $currentid = "root" ]; then
	dfltprinter=`lpstat -d | awk '{print $4}'`
	if lpstat -p -d $dfltprinter | grep disable >/dev/null 2>/dev/null; then
		echo Default Printer $dfltprinter disabled, re-enabling ...
		/usr/sbin/cupsenable $dfltprinter
	else
		echo Default Printer $dfltprinter enabled ...
	fi

	echo Restarting CUPS Printer Services ...
	/sbin/service cups status
	/sbin/service cups condrestart
	/sbin/service cups status
	echo sleep 5
else
	( lpstat -t ; echo "==================================" ; ps axfw ) | mail -s "User $currentid about to restart CUPS via $0" root
	sudo $0
	lpstat -t | mail -s "User $currentid restarted CUPS via $0" root
fi
$ 



I've now removed the system-config-printer-udev RPM, and just confirmed that the printer still prints. ( albeit admittedly without a system reboot just yet )

Just in case this contains some more clues, here's the relevant snippets of cups error and access logs, as well as syslog debug for an incident yesterday.

One interesting thing is that access_log shows "Create-Job" coinciding with "kernel: usblp0: removed" some 30 seconds before CUPS attempts to start the renderer - I have no idea if this is normal.

[ejtr@topaz ~]$ sudo cat /var/log/cups/access_log-20100226
localhost - - [25/Feb/2010:22:23:15 +0000] "POST /printers/Photosmart_2570_series HTTP/1.1" 200 292 Create-Job successful-ok
localhost - - [25/Feb/2010:22:23:15 +0000] "POST /printers/Photosmart_2570_series HTTP/1.1" 200 106752 Send-Document successful-ok
localhost - - [25/Feb/2010:22:23:15 +0000] "POST / HTTP/1.1" 200 324 Create-Printer-Subscription successful-ok
localhost - - [25/Feb/2010:22:24:01 +0000] "POST / HTTP/1.1" 200 2389 CUPS-Get-Devices -
localhost - - [25/Feb/2010:22:24:26 +0000] "POST /admin/ HTTP/1.1" 200 156 Resume-Printer client-error-not-found
localhost - - [25/Feb/2010:22:24:42 +0000] "POST /printers/Photosmart_2570_series HTTP/1.1" 200 292 Create-Job successful-ok
localhost - - [25/Feb/2010:22:24:42 +0000] "POST /printers/Photosmart_2570_series HTTP/1.1" 200 64713 Send-Document successful-ok
[ejtr@topaz ~]$ 


...
D [25/Feb/2010:22:23:48 +0000] [Job 698] -----------
D [25/Feb/2010:22:23:48 +0000] [Job 698] New page: %%Page: 1 1
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] Found: %%BeginPageSetup
D [25/Feb/2010:22:23:48 +0000] [Job 698] Inserting option code into "PageSetup" section.
D [25/Feb/2010:22:23:48 +0000] [Job 698] New page found but previous not printed, print it now.
D [25/Feb/2010:22:23:48 +0000] [Job 698] Found: %%Page: 2 2
D [25/Feb/2010:22:23:48 +0000] [Job 698] --> Output goes directly to the renderer now.
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] Starting renderer with command: "gs -sstdout=%stderr  -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -sDEVICE=ijs -sIjsServer=hpijs -sDeviceManufacturer="HEWLETT-PACKARD" -sDeviceModel="deskjet 5600" -dDEVICEWIDTHPOINTS=595 -dDEVICEHEIGHTPOINTS=842 -dDuplex=false -r300 -sIjsParams=Quality:Quality=0,Quality:ColorMode=2,Quality:MediaType=0,Quality:PenSet=2,PS:MediaPosition=7 -dIjsUseOutputFD -sOutputFile=%stdout -_"
D [25/Feb/2010:22:23:48 +0000] [Job 698] Starting process "kid3" (generation 1)
D [25/Feb/2010:22:23:48 +0000] [Job 698] Starting process "kid4" (generation 2)
D [25/Feb/2010:22:23:48 +0000] [Job 698] JCL: %-12345X@PJL
D [25/Feb/2010:22:23:48 +0000] [Job 698] <job data> 
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] Starting process "renderer" (generation 2)
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] -----------
D [25/Feb/2010:22:23:48 +0000] [Job 698] New page: %%Page: 2 2
D [25/Feb/2010:22:23:48 +0000] [Job 698] Found: %%Page: 2 2
D [25/Feb/2010:22:23:48 +0000] [Job 698] --> Output goes to the FIFO buffer now.
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] Found: %%BeginPageSetup
D [25/Feb/2010:22:23:48 +0000] [Job 698] Inserting option code into "PageSetup" section.
D [25/Feb/2010:22:23:48 +0000] [Job 698] New page found but previous not printed, print it now.
D [25/Feb/2010:22:23:48 +0000] [Job 698] Found: %%Page: 3 3
D [25/Feb/2010:22:23:48 +0000] [Job 698] --> Output goes directly to the renderer now.
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] -----------
D [25/Feb/2010:22:23:48 +0000] [Job 698] New page: %%Page: 3 3
D [25/Feb/2010:22:23:48 +0000] [Job 698] Found: %%Page: 3 3
D [25/Feb/2010:22:23:48 +0000] [Job 698] --> Output goes to the FIFO buffer now.
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] Found: %%BeginPageSetup
D [25/Feb/2010:22:23:48 +0000] [Job 698] Inserting option code into "PageSetup" section.
D [25/Feb/2010:22:23:48 +0000] [Job 698] Flushing FIFO.
D [25/Feb/2010:22:23:48 +0000] [Job 698] 
D [25/Feb/2010:22:23:48 +0000] [Job 698] Closing renderer
D [25/Feb/2010:22:23:48 +0000] [Job 698] PAGE: 1 1
D [25/Feb/2010:22:23:48 +0000] [Job 698] STATE: +connecting-to-device
D [25/Feb/2010:22:23:48 +0000] [Job 698] STATE: -connecting-to-device
D [25/Feb/2010:22:23:48 +0000] [Job 698] STATE: -media-empty-error,media-jam-error,hplip.plugin-error,cover-open-error,toner-empty-error,other
D [25/Feb/2010:22:23:48 +0000] [Job 698] PAGE: 2 1
D [25/Feb/2010:22:23:48 +0000] [Job 698] prnt/backend/hp.c 812: ERROR: device reconnected?Error: /ioerror in --showpage--
D [25/Feb/2010:22:23:48 +0000] [Job 698] Operand stack:
D [25/Feb/2010:22:23:48 +0000] [Job 698] 1   true
D [25/Feb/2010:22:23:48 +0000] [Job 698] Execution stack:
D [25/Feb/2010:22:23:48 +0000] [Job 698] %interp_exit   .runexec2   --nostringval--   --nostringval--   --nostringval--   2   %stopped_push   --nostringval--   --nostringval--   --nostringval--   false   1   %stopped_push   1862   1   3   %oparray_pop   1861   1   3   %oparray_pop   1845   1   3   %oparray_pop   1739   1   3   %oparray_pop   --nostringval--   %errorexec_pop   .runexec2   --nostringval--   --nostringval--   --nostringval--   2   %stopped_push   --nostringval--   1745   0   3   %oparray_pop   --nostringval--   --nostringval--
D [25/Feb/2010:22:23:48 +0000] [Job 698] Dictionary stack:
D [25/Feb/2010:22:23:48 +0000] [Job 698] --dict:1162/1684(ro)(G)--   --dict:1/20(G)--   --dict:91/200(L)--
D [25/Feb/2010:22:23:48 +0000] [Job 698] Current allocation mode is local
D [25/Feb/2010:22:23:48 +0000] [Job 698] Last OS error: 32
D [25/Feb/2010:22:23:48 +0000] [Job 698] GPL Ghostscript 8.70: Unrecoverable error, exit code 1
D [25/Feb/2010:22:23:48 +0000] [Job 698] renderer exited with status 1
D [25/Feb/2010:22:23:48 +0000] [Job 698] Possible error on renderer command line or PostScript error. Check options.kid3 exited with status 3
D [25/Feb/2010:22:23:48 +0000] [Job 698] Process is dying with "Error closing renderer
D [25/Feb/2010:22:23:48 +0000] [Job 698] ", exit stat 3
D [25/Feb/2010:22:23:48 +0000] [Job 698] Cleaning up...
D [25/Feb/2010:22:23:48 +0000] [Job 698] Backend returned status 1 (failed)
D [25/Feb/2010:22:23:48 +0000] [Job 698] Printer stopped due to backend errors; please consult the error_log file for details.
D [25/Feb/2010:22:23:48 +0000] [Job 698] End of messages
D [25/Feb/2010:22:23:48 +0000] [Job 698] printer-state=5(stopped)
D [25/Feb/2010:22:23:48 +0000] [Job 698] printer-state-message="/usr/lib/cups/backend/hp failed"
D [25/Feb/2010:22:23:48 +0000] [Job 698] printer-state-reasons=paused
...


Feb 25 22:23:16 topaz kernel: usblp0: removed
Feb 25 22:23:48 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Feb 25 22:23:48 topaz kernel: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x03F0 pid 0x4E11
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14580 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14493 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14493 (hp) did not claim interface 0 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14581 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14493 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14582 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14493 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14583 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14493 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14584 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz kernel: usb 1-4: usbfs: process 14493 (hp) did not claim interface 1 before use
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf862964 size=7680 len=-16: No data available
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: No data av
ailable
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf862964 size=7680 len=-16: Device or resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or 
resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf862964 size=7680 len=-16: Device or resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or 
resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf862964 size=7680 len=-16: Device or resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or 
resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1022: bulk_write failed buf=0xbf862964 size=7680 len=-16: Device or resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 1389: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: Device or 
resource busy
Feb 25 22:23:48 topaz hp[14493]: io/hpmud/musb.c 725: invalid deviceid wIndex=1, retrying wIndex=100: Device or resource busy
Feb 25 22:23:48 topaz hp[14493]: prnt/backend/hp.c 812: ERROR: device reconnected?
Feb 25 22:23:59 topaz python: hp-info[14597]: warning: No display found.
Feb 25 22:23:59 topaz python: hp-info[14597]: error: hp-info -u/--gui requires Qt4 GUI support. Entering interactive mode.
Feb 25 22:24:00 topaz python: hp-info[14597]: warning: Unable to start hp-systray
Feb 25 22:24:00 topaz kernel: usblp0: removed
Feb 25 22:24:01 topaz hp[14632]: io/hpmud/pp.c 627: unable to read device-id ret=-1
Feb 25 22:24:01 topaz kernel: warning: DROP: IN=eth0 OUT= MAC= SRC=172.27.2.1 DST=172.27.3.255 LEN=71 TOS=0x00 PREC=0x00 TTL=64 ID=0 DF PROT
O=UDP SPT=56724 DPT=161 LEN=51 
Feb 25 22:24:01 topaz kernel: lp0: using parport0 (interrupt-driven).
Feb 25 22:24:01 topaz kernel: lp0: console ready
Feb 25 22:24:01 topaz python: io/hpmud/pp.c 627: unable to read device-id ret=-1
Feb 25 22:24:26 topaz sudo:     anne : TTY=pts/0 ; PWD=/home/anne ; USER=root ; COMMAND=/usr/local/bin/cupsrestart
Feb 25 22:24:31 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4

In a further - probably vain - attempt to elicit some more clues, I've revised my old F10 hplip-debug patch - which previously only enabled the HPMUD_DEBUG define - by enabling the HP_DEBUG as well, as in:

[ejtr@topaz SOURCES]$ cat hplip-3.9.8-hp-debug.patch 
diff -uNr hplip-3.9.8.orig/io/hpmud/hpmudi.h hplip-3.9.8/io/hpmud/hpmudi.h
--- hplip-3.9.8.orig/io/hpmud/hpmudi.h	2009-08-04 22:37:25.000000000 +0100
+++ hplip-3.9.8/io/hpmud/hpmudi.h	2010-02-28 09:45:28.000000000 +0000
@@ -55,7 +55,7 @@
 #include "pp.h"
 #endif
 
-// #define HPMUD_DEBUG
+#define HPMUD_DEBUG 1
 
 #define _STRINGIZE(x) #x
 #define STRINGIZE(x) _STRINGIZE(x)
@@ -64,10 +64,10 @@
 //#define BUG(args...) fprintf(stderr, __FILE__ " " STRINGIZE(__LINE__) ": " args)
 
 #ifdef HPMUD_DEBUG
-   #define DBG(args...) syslog(LOG_INFO, __FILE__ " " STRINGIZE(__LINE__) ": " args)
+   #define DBG(args...) syslog(LOG_DEBUG, __FILE__ " " STRINGIZE(__LINE__) ": " args)
 // #define DBG(args...) fprintf(stderr, __FILE__ " " STRINGIZE(__LINE__) ": " args)
    #define DBG_DUMP(data, size) sysdump((data), (size))
-   #define DBG_SZ(args...) syslog(LOG_INFO, args)
+   #define DBG_SZ(args...) syslog(LOG_DEBUG, args)
 #else
    #define DBG(args...)
    #define DBG_DUMP(data, size)
diff -uNr hplip-3.9.8.orig/prnt/backend/hp.c hplip-3.9.8/prnt/backend/hp.c
--- hplip-3.9.8.orig/prnt/backend/hp.c	2010-02-28 09:31:25.000000000 +0000
+++ hplip-3.9.8/prnt/backend/hp.c	2010-02-28 09:45:14.000000000 +0000
@@ -46,7 +46,7 @@
 #include "hpmud.h"
 #include <signal.h>
 
-//#define HP_DEBUG
+#define HP_DEBUG 1
 
 struct pjl_attributes
 {
@@ -68,9 +68,9 @@
 #define BUG(args...) bug(__FILE__ " " STRINGIZE(__LINE__) ": " args)
 
 #ifdef HP_DEBUG
-   #define DBG(args...) syslog(LOG_INFO, __FILE__ " " STRINGIZE(__LINE__) ": " args)
+   #define DBG(args...) syslog(LOG_DEBUG, __FILE__ " " STRINGIZE(__LINE__) ": " args)
    #define DBG_DUMP(data, size) sysdump((data), (size))
-   #define DBG_SZ(args...) syslog(LOG_INFO, args)
+   #define DBG_SZ(args...) syslog(LOG_DEBUG, args)
 #else
    #define DBG(args...)
    #define DBG_DUMP(data, size)
[ejtr@topaz SOURCES]$ 


With this extra debugging in place, the syslog now includes an explicit timestamp for the print Job entering the HP backend. For some sample successful print jobs this morning, the resultant log is as below.

From this sample debug, this strikes me as curious - why is the HP driver removing the usb kernel module upon invocation of the first print job?

...
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 401: removing usblp driver interface=1
Feb 28 09:58:45 topaz kernel: usblp0: removed
...

Anyway, I now hope to have a bit more debug to hand when the printer crashes again.



[ejtr@topaz ~]$ cat Debug/syslog-printer-debug-20100228-trimmedC.txt 
Feb 28 09:09:45 topaz kernel: usb 1-4: new high speed USB device using ehci_hcd and address 4
Feb 28 09:09:45 topaz kernel: usb 1-4: New USB device found, idVendor=03f0, idProduct=4e11
Feb 28 09:09:45 topaz kernel: usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Feb 28 09:09:45 topaz kernel: usb 1-4: Product: Photosmart 2570 series
Feb 28 09:09:45 topaz kernel: usb 1-4: Manufacturer: HP
Feb 28 09:09:45 topaz kernel: usb 1-4: SerialNumber: MY65T112BM04DY
Feb 28 09:09:45 topaz kernel: usb 1-4: configuration #1 chosen from 1 choice
Feb 28 09:09:45 topaz kernel: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x03F0 pid 0x4E11
Feb 28 09:09:45 topaz kernel: usblp0: removed
Feb 28 09:09:45 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Feb 28 09:09:45 topaz kernel: usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x03F0 pid 0x4E11
Feb 28 09:09:55 topaz smbd[1470]: [2010/02/28 09:09:55,  0] printing/print_cups.c:103(cups_connect)
Feb 28 09:09:55 topaz smbd[1471]: [2010/02/28 09:09:55,  0] printing/print_cups.c:103(cups_connect)
Feb 28 09:58:44 topaz hp[23515]: prnt/backend/hp.c 693: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Feb 28 09:58:45 topaz hpijs: io/hpmud/hpmud.c 348: [23522] hpmud_init()
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/hpmud.c 475: [23522,23520,4,4,7,7] hpmud_device_open() uri=hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY iomode=1
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 401: removing usblp driver interface=1
Feb 28 09:58:45 topaz kernel: usblp0: removed
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/hpmud.c 522: [23522] hpmud_get_device_id() dd=1
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/hpmud.c 540: [23522] hpmud_get_device_status() dd=1
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 783: read actual device_status successfully fd=1
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/hpmud.c 522: [23522] hpmud_get_device_id() dd=1
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/hpmud.c 522: [23522] hpmud_get_device_id() dd=1
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/hpmud.c 522: [23522] hpmud_get_device_id() dd=1
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/hpmud.c 522: [23522] hpmud_get_device_id() dd=1
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/hpmud.c 522: [23522] hpmud_get_device_id() dd=1
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:58:45 topaz hpijs[23522]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/hpmud.c 475: [23515,1503,4,4,7,7] hpmud_device_open() uri=hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY iomode=1
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/hpmud.c 590: [23515] hpmud_channel_open() dd=1 name=PRINT
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/musb.c 911: new PRINT channel=2 clientCnt=1 channelCnt=1
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/hpmud.c 522: [23515] hpmud_get_device_id() dd=1
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/hpmud.c 627: [23515] hpmud_channel_write() dd=1 cd=2 buf=0xbf8ef1c4 size=8192 sectime=45
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 09:58:47 topaz hp[23515]: [0000]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
Feb 28 09:58:47 topaz hp[23515]: [0016]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/hpmud.c 627: [23515] hpmud_channel_write() dd=1 cd=2 buf=0xbf8ef1c4 size=8192 sectime=45
Feb 28 09:58:47 topaz hp[23515]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 09:58:47 topaz hp[23515]: [0000]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
Feb 28 09:58:47 topaz hp[23515]: [0016]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
...
Feb 28 09:58:58 topaz hp[23515]: io/hpmud/hpmud.c 627: [23515] hpmud_channel_write() dd=1 cd=2 buf=0xbf8ef1c4 size=8192 sectime=45
Feb 28 09:58:58 topaz hp[23515]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 09:58:58 topaz hp[23515]: [0000]   F0 C0 FF F0 83 00 03 03 FF C0 3F 80 03 01 FF C0     ..........?.....
Feb 28 09:58:58 topaz hp[23515]: [0016]   82 00 02 0F FF FF 80 00 01 FF F0 06 00 0F FF FC     ................
Feb 28 09:58:58 topaz hp[23515]: io/hpmud/hpmud.c 627: [23515] hpmud_channel_write() dd=1 cd=2 buf=0xbf8ef1c4 size=8192 sectime=45
Feb 28 09:58:59 topaz hpijs[23522]: io/hpmud/hpmud.c 503: [23522] hpmud_device_close() dd=1
Feb 28 09:58:59 topaz hpijs[23522]: io/hpmud/hpmud.c 353: [23522] hpmud_exit()
Feb 28 09:58:59 topaz hp[23515]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 09:58:59 topaz hp[23515]: [0000]   00 00 3F 80 00 00 FC 82 00 01 0F C0 00 00 03 0F     ..?.............
Feb 28 09:58:59 topaz hp[23515]: [0016]   C0 03 C0 02 00 03 F0 01 03 F0 80 00 01 3F C0 01     .............?..
Feb 28 09:58:59 topaz hp[23515]: io/hpmud/hpmud.c 627: [23515] hpmud_channel_write() dd=1 cd=2 buf=0xbf8ef1c4 size=8192 sectime=45
Feb 28 09:58:59 topaz hp[23515]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 09:58:59 topaz hp[23515]: [0000]   F0 00 00 01 0F C0 9F 53 00 1B 2A 62 30 57 1B 2A     .......S..*b0W.*
Feb 28 09:58:59 topaz hp[23515]: [0016]   62 35 30 34 56 9F 52 00 01 03 F0 00 03 00 00 01     b504V.R.........
...
Feb 28 09:59:00 topaz hp[23515]: io/hpmud/hpmud.c 627: [23515] hpmud_channel_write() dd=1 cd=2 buf=0xbf8ef1c4 size=6770 sectime=45
Feb 28 09:59:01 topaz hp[23515]: io/hpmud/musb.c 1026: write fd=1 len=6770 size=6770 usec=45000000
Feb 28 09:59:01 topaz hp[23515]: [0000]   FF 3B 00 1B 2A 62 30 57 1B 2A 62 35 56 9F FF FF     .;..*b0W.*b5V...
Feb 28 09:59:01 topaz hp[23515]: [0016]   3B 00 1B 2A 62 30 57 1B 2A 62 35 56 9F FF FF 3B     ;..*b0W.*b5V...;
Feb 28 09:59:01 topaz hp[23515]: prnt/backend/hp.c 833: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=6770
Feb 28 09:59:01 topaz hp[23515]: io/hpmud/hpmud.c 522: [23515] hpmud_get_device_id() dd=1
Feb 28 09:59:01 topaz hp[23515]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:59:03 topaz hp[23515]: io/hpmud/hpmud.c 522: [23515] hpmud_get_device_id() dd=1
Feb 28 09:59:03 topaz hp[23515]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:59:05 topaz hp[23515]: io/hpmud/hpmud.c 522: [23515] hpmud_get_device_id() dd=1
Feb 28 09:59:05 topaz hp[23515]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 09:59:05 topaz hp[23515]: io/hpmud/hpmud.c 608: [23515] hpmud_channel_close() dd=1 cd=2
Feb 28 09:59:05 topaz hp[23515]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 09:59:05 topaz hp[23515]: io/hpmud/musb.c 926: removed PRINT channel=2 clientCnt=0 channelCnt=0
Feb 28 09:59:05 topaz hp[23515]: io/hpmud/hpmud.c 503: [23515] hpmud_device_close() dd=1
Feb 28 09:59:05 topaz hp[23515]: io/hpmud/hpmud.c 353: [23515] hpmud_exit()
Feb 28 10:20:53 topaz hp[23856]: prnt/backend/hp.c 693: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Feb 28 10:20:53 topaz hpijs: io/hpmud/hpmud.c 348: [23863] hpmud_init()
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/hpmud.c 475: [23863,23861,4,4,7,7] hpmud_device_open() uri=hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY iomode=1
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/hpmud.c 522: [23863] hpmud_get_device_id() dd=1
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/hpmud.c 540: [23863] hpmud_get_device_status() dd=1
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 783: read actual device_status successfully fd=1
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/hpmud.c 522: [23863] hpmud_get_device_id() dd=1
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/hpmud.c 522: [23863] hpmud_get_device_id() dd=1
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/hpmud.c 522: [23863] hpmud_get_device_id() dd=1
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/hpmud.c 522: [23863] hpmud_get_device_id() dd=1
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/hpmud.c 522: [23863] hpmud_get_device_id() dd=1
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:20:53 topaz hpijs[23863]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/hpmud.c 475: [23856,1503,4,4,7,7] hpmud_device_open() uri=hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY iomode=1
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/hpmud.c 590: [23856] hpmud_channel_open() dd=1 name=PRINT
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/musb.c 911: new PRINT channel=2 clientCnt=1 channelCnt=1
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/hpmud.c 522: [23856] hpmud_get_device_id() dd=1
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/hpmud.c 627: [23856] hpmud_channel_write() dd=1 cd=2 buf=0xbf8def64 size=8192 sectime=45
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 10:20:53 topaz hp[23856]: [0000]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
Feb 28 10:20:53 topaz hp[23856]: [0016]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/hpmud.c 627: [23856] hpmud_channel_write() dd=1 cd=2 buf=0xbf8def64 size=8192 sectime=45
Feb 28 10:20:53 topaz hp[23856]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 10:20:53 topaz hp[23856]: [0000]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
Feb 28 10:20:53 topaz hp[23856]: [0016]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
...
Feb 28 10:22:33 topaz hp[23856]: io/hpmud/hpmud.c 627: [23856] hpmud_channel_write() dd=1 cd=2 buf=0xbf8def64 size=8192 sectime=45
Feb 28 10:22:33 topaz hp[23856]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 10:22:33 topaz hp[23856]: [0000]   00 FF FF 02 00 3F FC 07 03 00 FF F0 C0 3F FF FF     .....?.......?..
Feb 28 10:22:33 topaz hp[23856]: [0016]   C0 FF C0 FF 80 00 01 0F FF 80 00 02 03 FF C0 07     ................
Feb 28 10:22:33 topaz hp[23856]: io/hpmud/hpmud.c 627: [23856] hpmud_channel_write() dd=1 cd=2 buf=0xbf8def64 size=8192 sectime=45
Feb 28 10:22:33 topaz hpijs[23863]: io/hpmud/hpmud.c 503: [23863] hpmud_device_close() dd=1
Feb 28 10:22:33 topaz hpijs[23863]: io/hpmud/hpmud.c 353: [23863] hpmud_exit()
Feb 28 10:22:33 topaz hp[23856]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 10:22:33 topaz hp[23856]: [0000]   80 00 01 0F C0 82 00 01 03 FC 80 00 01 0F C0 81     ................
Feb 28 10:22:33 topaz hp[23856]: [0016]   00 00 30 81 00 01 0F F3 85 00 00 3F 00 00 00 30     ..0........?...0
Feb 28 10:22:33 topaz hp[23856]: io/hpmud/hpmud.c 627: [23856] hpmud_channel_write() dd=1 cd=2 buf=0xbf8def64 size=8192 sectime=45
Feb 28 10:22:33 topaz hp[23856]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 10:22:33 topaz hp[23856]: [0000]   00 00 FC 91 00 01 03 F0 86 00 00 FF 84 00 01 0F     ................
Feb 28 10:22:33 topaz hp[23856]: [0016]   C0 8E 00 00 3F 8F 00 01 0F F0 89 00 01 3F C0 91     ....?........?..
...
Feb 28 10:22:34 topaz hp[23856]: io/hpmud/hpmud.c 627: [23856] hpmud_channel_write() dd=1 cd=2 buf=0xbf8def64 size=639 sectime=45
Feb 28 10:22:34 topaz hp[23856]: io/hpmud/musb.c 1026: write fd=1 len=639 size=639 usec=45000000
Feb 28 10:22:34 topaz hp[23856]: [0000]   35 56 9F FF FF 3B 00 1B 2A 62 30 57 1B 2A 62 35     5V...;..*b0W.*b5
Feb 28 10:22:34 topaz hp[23856]: [0016]   56 9F FF FF 3B 00 1B 2A 62 30 57 1B 2A 62 35 56     V...;..*b0W.*b5V
Feb 28 10:22:34 topaz hp[23856]: prnt/backend/hp.c 833: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=639
Feb 28 10:22:34 topaz hp[23856]: io/hpmud/hpmud.c 522: [23856] hpmud_get_device_id() dd=1
Feb 28 10:22:34 topaz hp[23856]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:22:36 topaz hp[23856]: io/hpmud/hpmud.c 522: [23856] hpmud_get_device_id() dd=1
Feb 28 10:22:36 topaz hp[23856]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:22:38 topaz hp[23856]: io/hpmud/hpmud.c 522: [23856] hpmud_get_device_id() dd=1
Feb 28 10:22:38 topaz hp[23856]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:22:38 topaz hp[23856]: io/hpmud/hpmud.c 608: [23856] hpmud_channel_close() dd=1 cd=2
Feb 28 10:22:38 topaz hp[23856]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:22:38 topaz hp[23856]: io/hpmud/musb.c 926: removed PRINT channel=2 clientCnt=0 channelCnt=0
Feb 28 10:22:38 topaz hp[23856]: io/hpmud/hpmud.c 503: [23856] hpmud_device_close() dd=1
Feb 28 10:22:38 topaz hp[23856]: io/hpmud/hpmud.c 353: [23856] hpmud_exit()
Feb 28 10:37:35 topaz hp[26301]: prnt/backend/hp.c 693: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Feb 28 10:37:35 topaz hpijs: io/hpmud/hpmud.c 348: [26308] hpmud_init()
Feb 28 10:37:35 topaz hpijs[26308]: io/hpmud/hpmud.c 475: [26308,26306,4,4,7,7] hpmud_device_open() uri=hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY iomode=1
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/hpmud.c 522: [26308] hpmud_get_device_id() dd=1
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/hpmud.c 540: [26308] hpmud_get_device_status() dd=1
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 783: read actual device_status successfully fd=1
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/hpmud.c 522: [26308] hpmud_get_device_id() dd=1
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/hpmud.c 522: [26308] hpmud_get_device_id() dd=1
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/hpmud.c 522: [26308] hpmud_get_device_id() dd=1
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/hpmud.c 522: [26308] hpmud_get_device_id() dd=1
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/hpmud.c 522: [26308] hpmud_get_device_id() dd=1
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:37:36 topaz hpijs[26308]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/hpmud.c 475: [26301,1503,4,4,7,7] hpmud_device_open() uri=hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY iomode=1
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/hpmud.c 590: [26301] hpmud_channel_open() dd=1 name=PRINT
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/musb.c 911: new PRINT channel=2 clientCnt=1 channelCnt=1
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/musb.c 533: claimed 7/1/2 interface
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/hpmud.c 522: [26301] hpmud_get_device_id() dd=1
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/hpmud.c 627: [26301] hpmud_channel_write() dd=1 cd=2 buf=0xbfbf2264 size=8192 sectime=45
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 10:37:36 topaz hp[26301]: [0000]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
Feb 28 10:37:36 topaz hp[26301]: [0016]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/hpmud.c 627: [26301] hpmud_channel_write() dd=1 cd=2 buf=0xbfbf2264 size=4096 sectime=45
Feb 28 10:37:36 topaz hp[26301]: io/hpmud/musb.c 1026: write fd=1 len=4096 size=4096 usec=45000000
Feb 28 10:37:36 topaz hp[26301]: [0000]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
Feb 28 10:37:36 topaz hp[26301]: [0016]   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00     ................
...
Feb 28 10:37:58 topaz hp[26301]: io/hpmud/hpmud.c 627: [26301] hpmud_channel_write() dd=1 cd=2 buf=0xbfbf2264 size=8192 sectime=45
Feb 28 10:37:58 topaz hp[26301]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 10:37:58 topaz hp[26301]: [0000]   84 00 00 0F 80 00 00 30 86 00 06 0F CC 00 F0 C0     .......0........
Feb 28 10:37:58 topaz hp[26301]: [0016]   00 F0 85 00 00 0C 82 00 01 03 F0 80 00 01 0F 0C     ................
Feb 28 10:37:58 topaz hp[26301]: io/hpmud/hpmud.c 627: [26301] hpmud_channel_write() dd=1 cd=2 buf=0xbfbf2264 size=8192 sectime=45
Feb 28 10:37:58 topaz hpijs[26308]: io/hpmud/hpmud.c 503: [26308] hpmud_device_close() dd=1
Feb 28 10:37:58 topaz hpijs[26308]: io/hpmud/hpmud.c 353: [26308] hpmud_exit()
Feb 28 10:37:58 topaz hp[26301]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 10:37:58 topaz hp[26301]: [0000]   00 00 01 0F F0 93 00 00 3F 97 00 01 03 C0 83 00     ........?.......
Feb 28 10:37:58 topaz hp[26301]: [0016]   00 0F 97 00 01 03 F0 9F 79 00 1B 2A 62 30 57 1B     ........y..*b0W.
Feb 28 10:37:58 topaz hp[26301]: io/hpmud/hpmud.c 627: [26301] hpmud_channel_write() dd=1 cd=2 buf=0xbfbf2264 size=8192 sectime=45
Feb 28 10:37:58 topaz hp[26301]: io/hpmud/musb.c 1026: write fd=1 len=8192 size=8192 usec=45000000
Feb 28 10:37:58 topaz hp[26301]: [0000]   03 F0 80 00 03 03 FC 03 F0 00 00 01 0F C0 00 00     ................
Feb 28 10:37:58 topaz hp[26301]: [0016]   00 3F 80 00 80 FF 82 00 00 3F 81 00 00 FC 01 00     .?.......?......
...
Feb 28 10:38:00 topaz hp[26301]: io/hpmud/hpmud.c 627: [26301] hpmud_channel_write() dd=1 cd=2 buf=0xbfbf2264 size=3086 sectime=45
Feb 28 10:38:00 topaz hp[26301]: io/hpmud/musb.c 1026: write fd=1 len=3086 size=3086 usec=45000000
Feb 28 10:38:00 topaz hp[26301]: [0000]   2A 62 35 56 9F FF FF 3B 00 1B 2A 62 30 57 1B 2A     *b5V...;..*b0W.*
Feb 28 10:38:00 topaz hp[26301]: [0016]   62 35 56 9F FF FF 3B 00 1B 2A 62 30 57 1B 2A 62     b5V...;..*b0W.*b
Feb 28 10:38:00 topaz hp[26301]: prnt/backend/hp.c 833: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=3086
Feb 28 10:38:00 topaz hp[26301]: io/hpmud/hpmud.c 522: [26301] hpmud_get_device_id() dd=1
Feb 28 10:38:00 topaz hp[26301]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:38:02 topaz hp[26301]: io/hpmud/hpmud.c 522: [26301] hpmud_get_device_id() dd=1
Feb 28 10:38:02 topaz hp[26301]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:38:04 topaz hp[26301]: io/hpmud/hpmud.c 522: [26301] hpmud_get_device_id() dd=1
Feb 28 10:38:04 topaz hp[26301]: io/hpmud/musb.c 746: read actual device_id successfully fd=1 len=286
Feb 28 10:38:04 topaz hp[26301]: io/hpmud/hpmud.c 608: [26301] hpmud_channel_close() dd=1 cd=2
Feb 28 10:38:04 topaz hp[26301]: io/hpmud/musb.c 559: released 7/1/2 interface
Feb 28 10:38:04 topaz hp[26301]: io/hpmud/musb.c 926: removed PRINT channel=2 clientCnt=0 channelCnt=0
Feb 28 10:38:04 topaz hp[26301]: io/hpmud/hpmud.c 503: [26301] hpmud_device_close() dd=1
Feb 28 10:38:04 topaz hp[26301]: io/hpmud/hpmud.c 353: [26301] hpmud_exit()

Created attachment 396873 [details]
Sample debug for failed print Job

As a further twist, I tried backporting the latest HPLIP SRPM from the F13-Alpha repository to F12, and adding my debugging patch, as in:

$ rpm -qip rpmbuild/SRPMS/hplip-3.9.12-7.fc13.src.rpm  
warning: rpmbuild/SRPMS/hplip-3.9.12-7.fc13.src.rpm: Header V3 RSA/SHA256 signature: NOKEY, key ID e8e40fde
Name        : hplip                        Relocations: (not relocatable)
Version     : 3.9.12                            Vendor: Fedora Project
Release     : 7.fc13                        Build Date: Tue 16 Feb 2010 15:55:44 GMT
Install Date: (not installed)               Build Host: xb-01.phx2.fedoraproject.org
Group       : System Environment/Daemons    Source RPM: (none)
Size        : 21415219                         License: GPLv2+ and MIT
Signature   : RSA/8, Sat 20 Feb 2010 19:52:38 GMT, Key ID 7edc6ad6e8e40fde
Packager    : Fedora Project
URL         : http://hplip.sourceforge.net/
Summary     : HP Linux Imaging and Printing Project
Description :
The Hewlett-Packard Linux Imaging and Printing Project provides
drivers for HP printers and multi-function peripherals.
$ 

$ rpm -q hplip 
hplip-3.9.12-7.hpdebug.fc12.i686
$ 


I was led to try this because the HPLIP 3.9.10/3.9.12 Release Notes themselves suggested that there had been a major reworking of the libusb-based drivers.

Sadly, my luck was out, and this had no perceivable benefit.


Then, just for luck, I tried simply replacing the USB-cable itself, since Tim Waugh's comments suggested that maybe the USB interface itself was resetting.

No luck.


Then I found this report for Ubuntu:

https://bugs.launchpad.net/ubuntu/+source/cups/+bug/420015

which led me to suspect that the kernel's usblp module was somehow to blame.


So I added a blacklist configuration for usblp, as in:

$ cat /etc/modprobe.d/blacklist-usblp.conf  
blacklist usblp
$ 


Rebooted the machine, and tried again. Printing appeared to work perfectly Ok via the libusb interface. Yippee. This is based on performing at least 7 6-page print jobs after the usblp module was removed, having had the same 6-page print job fail at least 3 times in a row just before I removed the module.

Being somewhat wary of changing things again whilst it's working, I've left the machine with the F13 hplip drivers and the new USB cable for the time being.

Although I've performed basic printing Ok, I don't know whether there's anything in terms of printer status, or perhaps Scanner usage, which actually requires usblp operations. Can anyone enlighten me further on this point?


Looking back at the debug logs for the 7 print jobs since removing the usblp module I found this little snippet:

....
Mar 19 15:29:46 topaz hp[2131]: io/hpmud/hpmud.c 629: [2131] hpmud_channel_write() dd=1 cd=2 buf=0xbf890bb4 size=8192 sectime=45
Mar 19 15:29:49 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 19 15:29:49 topaz kernel: usb 1-4: usbfs: process 2268 (hp) did not claim interface 1 before use
Mar 19 15:29:49 topaz hp[2131]: io/hpmud/hpmud.c 629: [2131] hpmud_channel_write() dd=1 cd=2 buf=0xbf890bb4 size=8192 sectime=45
....

The interesting thing here is that the print job succeeded - even though there was a USB reset reported.

Looking back at the hplip source code in this light, I found that hplip had this code snippet:

#ifdef LIBUSB_HAS_DETACH_KERNEL_DRIVER_NP
   /* If any kernel module (ie:usblp) has claimed this interface, detach it. */
   usb_get_driver_np(hd, interface, driver, sizeof(driver));
   if ((driver[0] != 0) && (strcasecmp(driver, "usbfs") != 0))
   {
      DBG("removing %s driver interface=%d\n", driver, interface);
      if (usb_detach_kernel_driver_np(hd, interface) < 0)
         BUG("could not remove %s driver interface=%d: %m\n", driver, interface);
   }
#endif

which resulted in this syslog message when I still had the usblp module whitelisted:

Mar 19 15:08:57 topaz hpijs[8631]: io/hpmud/musb.c 401: removing usblp driver interface=1


With all these clues in mind, I think the overall problem was/is:

1. The usblp kernel module was loaded anyway, independent of cups/hplip.

2. The first print job, probably, explicitly removed the usblp driver to avoid it interfering with access to the USB interface for the duration of the print job.

3. A USB-reset, possibly as a result of a hardware/firmware fault in the printer itself, occasionally happened at a random point in the middle of a print job.

4. The kernel automatically reloaded the usblp driver module as a result of the USB reset - unbeknown to the HPLIP drivers.

5. The usblp and libusb drivers "argued" over control of the USB interface and chaos ensued.


Having blacklisted the usblp driver, the USB resets no longer cause the driver to be reloaded, and the printer interface is thereby stabilised.


Another interesting point, which leads me to think that the fault is firmware rather than hardware related on the printer is that the final usb_bulk_write before a crash always seemed to deliver 512 bytes out of 8192; if this were a hardware fault, the delivered quantity would surely be more random?


$ sudo grep 15:08:47 /var/log/debug-20100320 | grep 15:08:47 
Mar 19 15:08:47 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 5
Mar 19 15:08:47 topaz kernel: usblp0: USB Bidirectional printer dev 5 if 1 alt 0 proto 2 vid 0x03F0 pid 0x4E11
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/musb.c 1030: write fd=1 len=512 size=8192 usec=45000000
Mar 19 15:08:47 topaz kernel: usb 1-4: usbfs: process 5989 (hp) did not claim interface 1 before use
Mar 19 15:08:47 topaz kernel: usb 1-4: usbfs: process 5889 (hp) did not claim interface 1 before use
Mar 19 15:08:47 topaz hp[5889]: [0000]   FC 85 00 02 0F FF F0 00 00 03 03 FF FF C0 83 00     ................
Mar 19 15:08:47 topaz hp[5889]: [0016]   01 3F FC 80 00 02 03 FF FF 82 00 03 0F FF FF F0     .?..............
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/musb.c 1026: bulk_write failed buf=0xbfdce334 size=7680 len=-16: No data available
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/musb.c 1393: unable to write data hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY: No data available
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/hpmud.c 524: [5889] hpmud_get_device_id() dd=1
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/musb.c 739: invalid deviceid ret=-16: Device or resource busy
Mar 19 15:08:47 topaz hp[5889]: prnt/backend/hp.c 626: ERROR: 5021 device communication error!
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/hpmud.c 610: [5889] hpmud_channel_close() dd=1 cd=2
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/musb.c 559: released 7/1/2 interface
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/musb.c 930: removed PRINT channel=2 clientCnt=0 channelCnt=0
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/hpmud.c 505: [5889] hpmud_device_close() dd=1
Mar 19 15:08:47 topaz hp[5889]: io/hpmud/hpmud.c 353: [5889] hpmud_exit()


It's also slightly odd that libusb seems to cope Ok with this USB reset condition. Maybe it has a more bullet-proof retry heuristic?


In summary therefore, it looks as if there's a firmware bug in the printer, which is exacerbated by the reload of the usblp module when the USB interface resets.

Since implementing the usblp module blacklisting, I've been able to print without apparent error.

Nevertheless, a summary of print jobs and associated USB resets shows that a significant number of jobs are interrupted by a USB reset, whilst some other jobs appear to result in a USB reset AFTER the Job has completed.

I suspect it may therefore be worthwhile recommending that all machines with USB connected HP printers have usblp blacklisted, or at least add something to that effect to the general CUPS FAQ.

There is another little clue in the listing below. Now that I've stopped the print jobs from crashing, it is apparent that the USB reset always seems to occur almost exactly 32 seconds after the Job Start notification. The presumption, therefore, is that if a print job squeezes in to the printer in under 30 seconds, it is likely to succeed without blacklisting usblp, even though it may still suffer a USB reset. This somewhat ties in with one of my original observations that single-page print jobs tended to succeed.




$ sudo cat `ls -rt /var/log/debug-2010032*` /var/log/debug | grep "Mar 2" | egrep "job.end|job.start|reset.high.speed.USB" | grep -v sudo
Mar 20 10:59:14 topaz hp[8764]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 20 10:59:29 topaz hp[8764]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=5193
Mar 20 10:59:46 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 21 16:45:41 topaz hp[14637]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 21 16:46:02 topaz hp[14637]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=524
Mar 21 16:46:13 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 21 17:07:42 topaz hp[14973]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 21 17:08:01 topaz hp[14973]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=5067
Mar 23 18:21:00 topaz hp[6407]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 23 18:21:16 topaz hp[6407]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=1277
Mar 23 18:21:32 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 23 19:12:53 topaz hp[7775]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 23 19:13:23 topaz hp[7775]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=7099
Mar 24 14:13:19 topaz hp[13387]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 24 14:13:51 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 24 14:14:54 topaz hp[13387]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=2133
Mar 24 14:24:19 topaz hp[13888]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 24 14:24:35 topaz hp[13888]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=4550
Mar 24 14:24:50 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 24 14:25:11 topaz hp[13938]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 24 14:25:24 topaz hp[13938]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=4072
Mar 24 14:26:05 topaz hp[13988]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 24 14:26:17 topaz hp[13988]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=5994
Mar 24 14:26:37 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 24 18:59:59 topaz hp[17774]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 24 19:00:17 topaz hp[17774]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=6235
Mar 24 19:00:31 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 24 19:01:06 topaz hp[17888]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 24 19:01:24 topaz hp[17888]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=8076
Mar 24 19:01:38 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 24 19:03:53 topaz hp[18165]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 24 19:04:06 topaz hp[18165]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=3176
Mar 24 19:04:25 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 24 19:05:17 topaz hp[18239]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 24 19:05:48 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 24 19:06:04 topaz hp[18239]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=497
Mar 25 09:16:59 topaz hp[2933]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 25 09:17:12 topaz hp[2933]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=4559
Mar 25 09:17:32 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 25 09:17:48 topaz hp[2972]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 25 09:17:58 topaz hp[2972]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=4559
Mar 25 09:18:19 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 25 22:32:54 topaz hp[14073]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 25 22:33:26 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 25 22:34:10 topaz hp[14073]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=2721
Mar 26 07:16:18 topaz hp[1913]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 26 07:16:53 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 26 07:20:00 topaz hp[1913]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=2682
Mar 26 07:20:09 topaz hp[2709]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 26 07:20:25 topaz hp[2709]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=318
Mar 26 11:10:15 topaz hp[8180]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 26 11:10:28 topaz hp[8180]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=660
Mar 26 11:10:48 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 28 14:10:53 topaz hp[2194]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 28 14:10:56 topaz hp[2194]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=5258
Mar 28 14:11:26 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 28 14:13:43 topaz hp[2247]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 28 14:13:46 topaz hp[2247]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=5258
Mar 28 14:14:38 topaz hp[2283]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 28 14:15:07 topaz hp[2283]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=5653
Mar 28 14:18:22 topaz hp[2411]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 28 14:18:25 topaz hp[2411]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=5258
Mar 28 14:21:06 topaz hp[2476]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 28 14:21:58 topaz hp[2476]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=5663
Mar 28 14:22:28 topaz hp[2574]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 28 14:22:41 topaz hp[2574]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=3744
Mar 28 14:23:01 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 29 14:42:27 topaz hp[14435]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 29 14:42:59 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 29 14:43:20 topaz hp[14435]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=1562
Mar 29 14:57:14 topaz hp[14702]: prnt/backend/hp.c 701: job start hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2
Mar 29 14:57:46 topaz kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 4
Mar 29 14:58:55 topaz hp[14702]: prnt/backend/hp.c 842: job end hp:/usb/Photosmart_2570_series?serial=MY65T112BM04DY prt_mode=1 statustype=2 total=2818

With the print jobs continue to work Ok, I've used Wireshark's USB sniffing capability to provide some further evidence that the real issue is one of a firmware bug in the printer itself causing a USB reset.

Printing a multi-page print job, whilst capturing USB traffic, I then tallied the USB reset syslog with the corresponding USB traffic to show that the reset seems to happen after the completion of a full 8k data transfer. The USB session is then re-established, and further 8k data transfers are initiated.
If there are any USB gurus out there, the (cut-down) packet trace below may offer further clues.

This further suggests that some sort of glaring warning note should be put in Fedora w.r.t. HP Printers suggesting that usblp be disabled forevermore to work round this issue. I also note that CUPS in F12 seems to be compiled without libusb support, and thus appears to rely on usblp for USB printer discovery; maybe it's time that was changed?



Relevant wireshark command:

$ sudo tshark -i usbmon1 -V -x -s0  | tee usb-printer-tshark.txt


Cut-down copy of packet capture showing reset event:

$ cat usb-printer-tshark-trimmedB.txt  
Frame 634 (8216 bytes on wire, 8216 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.153201000
    [Time delta from previous captured frame: 0.000130000 seconds]
    [Time delta from previous displayed frame: 0.000130000 seconds]
    [Time since reference or first frame: 48.699977000 seconds]
    Frame Number: 634
    Frame Length: 8216 bytes
    Capture Length: 8216 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f3f6d980
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_BULK (3)
    Endpoint: 0x03
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 8192
    Data length [bytes]: 8192
    [bInterfaceClass: Unknown (0xffff)]
    Application Data: 1513F837FE13F839F81DFF150FF819FF150FF809FF130DF8...

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00 15 13 f8 37 fe 13 f8 39   ...........7...9
0020  f8 1d ff 15 0f f8 19 ff 15 0f f8 09 ff 13 0d f8   ................
0030  3f ff 17 0d f8 3f ff 15 35 ff 15 17 ff 17 0d f8   ?....?..5.......
0040  25 fc 13 f8 7d ff 17 0d f8 79 f8 57 ff 15 39 f8   %...}....y.W..9.
0050  3f fe 13 f8 7b fe 13 fa 17 ff 15 0f b8 27 f8 29   ?...{........'.)
0060  f8 1f ff 17 35 f8 57 ff 15 39 ff 0b 01 f8 37 fe   ....5.W..9....7.
...
1fe0  62 30 56 1b 2a 62 30 57 1b 2a 62 30 56 1b 2a 62   b0V.*b0W.*b0V.*b
1ff0  30 57 1b 2a 62 30 56 1b 2a 62 30 57 1b 2a 62 30   0W.*b0V.*b0W.*b0
2000  56 1b 2a 62 30 57 1b 2a 62 30 56 1b 2a 62 30 57   V.*b0W.*b0V.*b0W
2010  1b 2a 62 30 56 1b 2a 62                           .*b0V.*b

Frame 635 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.746440000
    [Time delta from previous captured frame: 0.593239000 seconds]
    [Time delta from previous displayed frame: 0.593239000 seconds]
    [Time since reference or first frame: 49.293216000 seconds]
    Frame Number: 635
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f6540180
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_BULK (3)
    Endpoint: 0x87
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Connection reset by peer (-ECONNRESET) (-104)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [Request in: 515]
    [Time from request: 30.739297000 seconds]
    [bInterfaceClass: Unknown (0xffff)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  0c 02 00 00 00 00 00 00                           ........

Frame 636 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.746565000
    [Time delta from previous captured frame: 0.000125000 seconds]
    [Time delta from previous displayed frame: 0.000125000 seconds]
    [Time since reference or first frame: 49.293341000 seconds]
    Frame Number: 636
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f3f6d980
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_BULK (3)
    Endpoint: 0x03
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: not present ('>')
    URB status: Cannot send after transport endpoint shutdown (-ESHUTDOWN) (-108)
    URB length [bytes]: 512
    Data length [bytes]: 0
    [Request in: 634]
    [Time from request: 0.593364000 seconds]
    [bInterfaceClass: Unknown (0xffff)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00                           ........

Frame 637 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.746578000
    [Time delta from previous captured frame: 0.000013000 seconds]
    [Time delta from previous displayed frame: 0.000013000 seconds]
    [Time since reference or first frame: 49.293354000 seconds]
    Frame Number: 637
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 1
    URB bus id: 1
    Device setup request: present (0)
    Data: present (0)
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0x23
            0... .... = Direction: Host-to-device
            .01. .... = Type: Class (0x01)
            ...0 0011 = Recipient: Other (0x03)
    Application Data: 0304000400000000000000000000000000000000000000

0000  23 03 04 00 04 00 00 00 00 00 00 00 00 00 00 00   #...............
0010  00 00 00 00 00 00 00 00                           ........

Frame 638 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.746581000
    [Time delta from previous captured frame: 0.000003000 seconds]
    [Time delta from previous displayed frame: 0.000003000 seconds]
    [Time since reference or first frame: 49.293357000 seconds]
    Frame Number: 638
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 1
    URB bus id: 1
    Device setup request: not present ('-')
    Data: not present ('>')
    URB status: Success (0)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [Request in: 637]
    [Time from request: 0.000003000 seconds]
    [bInterfaceClass: Unknown (0xffff)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00                           ........

Frame 639 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.797438000
    [Time delta from previous captured frame: 0.050857000 seconds]
    [Time delta from previous displayed frame: 0.050857000 seconds]
    [Time since reference or first frame: 49.344214000 seconds]
    Frame Number: 639
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 1
    URB bus id: 1
    Device setup request: present (0)
    Data: not present ('<')
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 4
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0xa3
            1... .... = Direction: Device-to-host
            .01. .... = Type: Class (0x01)
            ...0 0011 = Recipient: Other (0x03)
    Application Data: 0000000400040000000000000000000002000000000000

0000  a3 00 00 00 04 00 04 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00                           ........

Frame 640 (28 bytes on wire, 28 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.797687000
    [Time delta from previous captured frame: 0.000249000 seconds]
    [Time delta from previous displayed frame: 0.000249000 seconds]
    [Time since reference or first frame: 49.344463000 seconds]
    Frame Number: 640
    Frame Length: 28 bytes
    Capture Length: 28 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 1
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Success (0)
    URB length [bytes]: 4
    Data length [bytes]: 4
    [Request in: 639]
    [Time from request: 0.000249000 seconds]
    [bInterfaceClass: Unknown (0xffff)]
    Application Data: 03051000

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00 03 05 10 00               ............

Frame 641 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.848315000
    [Time delta from previous captured frame: 0.050628000 seconds]
    [Time delta from previous displayed frame: 0.050628000 seconds]
    [Time since reference or first frame: 49.395091000 seconds]
    Frame Number: 641
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 1
    URB bus id: 1
    Device setup request: present (0)
    Data: present (0)
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0x23
            0... .... = Direction: Host-to-device
            .01. .... = Type: Class (0x01)
            ...0 0011 = Recipient: Other (0x03)
    Application Data: 0114000400000000000000000000000000000000000000

0000  23 01 14 00 04 00 00 00 00 00 00 00 00 00 00 00   #...............
0010  00 00 00 00 00 00 00 00                           ........

Frame 642 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.848319000
    [Time delta from previous captured frame: 0.000004000 seconds]
    [Time delta from previous displayed frame: 0.000004000 seconds]
    [Time since reference or first frame: 49.395095000 seconds]
    Frame Number: 642
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 1
    URB bus id: 1
    Device setup request: not present ('-')
    Data: not present ('>')
    URB status: Success (0)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [Request in: 641]
    [Time from request: 0.000004000 seconds]
    [bInterfaceClass: Unknown (0xffff)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00                           ........

Frame 643 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.848327000
    [Time delta from previous captured frame: 0.000008000 seconds]
    [Time delta from previous displayed frame: 0.000008000 seconds]
    [Time since reference or first frame: 49.395103000 seconds]
    Frame Number: 643
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 0
    URB bus id: 1
    Device setup request: present (0)
    Data: not present ('<')
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 64
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0x80
            1... .... = Direction: Device-to-host
            .00. .... = Type: Standard (0x00)
            ...0 0000 = Recipient: Device (0x00)
        bRequest: GET DESCRIPTOR (6)
        Descriptor Index: 0x00
        bDescriptorType: DEVICE (1)
        Language Id: no language specified (0x0000)
        wLength: 64

0000  80 06 00 01 00 00 40 00 00 00 00 00 00 00 00 00   ......@.........
0010  00 02 00 00 00 00 00 00                           ........

Frame 644 (42 bytes on wire, 42 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.848440000
    [Time delta from previous captured frame: 0.000113000 seconds]
    [Time delta from previous displayed frame: 0.000113000 seconds]
    [Time since reference or first frame: 49.395216000 seconds]
    Frame Number: 644
    Frame Length: 42 bytes
    Capture Length: 42 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 0
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Success (0)
    URB length [bytes]: 18
    Data length [bytes]: 18
    [Request in: 643]
    [Time from request: 0.000113000 seconds]
    [bInterfaceClass: Unknown (0xffff)]
    DEVICE DESCRIPTOR
        bLength: 18
        bDescriptorType: DEVICE (1)
        bcdUSB: 0x0200
        bDeviceClass: 0
        bDeviceSubClass: 0
        bDeviceProtocol: 0
        bMaxPacketSize0: 64
        idVendor: 0x03f0
        idProduct: 0x4e11
        bcdDevice: 0x0200
        iManufacturer: 1
        iProduct: 2
        iSerialNumber: 3
        bNumConfigurations: 1

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00 12 01 00 02 00 00 00 40   ...............@
0020  f0 03 11 4e 00 02 01 02 03 01                     ...N......

Frame 645 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.848545000
    [Time delta from previous captured frame: 0.000105000 seconds]
    [Time delta from previous displayed frame: 0.000105000 seconds]
    [Time since reference or first frame: 49.395321000 seconds]
    Frame Number: 645
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 1
    URB bus id: 1
    Device setup request: present (0)
    Data: present (0)
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0x23
            0... .... = Direction: Host-to-device
            .01. .... = Type: Class (0x01)
            ...0 0011 = Recipient: Other (0x03)
    Application Data: 0304000400000000000000000000000000000000000000

0000  23 03 04 00 04 00 00 00 00 00 00 00 00 00 00 00   #...............
0010  00 00 00 00 00 00 00 00                           ........

Frame 646 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.848547000
    [Time delta from previous captured frame: 0.000002000 seconds]
    [Time delta from previous displayed frame: 0.000002000 seconds]
    [Time since reference or first frame: 49.395323000 seconds]
    Frame Number: 646
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 1
    URB bus id: 1
    Device setup request: not present ('-')
    Data: not present ('>')
    URB status: Success (0)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [Request in: 645]
    [Time from request: 0.000002000 seconds]
    [bInterfaceClass: Unknown (0xffff)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00                           ........

Frame 647 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.899315000
    [Time delta from previous captured frame: 0.050768000 seconds]
    [Time delta from previous displayed frame: 0.050768000 seconds]
    [Time since reference or first frame: 49.446091000 seconds]
    Frame Number: 647
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 1
    URB bus id: 1
    Device setup request: present (0)
    Data: not present ('<')
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 4
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0xa3
            1... .... = Direction: Device-to-host
            .01. .... = Type: Class (0x01)
            ...0 0011 = Recipient: Other (0x03)
    Application Data: 0000000400040000000000000000000002000000000000

0000  a3 00 00 00 04 00 04 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00                           ........

Frame 648 (28 bytes on wire, 28 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.899563000
    [Time delta from previous captured frame: 0.000248000 seconds]
    [Time delta from previous displayed frame: 0.000248000 seconds]
    [Time since reference or first frame: 49.446339000 seconds]
    Frame Number: 648
    Frame Length: 28 bytes
    Capture Length: 28 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 1
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Success (0)
    URB length [bytes]: 4
    Data length [bytes]: 4
    [Request in: 647]
    [Time from request: 0.000248000 seconds]
    [bInterfaceClass: Unknown (0xffff)]
    Application Data: 03051000

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00 03 05 10 00               ............

Frame 649 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.950314000
    [Time delta from previous captured frame: 0.050751000 seconds]
    [Time delta from previous displayed frame: 0.050751000 seconds]
    [Time since reference or first frame: 49.497090000 seconds]
    Frame Number: 649
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 1
    URB bus id: 1
    Device setup request: present (0)
    Data: present (0)
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0x23
            0... .... = Direction: Host-to-device
            .01. .... = Type: Class (0x01)
            ...0 0011 = Recipient: Other (0x03)
    Application Data: 0114000400000000000000000000000000000000000000

0000  23 01 14 00 04 00 00 00 00 00 00 00 00 00 00 00   #...............
0010  00 00 00 00 00 00 00 00                           ........

Frame 650 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.950318000
    [Time delta from previous captured frame: 0.000004000 seconds]
    [Time delta from previous displayed frame: 0.000004000 seconds]
    [Time since reference or first frame: 49.497094000 seconds]
    Frame Number: 650
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 1
    URB bus id: 1
    Device setup request: not present ('-')
    Data: not present ('>')
    URB status: Success (0)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [Request in: 649]
    [Time from request: 0.000004000 seconds]
    [bInterfaceClass: Unknown (0xffff)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00                           ........

Frame 651 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.950320000
    [Time delta from previous captured frame: 0.000002000 seconds]
    [Time delta from previous displayed frame: 0.000002000 seconds]
    [Time since reference or first frame: 49.497096000 seconds]
    Frame Number: 651
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 0
    URB bus id: 1
    Device setup request: present (0)
    Data: present (0)
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0x00
            0... .... = Direction: Host-to-device
            .00. .... = Type: Standard (0x00)
            ...0 0000 = Recipient: Device (0x00)
        bRequest: SET ADDRESS (5)
        Device: 4
        wIndex: 0
        wLength: 0

0000  00 05 04 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00                           ........

Frame 652 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.950440000
    [Time delta from previous captured frame: 0.000120000 seconds]
    [Time delta from previous displayed frame: 0.000120000 seconds]
    [Time since reference or first frame: 49.497216000 seconds]
    Frame Number: 652
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 0
    URB bus id: 1
    Device setup request: not present ('-')
    Data: not present ('>')
    URB status: Success (0)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [Request in: 651]
    [Time from request: 0.000120000 seconds]
    [bInterfaceClass: Unknown (0xffff)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00                           ........

Frame 653 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.962314000
    [Time delta from previous captured frame: 0.011874000 seconds]
    [Time delta from previous displayed frame: 0.011874000 seconds]
    [Time since reference or first frame: 49.509090000 seconds]
    Frame Number: 653
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 4
    URB bus id: 1
    Device setup request: present (0)
    Data: not present ('<')
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 18
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0x80
            1... .... = Direction: Device-to-host
            .00. .... = Type: Standard (0x00)
            ...0 0000 = Recipient: Device (0x00)
        bRequest: GET DESCRIPTOR (6)
        Descriptor Index: 0x00
        bDescriptorType: DEVICE (1)
        Language Id: no language specified (0x0000)
        wLength: 18

0000  80 06 00 01 00 00 12 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00                           ........

Frame 654 (42 bytes on wire, 42 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.962439000
    [Time delta from previous captured frame: 0.000125000 seconds]
    [Time delta from previous displayed frame: 0.000125000 seconds]
    [Time since reference or first frame: 49.509215000 seconds]
    Frame Number: 654
    Frame Length: 42 bytes
    Capture Length: 42 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Success (0)
    URB length [bytes]: 18
    Data length [bytes]: 18
    [Request in: 653]
    [Time from request: 0.000125000 seconds]
    [bInterfaceClass: Unknown (0xffff)]
    DEVICE DESCRIPTOR
        bLength: 18
        bDescriptorType: DEVICE (1)
        bcdUSB: 0x0200
        bDeviceClass: 0
        bDeviceSubClass: 0
        bDeviceProtocol: 0
        bMaxPacketSize0: 64
        idVendor: 0x03f0
        idProduct: 0x4e11
        bcdDevice: 0x0200
        iManufacturer: 1
        iProduct: 2
        iSerialNumber: 3
        bNumConfigurations: 1

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00 12 01 00 02 00 00 00 40   ...............@
0020  f0 03 11 4e 00 02 01 02 03 01                     ...N......

Frame 655 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.962454000
    [Time delta from previous captured frame: 0.000015000 seconds]
    [Time delta from previous displayed frame: 0.000015000 seconds]
    [Time since reference or first frame: 49.509230000 seconds]
    Frame Number: 655
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 4
    URB bus id: 1
    Device setup request: present (0)
    Data: not present ('<')
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 152
    Data length [bytes]: 0
    [bInterfaceClass: Unknown (0xffff)]
    URB setup
        bmRequestType: 0x80
            1... .... = Direction: Device-to-host
            .00. .... = Type: Standard (0x00)
            ...0 0000 = Recipient: Device (0x00)
        bRequest: GET DESCRIPTOR (6)
        Descriptor Index: 0x00
        bDescriptorType: CONFIGURATION (2)
        Language Id: no language specified (0x0000)
        wLength: 152

0000  80 06 00 02 00 00 98 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00                           ........

Frame 656 (176 bytes on wire, 176 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.962689000
    [Time delta from previous captured frame: 0.000235000 seconds]
    [Time delta from previous displayed frame: 0.000235000 seconds]
    [Time since reference or first frame: 49.509465000 seconds]
    Frame Number: 656
    Frame Length: 176 bytes
    Capture Length: 176 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Success (0)
    URB length [bytes]: 152
    Data length [bytes]: 152
    [Request in: 655]
    [Time from request: 0.000235000 seconds]
    [bInterfaceClass: Unknown (0xffff)]
    CONFIGURATION DESCRIPTOR
        bLength: 9
        bDescriptorType: CONFIGURATION (2)
        wTotalLength: 152
        bNumInterfaces: 4
        bConfigurationValue: 1
        iConfiguration: 0
        Configuration bmAttributes: 0xc0  SELF-POWERED  NO REMOTE-WAKEUP
            1... .... = Must be 1: Must be 1 for USB 1.1 and higher
            .1.. .... = Self-Powered: This device is SELF-POWERED
            ..0. .... = Remote Wakeup: This device does NOT support remote wakeup
        bMaxPower: 1  (2mA)
    INTERFACE DESCRIPTOR
        bLength: 9
        bDescriptorType: INTERFACE (4)
        bInterfaceNumber: 0
        bAlternateSetting: 0
        bNumEndpoints: 3
        bInterfaceClass: VENDOR_SPECIFIC (0xff)
        bInterfaceSubClass: 0xcc
        bInterfaceProtocol: 0x00
        iInterface: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x01  OUT  Endpoint:1
            0... .... = Direction: OUT Endpoint
            .... 0001 = Endpoint Number: 0x01
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x81  IN  Endpoint:1
            1... .... = Direction: IN Endpoint
            .... 0001 = Endpoint Number: 0x01
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x82  IN  Endpoint:2
            1... .... = Direction: IN Endpoint
            .... 0010 = Endpoint Number: 0x02
        bmAttributes: 0x03
            .... ..11 = Transfertype: Interrupt-Transfer (0x03)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 8
        bInterval: 7
    INTERFACE DESCRIPTOR
        bLength: 9
        bDescriptorType: INTERFACE (4)
        bInterfaceNumber: 1
        bAlternateSetting: 0
        bNumEndpoints: 3
        bInterfaceClass: PRINTER (0x07)
        bInterfaceSubClass: 0x01
        bInterfaceProtocol: 0x02
        iInterface: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x03  OUT  Endpoint:3
            0... .... = Direction: OUT Endpoint
            .... 0011 = Endpoint Number: 0x03
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x83  IN  Endpoint:3
            1... .... = Direction: IN Endpoint
            .... 0011 = Endpoint Number: 0x03
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x84  IN  Endpoint:4
            1... .... = Direction: IN Endpoint
            .... 0100 = Endpoint Number: 0x04
        bmAttributes: 0x03
            .... ..11 = Transfertype: Interrupt-Transfer (0x03)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 8
        bInterval: 7
    INTERFACE DESCRIPTOR
        bLength: 9
        bDescriptorType: INTERFACE (4)
        bInterfaceNumber: 2
        bAlternateSetting: 0
        bNumEndpoints: 3
        bInterfaceClass: VENDOR_SPECIFIC (0xff)
        bInterfaceSubClass: 0xff
        bInterfaceProtocol: 0xff
        iInterface: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x05  OUT  Endpoint:5
            0... .... = Direction: OUT Endpoint
            .... 0101 = Endpoint Number: 0x05
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x85  IN  Endpoint:5
            1... .... = Direction: IN Endpoint
            .... 0101 = Endpoint Number: 0x05
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x86  IN  Endpoint:6
            1... .... = Direction: IN Endpoint
            .... 0110 = Endpoint Number: 0x06
        bmAttributes: 0x03
            .... ..11 = Transfertype: Interrupt-Transfer (0x03)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 8
        bInterval: 7
    INTERFACE DESCRIPTOR
        bLength: 9
        bDescriptorType: INTERFACE (4)
        bInterfaceNumber: 2
        bAlternateSetting: 1
        bNumEndpoints: 3
        bInterfaceClass: VENDOR_SPECIFIC (0xff)
        bInterfaceSubClass: 0xd4
        bInterfaceProtocol: 0x00
        iInterface: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x05  OUT  Endpoint:5
            0... .... = Direction: OUT Endpoint
            .... 0101 = Endpoint Number: 0x05
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x85  IN  Endpoint:5
            1... .... = Direction: IN Endpoint
            .... 0101 = Endpoint Number: 0x05
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x86  IN  Endpoint:6
            1... .... = Direction: IN Endpoint
            .... 0110 = Endpoint Number: 0x06
        bmAttributes: 0x03
            .... ..11 = Transfertype: Interrupt-Transfer (0x03)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 8
        bInterval: 7
    INTERFACE DESCRIPTOR
        bLength: 9
        bDescriptorType: INTERFACE (4)
        bInterfaceNumber: 3
        bAlternateSetting: 0
        bNumEndpoints: 2
        bInterfaceClass: MASSTORAGE (0x08)
        bInterfaceSubClass: 0x06
        bInterfaceProtocol: 0x50
        iInterface: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x07  OUT  Endpoint:7
            0... .... = Direction: OUT Endpoint
            .... 0111 = Endpoint Number: 0x07
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0
    ENDPOINT DESCRIPTOR
        bLength: 7
        bDescriptorType: ENDPOINT (5)
        bEndpointAddress: 0x87  IN  Endpoint:7
            1... .... = Direction: IN Endpoint
            .... 0111 = Endpoint Number: 0x07
        bmAttributes: 0x02
            .... ..10 = Transfertype: Bulk-Transfer (0x02)
            .... 00.. = Synchronisationtype: No Sync (0x00)
            ..00 .... = Behaviourtype: Data-Endpoint (0x00)
        wMaxPacketSize: 512
        bInterval: 0

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00 09 02 98 00 04 01 00 c0   ................
0020  01 09 04 00 00 03 ff cc 00 00 07 05 01 02 00 02   ................
0030  00 07 05 81 02 00 02 00 07 05 82 03 08 00 07 09   ................
0040  04 01 00 03 07 01 02 00 07 05 03 02 00 02 00 07   ................
0050  05 83 02 00 02 00 07 05 84 03 08 00 07 09 04 02   ................
0060  00 03 ff ff ff 00 07 05 05 02 00 02 00 07 05 85   ................
0070  02 00 02 00 07 05 86 03 08 00 07 09 04 02 01 03   ................
0080  ff d4 00 00 07 05 05 02 00 02 00 07 05 85 02 00   ................
0090  02 00 07 05 86 03 08 00 07 09 04 03 00 02 08 06   ................
00a0  50 00 07 05 07 02 00 02 00 07 05 87 02 00 02 00   P...............

Frame 657 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.962703000
    [Time delta from previous captured frame: 0.000014000 seconds]
    [Time delta from previous displayed frame: 0.000014000 seconds]
    [Time since reference or first frame: 49.509479000 seconds]
    Frame Number: 657
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 4
    URB bus id: 1
    Device setup request: present (0)
    Data: not present ('<')
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 255
    Data length [bytes]: 0
    [bInterfaceClass: MASSTORAGE (0x08)]
    URB setup
        bmRequestType: 0x80
            1... .... = Direction: Device-to-host
            .00. .... = Type: Standard (0x00)
            ...0 0000 = Recipient: Device (0x00)
        bRequest: GET DESCRIPTOR (6)
        Descriptor Index: 0x03
        bDescriptorType: STRING (3)
        Language Id: English (United States) (0x0409)
        wLength: 255

0000  80 06 03 03 09 04 ff 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00                           ........

Frame 658 (54 bytes on wire, 54 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.962814000
    [Time delta from previous captured frame: 0.000111000 seconds]
    [Time delta from previous displayed frame: 0.000111000 seconds]
    [Time since reference or first frame: 49.509590000 seconds]
    Frame Number: 658
    Frame Length: 54 bytes
    Capture Length: 54 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x80
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Success (0)
    URB length [bytes]: 30
    Data length [bytes]: 30
    [Request in: 657]
    [Time from request: 0.000111000 seconds]
    [bInterfaceClass: MASSTORAGE (0x08)]
    STRING DESCRIPTOR
        bLength: 30
        bDescriptorType: STRING (3)
        bString: MY65T112BM04DY

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 02 00 00 00 00 00 00 1e 03 4d 00 59 00 36 00   ..........M.Y.6.
0020  35 00 54 00 31 00 31 00 32 00 42 00 4d 00 30 00   5.T.1.1.2.B.M.0.
0030  34 00 44 00 59 00                                 4.D.Y.

Frame 659 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.962827000
    [Time delta from previous captured frame: 0.000013000 seconds]
    [Time delta from previous displayed frame: 0.000013000 seconds]
    [Time since reference or first frame: 49.509603000 seconds]
    Frame Number: 659
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 4
    URB bus id: 1
    Device setup request: present (0)
    Data: present (0)
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [bInterfaceClass: MASSTORAGE (0x08)]
    URB setup
        bmRequestType: 0x00
            0... .... = Direction: Host-to-device
            .00. .... = Type: Standard (0x00)
            ...0 0000 = Recipient: Device (0x00)
        bRequest: SET CONFIGURATION (9)
        bConfigurationValue: 1
        wIndex: 0
        wLength: 0

0000  00 09 01 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00                           ........

Frame 660 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.963064000
    [Time delta from previous captured frame: 0.000237000 seconds]
    [Time delta from previous displayed frame: 0.000237000 seconds]
    [Time since reference or first frame: 49.509840000 seconds]
    Frame Number: 660
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2d51f00
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_CONTROL (2)
    Endpoint: 0x00
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: not present ('>')
    URB status: Success (0)
    URB length [bytes]: 0
    Data length [bytes]: 0
    [Request in: 659]
    [Time from request: 0.000237000 seconds]
    [bInterfaceClass: MASSTORAGE (0x08)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00                           ........

Frame 661 (55 bytes on wire, 55 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.963096000
    [Time delta from previous captured frame: 0.000032000 seconds]
    [Time delta from previous displayed frame: 0.000032000 seconds]
    [Time since reference or first frame: 49.509872000 seconds]
    Frame Number: 661
    Frame Length: 55 bytes
    Capture Length: 55 bytes
    [Frame is marked: False]
    [Protocols in frame: usb:usbms]
USB URB
    URB id: 0x00000000f6540180
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_BULK (3)
    Endpoint: 0x07
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 31
    Data length [bytes]: 31
    [bInterfaceClass: MASSTORAGE (0x08)]
USB Mass Storage
    Signature: 0x43425355
    Tag: 0x0001155b
    DataTransferLength: 0
    Flags: 0x00
    .... 0000 = LUN: 0x00
    ...0 0110 = CDB Length: 0x06
SCSI CDB Test Unit Ready
    [LUN: 0x0000]
    [Command Set:Direct Access Device (0x00) (Using default commandset)]
    Opcode: Test Unit Ready (0x00)
    Vendor Unique = 0, NACA = 0, Link = 0

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  0c 00 00 00 00 00 00 00 55 53 42 43 5b 15 01 00   ........USBC[...
0020  00 00 00 00 00 00 06 00 00 00 00 00 00 00 00 00   ................
0030  00 00 00 00 00 00 00                              .......

Frame 662 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.963189000
    [Time delta from previous captured frame: 0.000093000 seconds]
    [Time delta from previous displayed frame: 0.000093000 seconds]
    [Time since reference or first frame: 49.509965000 seconds]
    Frame Number: 662
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f6540180
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_BULK (3)
    Endpoint: 0x07
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: not present ('>')
    URB status: Success (0)
    URB length [bytes]: 31
    Data length [bytes]: 0
    [Request in: 661]
    [Time from request: 0.000093000 seconds]
    [bInterfaceClass: MASSTORAGE (0x08)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  0c 00 00 00 00 00 00 00                           ........

Frame 663 (24 bytes on wire, 24 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.963201000
    [Time delta from previous captured frame: 0.000012000 seconds]
    [Time delta from previous displayed frame: 0.000012000 seconds]
    [Time since reference or first frame: 49.509977000 seconds]
    Frame Number: 663
    Frame Length: 24 bytes
    Capture Length: 24 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f6540180
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_BULK (3)
    Endpoint: 0x87
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: not present ('<')
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 13
    Data length [bytes]: 0
    [bInterfaceClass: MASSTORAGE (0x08)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  0c 02 00 00 00 00 00 00                           ........

Frame 664 (7704 bytes on wire, 7704 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.963216000
    [Time delta from previous captured frame: 0.000015000 seconds]
    [Time delta from previous displayed frame: 0.000015000 seconds]
    [Time since reference or first frame: 49.509992000 seconds]
    Frame Number: 664
    Frame Length: 7704 bytes
    Capture Length: 7704 bytes
    [Frame is marked: False]
    [Protocols in frame: usb]
USB URB
    URB id: 0x00000000f2c9ac80
    URB type: URB_SUBMIT ('S')
    URB transfer type: URB_BULK (3)
    Endpoint: 0x03
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Operation now in progress (-EINPROGRESS) (-115)
    URB length [bytes]: 7680
    Data length [bytes]: 7680
    [bInterfaceClass: PRINTER (0x07)]
    Application Data: 1B01877FFFFF6FFF05FFFF971B2A6230561B2A6230571B2A...

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  00 00 00 00 00 00 00 00 1b 01 87 7f ff ff 6f ff   ..............o.
0020  05 ff ff 97 1b 2a 62 30 56 1b 2a 62 30 57 1b 2a   .....*b0V.*b0W.*
0030  62 30 56 1b 2a 62 36 32 57 9f ff ff ff ff 03 0d   b0V.*b62W.......
0040  0c 8c 07 87 7f ff ff ab ff 01 d1 98 4f 0d 0c 8c   ............O...
0050  ff 05 01 ff ff ff ff ff ff ff ff 70 07 87 7f ff   ...........p....
0060  ff ff f8 bc 05 9f 09 0d 0c 8c 03 87 7f ff ff 65   ...............e
...
1de0  62 30 56 1b 2a 62 30 57 1b 2a 62 30 56 1b 2a 62   b0V.*b0W.*b0V.*b
1df0  30 57 1b 2a 62 30 56 1b 2a 62 30 57 1b 2a 62 30   0W.*b0V.*b0W.*b0
1e00  56 1b 2a 62 30 57 1b 2a 62 30 56 1b 2a 62 30 57   V.*b0W.*b0V.*b0W
1e10  1b 2a 62 30 56 1b 2a 62                           .*b0V.*b

Frame 665 (37 bytes on wire, 37 bytes captured)
    Arrival Time: Apr  3, 2010 17:40:19.963314000
    [Time delta from previous captured frame: 0.000098000 seconds]
    [Time delta from previous displayed frame: 0.000098000 seconds]
    [Time since reference or first frame: 49.510090000 seconds]
    Frame Number: 665
    Frame Length: 37 bytes
    Capture Length: 37 bytes
    [Frame is marked: False]
    [Protocols in frame: usb:usbms]
USB URB
    URB id: 0x00000000f6540180
    URB type: URB_COMPLETE ('C')
    URB transfer type: URB_BULK (3)
    Endpoint: 0x87
    Device: 4
    URB bus id: 1
    Device setup request: not present ('-')
    Data: present (0)
    URB status: Success (0)
    URB length [bytes]: 13
    Data length [bytes]: 13
    [Request in: 663]
    [Time from request: 0.000113000 seconds]
    [bInterfaceClass: MASSTORAGE (0x08)]
USB Mass Storage
    Signature: 0x53425355
    Tag: 0x0001155b
    DataResidue: 0
    Status: Command Failed (0x01)
SCSI Response (Test Unit Ready)
    [LUN: 0x0000]
    [Command Set:Direct Access Device (0x00) (Using default commandset)]
    [SBC Opcode: Test Unit Ready (0x00)]
    [Request in: 661]
    [Time from request: 0.000218000 seconds]
    [Status: Check Condition (0x02)]

0000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
0010  0c 02 00 00 00 00 00 00 55 53 42 53 5b 15 01 00   ........USBS[...
0020  00 00 00 00 01                                    .....

$

(In reply to comment #8)
> I also note that CUPS in F12 seems to be compiled without
> libusb support, and thus appears to rely on usblp for USB printer discovery;
> maybe it's time that was changed?

The reason for still using usblp support in the CUPS usb backend is that there are features we would lose by switching to libusb support; notably, the ability to report paper-out.

It probably wouldn't be too hard to add paper-out reporting to the libusb-aware backend.

See bug #488949 which is tracking that.

This message is a reminder that Fedora 12 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 12.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '12'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 12's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 12 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Fedora 12 changed to end-of-life (EOL) status on 2010-12-02. Fedora 12 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.