USB Printer not re-enabled after printer power off

[David Mitchell]

Possibly udev bug.
After last updates to Lucid (10.04 LTS).

libusb-0.1-4 2:0.1.12-14ubuntu0.2
libusb-1.0-0 2:1.0.6-1
udev 151-12.2
uname -a gives
Linux fitsserver 2.6.32-26-server #48-Ubuntu SMP Wed Nov 24 10:28:32 UTC 2010 x86_64 GNU/Linux

I have a server running 24/7 which has a canon USB printer connected. The canon is on a switched mains supply so is turned off every day when not in use.
Previously this worked fine - the server would see the canon turned on and the Print queue would be re-enabled.
After the last round of updates this no longer works. Replugging the printer will make it work.
I have just tested and the syslog is below with interline comments at ***:

Thanks

David

*** Turn printer off at mains - usb device removed OK
Dec 16 09:57:41 fitsserver kernel: [521189.771560] usblp0: nonzero read bulk status received: -84
Dec 16 09:57:41 fitsserver init: Handling class-device-removed event
Dec 16 09:57:41 fitsserver init: Handling usb-device-removed event
Dec 16 09:57:41 fitsserver init: Handling usb-device-removed event
Dec 16 09:57:41 fitsserver kernel: [521189.790095] usb 3-2: USB disconnect, address 23
Dec 16 09:57:41 fitsserver kernel: [521189.790446] usblp0: removed
Dec 16 09:57:41 fitsserver udev-configure-printer: remove /devices/pci0000:00/0000:00:1d.1/usb3/3-2
Dec 16 09:57:41 fitsserver udev-configure-printer: URI of print queue: lpd://10.55.12.101/PASSTHRU, normalized: lpd 10 55 12 101 passthru
Dec 16 09:57:41 fitsserver udev-configure-printer: URI of detected printer: usb://Canon/i965, normalized: canon i965
Dec 16 09:57:41 fitsserver udev-configure-printer: URI of print queue: lpd://10.55.12.101/PASSTHRU, normalized: lpd 10 55 12 101 passthru
Dec 16 09:57:41 fitsserver udev-configure-printer: URI of detected printer: usb://Canon/i965, normalized: canon i965
Dec 16 09:57:41 fitsserver udev-configure-printer: URI of print queue: usb://Canon/i965, normalized: canon i965
Dec 16 09:57:41 fitsserver udev-configure-printer: URI of detected printer: usb://Canon/i965, normalized: canon i965
Dec 16 09:57:41 fitsserver udev-configure-printer: Queue ipp://localhost:631/printers/i965 has matching device URI
Dec 16 09:57:41 fitsserver udev-configure-printer: Disabled printer ipp://localhost:631/printers/i965 as the corresponding device was unplugged or turned off
Dec 16 09:57:41 fitsserver init: Handling usb-device-removed event

*** Now turn printer back on:
Dec 16 09:57:55 fitsserver kernel: [521204.481335] usb 3-2: new full speed USB device using uhci_hcd and address 24
Dec 16 09:57:55 fitsserver kernel: [521204.685303] usb 3-2: configuration #1 chosen from 1 choice
Dec 16 09:57:55 fitsserver init: Handling usb-device-added event
Dec 16 09:57:55 fitsserver init: Handling class-device-added event
Dec 16 09:57:55 fitsserver kernel: [521204.706361] usblp0: USB Bidirectional printer dev 24 if 0 alt 0 proto 2 vid 0x04A9 pid 0x1088
Dec 16 09:57:55 fitsserver udev-configure-printer: add /devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2:1.0
Dec 16 09:57:55 fitsserver udev-configure-printer: parent devpath is /devices/pci0000:00/0000:00:1d.1/usb3/3-2
Dec 16 09:57:55 fitsserver udev-configure-printer: Device vendor/product is 04A9:1088
Dec 16 09:57:55 fitsserver init: Handling usb-device-added event
Dec 16 09:57:55 fitsserver init: Handling usb-device-added event

*** Ooops I think this is the problem...
Dec 16 09:57:55 fitsserver udev-configure-printer: add /devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2:1.0/usb/lp0
Dec 16 09:57:56 fitsserver udev-configure-printer: failed to claim interface
Dec 16 09:57:56 fitsserver udev-configure-printer: invalid or missing IEEE 1284 Device ID
Dec 16 09:57:56 fitsserver udev-configure-printer: parent devpath is /devices/pci0000:00/0000:00:1d.1/usb3/3-2
Dec 16 09:57:56 fitsserver udev-configure-printer: MFG:Canon MDL:i965 SERN:- serial:210805
Dec 16 09:57:57 fitsserver kernel: [521205.844652] usb 3-2: usbfs: interface 0 claimed by usblp while 'usb' sets config #1
Dec 16 09:57:57 fitsserver hp[28556]: io/hpmud/pp.c 627: unable to read device-id ret=-1
Dec 16 09:57:57 fitsserver python: io/hpmud/pp.c 627: unable to read device-id ret=-1

*** Now UNPLUG printer
Dec 16 10:00:24 fitsserver kernel: [521352.888121] usbcore: deregistering interface driver usblp
Dec 16 10:00:24 fitsserver kernel: [521352.888549] usblp0: removed
Dec 16 10:00:24 fitsserver init: Handling class-device-removed event
Dec 16 10:00:24 fitsserver init: Handling usb-device-removed event
Dec 16 10:00:24 fitsserver init: Handling module-device-removed event
Dec 16 10:00:24 fitsserver init: Handling drivers-device-removed event

Dec 16 10:00:51 fitsserver init: Handling usb-device-removed event
Dec 16 10:00:51 fitsserver kernel: [521380.300088] usb 3-2: USB disconnect, address 24
Dec 16 10:00:51 fitsserver udev-configure-printer: remove /devices/pci0000:00/0000:00:1d.1/usb3/3-2
Dec 16 10:00:51 fitsserver init: Handling usb-device-removed event

*** And plug it back in
Dec 16 10:01:01 fitsserver kernel: [521390.661300] usb 3-2: new full speed USB device using uhci_hcd and address 25
Dec 16 10:01:02 fitsserver kernel: [521390.838310] usb 3-2: configuration #1 chosen from 1 choice
Dec 16 10:01:02 fitsserver init: Handling usb-device-added event
Dec 16 10:01:02 fitsserver udev-configure-printer: add /devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2:1.0
Dec 16 10:01:02 fitsserver udev-configure-printer: parent devpath is /devices/pci0000:00/0000:00:1d.1/usb3/3-2
Dec 16 10:01:02 fitsserver udev-configure-printer: Device vendor/product is 04A9:1088
Dec 16 10:01:02 fitsserver udev-configure-printer: MFG:Canon MDL:i965 SERN:- serial:210805
Dec 16 10:01:02 fitsserver init: Handling module-device-added event
Dec 16 10:01:02 fitsserver init: Handling class-device-added event
Dec 16 10:01:02 fitsserver init: Handling usb-device-added event
Dec 16 10:01:02 fitsserver init: Handling drivers-device-added event
Dec 16 10:01:02 fitsserver kernel: [521390.993390] usblp0: USB Bidirectional printer dev 25 if 0 alt 0 proto 2 vid 0x04A9 pid 0x1088
Dec 16 10:01:02 fitsserver kernel: [521390.993462] usbcore: registered new interface driver usblp
Dec 16 10:01:02 fitsserver init: Handling usb-device-added event
Dec 16 10:01:02 fitsserver udev-configure-printer: add /devices/pci0000:00/0000:00:1d.1/usb3/3-2/3-2:1.0/usb/lp0
Dec 16 10:01:03 fitsserver kernel: [521392.020794] usb 3-2: usbfs: interface 0 claimed by usblp while 'usb' sets config #1
Dec 16 10:01:03 fitsserver hp[28632]: io/hpmud/pp.c 627: unable to read device-id ret=-1
Dec 16 10:01:03 fitsserver python: io/hpmud/pp.c 627: unable to read device-id ret=-1
Dec 16 10:01:05 fitsserver udev-configure-printer: URI matches without serial number: usb://Canon/i965
Dec 16 10:01:05 fitsserver udev-configure-printer: No serial number URI matches so using those without
Dec 16 10:01:05 fitsserver udev-configure-printer: URI of print queue: lpd://10.55.12.101/PASSTHRU, normalized: lpd 10 55 12 101 passthru
Dec 16 10:01:05 fitsserver udev-configure-printer: URI of detected printer: usb://Canon/i965, normalized: canon i965
Dec 16 10:01:05 fitsserver udev-configure-printer: URI of print queue: lpd://10.55.12.101/PASSTHRU, normalized: lpd 10 55 12 101 passthru
Dec 16 10:01:05 fitsserver udev-configure-printer: URI of detected printer: usb://Canon/i965, normalized: canon i965
Dec 16 10:01:05 fitsserver udev-configure-printer: URI of print queue: usb://Canon/i965, normalized: canon i965
Dec 16 10:01:05 fitsserver udev-configure-printer: URI of detected printer: usb://Canon/i965, normalized: canon i965

*** and printer is recognised...
Dec 16 10:01:05 fitsserver udev-configure-printer: Queue ipp://localhost:631/printers/i965 has matching device URI
Dec 16 10:01:05 fitsserver udev-configure-printer: parent devpath is /devices/pci0000:00/0000:00:1d.1/usb3/3-2
Dec 16 10:01:05 fitsserver udev-configure-printer: Re-enabled printer ipp://localhost:631/printers/i965

[NoOp (glgxg)]

Affects me as well. I find that I have to renable from the System|Administration|Printers on boot.

Syslog shows:

May 1 10:05:22 gg kernel: [ 806.315562] audit_printk_skb: 63 callbacks suppressed
May 1 10:05:22 gg kernel: [ 806.315568] type=1400 audit(1304269522.507:33): apparmor="ALLOWED" operation="mknod" parent=1 profile="/usr/sbin/nmbd" name="/var/run/samba/namelist.debug" pid=1321 comm="nmbd" requested_mask="c" denied_mask="c" fsuid=0 ouid=0
May 1 10:05:22 gg kernel: [ 806.315591] type=1400 audit(1304269522.507:34): apparmor="ALLOWED" operation="open" parent=1 profile="/usr/sbin/nmbd" name="/var/run/samba/namelist.debug" pid=1321 comm="nmbd" requested_mask="wc" denied_mask="wc" fsuid=0 ouid=0
May 1 10:08:29 gg anacron[1399]: Job `cron.daily' terminated
May 1 10:08:29 gg anacron[1399]: Normal exit (1 job run)
May 1 10:17:01 gg CRON[25332]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
May 1 11:04:20 gg kernel: [ 4344.104025] usb 1-2: new high speed USB device using ehci_hcd and address 4
May 1 11:04:20 gg kernel: [ 4344.268614] WARNING! power/level is deprecated; use power/control instead
May 1 11:04:20 gg udev-configure-printer: add /devices/pci0000:00/0000:00:1d.7/usb1/1-2/1-2:1.1
May 1 11:04:20 gg udev-configure-printer: parent devpath is /devices/pci0000:00/0000:00:1d.7/usb1/1-2
May 1 11:04:20 gg udev-configure-printer: Device vendor/product is 04A9:1706
May 1 11:04:20 gg kernel: [ 4344.309361] usblp0: USB Bidirectional printer dev 4 if 1 alt 0 proto 2 vid 0x04A9 pid 0x1706
May 1 11:04:20 gg kernel: [ 4344.310630] usbcore: registered new interface driver usblp
May 1 11:04:20 gg udev-configure-printer: add /devices/pci0000:00/0000:00:1d.7/usb1/1-2/1-2:1.1/usb/lp0
May 1 11:04:20 gg udev-configure-printer: failed to claim interface
May 1 11:04:20 gg udev-configure-printer: invalid or missing IEEE 1284 Device ID
May 1 11:04:20 gg udev-configure-printer: parent devpath is /devices/pci0000:00/0000:00:1d.7/usb1/1-2
May 1 11:04:20 gg udev-configure-printer: MFG:Canon MDL:MP750 SERN:- serial:5039E6
May 1 11:04:21 gg kernel: [ 4345.481482] usb 1-2: usbfs: interface 1 claimed by usblp while 'usb' sets config #1
May 1 11:04:21 gg hp[25394]: io/hpmud/pp.c 627: unable to read device-id ret=-1
May 1 11:04:22 gg python: io/hpmud/pp.c 627: unable to read device-id ret=-1

Linux gg 2.6.35-29-generic #51-Ubuntu SMP Fri Apr 15 17:13:54 UTC 2011 i686 GNU/Linux

$ apt-cache policy udev
udev:
  Installed: 162-2.2
  Candidate: 162-2.2
  Version table:
 *** 162-2.2 0
        500 http://us.archive.ubuntu.com/ubuntu/ maverick-updates/main i386 Packages
        100 /var/lib/dpkg/status
     162-2 0
        500 http://us.archive.ubuntu.com/ubuntu/ maverick/main i386 Packages

Printer is a Canon MP750.
$ lsusb
...
Bus 001 Device 004: ID 04a9:1706 Canon, Inc. PIXMA MP750 Scanner

Possibly related?
https://bugs.launchpad.net/ubuntu/+source/system-config-printer/+bug/459648
[udev-configure-printer /invalid or missing IEEE 1284 Device ID]

[NoOp (glgxg)]

Not printer related as I have the same issue with an Epson Workforce 635:

Bus 001 Device 005: ID 04b8:085d Seiko Epson Corp.
$ apt-cache policy udev
udev:
  Installed: 162-2.2
  Candidate: 162-2.2
$ apt-cache policy udev
udev:
  Installed: 162-2.2
  Candidate: 162-2.2
$ apt-cache policy cups
cups:
  Installed: 1.4.4-6ubuntu2.4
  Candidate: 1.4.4-6ubuntu2.4

Found something of interest in the Cups access log - the following was from boot/startup:
localhost - - [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 401 180 Pause-Printer successful-ok
localhost - root [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 200 180 Pause-Printer successful-ok
localhost - - [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 401 186 Pause-Printer successful-ok
localhost - root [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 200 186 Pause-Printer successful-ok
localhost - - [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 401 183 Pause-Printer successful-ok
localhost - root [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 200 183 Pause-Printer successful-ok
localhost - - [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 401 183 Pause-Printer successful-ok
localhost - root [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 200 183 Pause-Printer successful-ok
localhost - - [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 401 186 Pause-Printer successful-ok
localhost - root [31/Mar/2012:10:32:57 -0700] "POST /admin/ HTTP/1.1" 200 186 Pause-Printer successful-ok

and after discovering that I can't print, so manually reenabling the printers via System|Administration|Printers:
localhost - - [31/Mar/2012:11:33:15 -0700] "POST /admin/ HTTP/1.1" 401 127 Resume-Printer successful-ok
localhost - gg [31/Mar/2012:11:33:15 -0700] "POST /admin/ HTTP/1.1" 200 127 Resume-Printer successful-ok
localhost - gg [31/Mar/2012:11:33:24 -0700] "POST /admin/ HTTP/1.1" 200 130 Resume-Printer successful-ok
localhost - gg [31/Mar/2012:11:33:27 -0700] "POST /admin/ HTTP/1.1" 200 133 Resume-Printer successful-ok
localhost - gg [31/Mar/2012:11:33:32 -0700] "POST /admin/ HTTP/1.1" 200 130 Resume-Printer successful-ok
localhost - gg [31/Mar/2012:11:33:35 -0700] "POST /admin/ HTTP/1.1" 200 133 Resume-Printer successful-ok

I think the key is figuring out what is causing 'Pause-Printer successful-ok'

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Marcel Partap (empee584)]

Ok, after a deep look into this it seems the usblp kernel module does not set the ieee1284_id proper, which makes system-config-printer-udev skip the device even though the serial number is present..
I tested this for my setup (after going in circles for a good while) with:
# watch -d -n 1 'cat /sys/devices/pci0000\:00/0000\:00\:02.1/usb1/1-3/1-3\:1.1/ieee1284_id'
USB hub and port number do not change by themself, so when unplugging you can see the file disappear and reappear on replug. However, when doing a power off/up cycle of the device, it is populated only incompletely:
"MODE:PCL;STATUS:IDLE;"
Waiting does not help.. However, executing /usr/lib/cups/backend/usb does! A quick strace shows that it sends some IOCTLs to the USB sub system, which makes the correct ieee1284_id reinitialize - after that manual printer resume with "config-printer-udev" does work. Here, my ambition to further nail the issue is exhausted - not going to dive into kernel debugging on a saturday evening C-;
someone have a look at code in that backend, please ;-)

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.