Hello!

When trying to set up the HP LaserJet 1300 printer under Linux (using
USB connection), I have found that in some circumstances the printer
locks up.  In my configuration (Linux 2.4.21, CUPS 1.1.18) the first
print job prints normally, but on the second print job the printer
locks up before printing anything and needs to be powercycled; after
this it prints the job normally, but locks up in the same way at the
beginning of the next job...

I have tried to investigate the problem and found that the lockup
happens when a program uses the LPIOC_GET_DEVICE_ID ioctl to get the
IEEE-1284 device ID immediately after opening /dev/usb/lp0, and there
is some data in the printer reverse channel at this time.  The USB
backend in CUPS unconditionally gets the device ID when asked to list
all available ports (which happens during CUPS startup), and also can
get the device ID on every print job if the printer is specified in
the CUPS configuration by its model name and serial number (this is
the default when using the builtin web interface for configuration).

I turned on debugging in printer.c and added some more debugging
statements - logging of both entry and exit in usblp_control_msg(),
usb_submit_urb(), usb_unlink_urb(), and logging in the URB completion
handler.  Here is the annotated log.

I turn on the printer:

  hub.c: new USB device 00:10.1-2, assigned address 6
  printer.c: usblp0 set protocol 2
  printer.c: > usblp_control_msg: rq: 0x00 dir: 1 recip: 1 value: 0 len: 0x3ff
  printer.c: < usblp_control_msg: rq: 0x00 dir: 1 recip: 1 value: 0 len: 0x3ff result: 
158
  printer.c: usblp0 Device ID string 
[len=158]="MFG:Hewlett-Packard;CMD:PJL,MLC,BIDI-ECP,PCL,POSTSCRIPT,PCLXL;MDL:hp 
LaserJet 1300;CLS:PRINTER;DES:Hewlett-Packard LaserJet 
1300;MEM:8MB;COMMENT:RES=1200x1;"
  printer.c: > usblp_control_msg: rq: 0x01 dir: 1 recip: 1 value: 0 len: 0x1
  printer.c: < usblp_control_msg: rq: 0x01 dir: 1 recip: 1 value: 0 len: 0x1 result: 1
  printer.c: usblp0: USB Bidirectional printer dev 6 if 0 alt 1 proto 2 vid 0x03F0 pid 
0x1017

Now I send the command to the printer (cat echo.pjl >/dev/usb/lp0):

  printer.c: > submit urb @dbdc101c, pipe=0xc0408680
  printer.c: < submit urb @dbdc101c, pipe=0xc0408680, status=-115
  printer.c: > submit urb @dbdc1074, pipe=0xc0008600
  printer.c: < submit urb @dbdc1074, pipe=0xc0008600, status=-115
  printer.c: < completed urb @dbdc1074, pipe=0xc0008600, status=0, len=29
  printer.c: > unlink urb @dbdc1074, pipe=0xc0008600
  printer.c: < unlink urb @dbdc1074, pipe=0xc0008600, status=0
  printer.c: > unlink urb @dbdc101c, pipe=0xc0408680
  printer.c: < completed urb @dbdc101c, pipe=0xc0408680, status=-2, len=0
  printer.c: < unlink urb @dbdc101c, pipe=0xc0408680, status=-2

Then I start my test program which just tries to get the device ID
with LPIOC_GET_DEVICE_ID (./printer_check /dev/usb/lp0):

  printer.c: > submit urb @dbdc101c, pipe=0xc0408680
  printer.c: < submit urb @dbdc101c, pipe=0xc0408680, status=-115
  printer.c: > usblp_control_msg: rq: 0x00 dir: 1 recip: 1 value: 0 len: 0x3ff
  printer.c: < completed urb @dbdc101c, pipe=0xc0408680, status=0, len=17

At this point the printer is hung - all 3 indicators at the front
panel are lit (according to the printer documentation this means
internal error).  After USBLP_WRITE_TIMEOUT expires, the device ID
read fails:

  usb_control/bulk_msg: timeout
  printer.c: < usblp_control_msg: rq: 0x00 dir: 1 recip: 1 value: 0 len: 0x3ff result: 
-110
  printer.c: usblp0: error = -110 reading IEEE-1284 Device ID string

I have added dumping of the full device_id_string buffer here (and
cleared it before the call):

  printer.c: 0000: 00 9e 4d 46 47 3a 48 65  77 6c 65 74 74 2d 50 61
  printer.c: 0010: 63 6b 61 72 64 3b 43 4d  44 3a 50 4a 4c 2c 4d 4c
  printer.c: 0020: 43 2c 42 49 44 49 2d 45  43 50 2c 50 43 4c 2c 50
  printer.c: 0030: 4f 53 54 53 43 52 49 50  54 2c 50 43 4c 58 4c 3b
  printer.c: 0040: 4d 44 4c 3a 68 70 20 4c  61 73 65 72 4a 65 74 20
  printer.c: 0050: 31 33 30 30 3b 43 4c 53  3a 50 52 49 4e 54 45 52
  printer.c: 0060: 3b 44 45 53 3a 48 65 77  6c 65 74 74 2d 50 61 63
  printer.c: 0070: 6b 61 72 64 20 4c 61 73  65 72 4a 65 74 20 31 33
  printer.c: 0080: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
[lots of lines with zeros skipped]
  printer.c: 03f0: 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
  printer.c: > unlink urb @dbdc1074, pipe=0xc0008600
  printer.c: < unlink urb @dbdc1074, pipe=0xc0008600, status=0
  printer.c: > unlink urb @dbdc101c, pipe=0xc0408680
  printer.c: < unlink urb @dbdc101c, pipe=0xc0408680, status=0

Seems that the lockup happens in the middle of the device ID transfer
(128 bytes were transferred successfully, but the last packet did not
arrive).  The printer can be returned to the operational state only by
switching it off and back on.

The lockup can also be triggered from a userspace program using
usbdevfs (without the printer module loaded).  I have attached such a
program (usb_printer_test.c); it is invoked as

  ./usb_printer_test /proc/bus/usb/XXX/YYY <mode>

<mode> is either "r" or "w"; the program tries to perform a bulk read
or write in paralled with the device ID read.

My tests with this program give the following results:

$ ./usb_printer_test /proc/bus/usb/002/007 r
Setting configuration 1
Claiming interface 0
Selecting altsetting 1
Reading ID...
Device ID: "MFG:Hewlett-Packard;CMD:PJL,MLC,BIDI-ECP,PCL,POSTSCRIPT,PCLXL;MDL:hp 
LaserJet 1300;CLS:PRINTER;DES:Hewlett-Packard LaserJet 
1300;MEM:8MB;COMMENT:RES=1200x1;"
Writing 29 bytes
Reading ID...
Device ID: "MFG:Hewlett-Packard;CMD:PJL,MLC,BIDI-ECP,PCL,POSTSCRIPT,PCLXL;MDL:hp 
LaserJet 1300;CLS:PRINTER;DES:Hewlett-Packard LaserJet 
1300;MEM:8MB;COMMENT:RES=1200x1;"
Submitting URB
Reading ID...
./usb_printer_test: usbdev_control_msg(read ID): Connection timed out
Reaping URB
  status=0, length=17


$ ./usb_printer_test /proc/bus/usb/002/011 w
Setting configuration 1
Claiming interface 0
Selecting altsetting 1
Reading ID...
Device ID: "MFG:Hewlett-Packard;CMD:PJL,MLC,BIDI-ECP,PCL,POSTSCRIPT,PCLXL;MDL:hp 
LaserJet 1300;CLS:PRINTER;DES:Hewlett-Packard LaserJet 
1300;MEM:8MB;COMMENT:RES=1200x1;"
Submitting URB
Reading ID...
./usb_printer_test: usbdev_control_msg(read ID): Connection timed out
Reaping URB
  status=0, length=29

The read test causes the lockup every time; the write test needs about
10-15 tries, but eventually locks up the printer too.  In both cases
the bulk transaction completes successfully, but the device ID read
fails.  USBLP_REQ_GET_STATUS did not have this problem in my tests -
only USBLP_REQ_GET_ID caused lockups when used with parallel bulk I/O
operations.  The lockups are reproducible with both usb-uhci and uhci
drivers.

I don't know what really happens on the wire, but probably the bulk
transaction happens in the middle of the control transfer, which
greatly confuses the printer firmware.

As a workaround for such printers, we may need to avoid reading the
device ID at the time LPIOC_GET_DEVICE_ID is called - instead we need
to get the device ID at the initialization time (this is already done)
and just return the saved ID in response to the ioctl.  It is possible
to reread the ID after calling usblp_set_protocol() - at this time
URBs are unlinked, so reading the ID should be safe.

I have made a patch with this workaround - it is attached.  The patch
is against drivers/usb/printer.c in Linux 2.4.21/2.4.22-rc2.  With
this workaround the printer lockup with CUPS is avoided.

-- 
Sergey Vlasov

Attachment: linux-2.4.21-usb-printer-get-id-lockup.patch
Description: Binary data

Attachment: echo.pjl
Description: Binary data

Attachment: printer_check.c
Description: Binary data

Attachment: usb_printer_test.c
Description: Binary data

Attachment: pgp00000.pgp
Description: PGP signature

Reply via email to