Bug 911727 - USB printer CANON PIXMA MP500 does not print with CUPS: "Waiting for printer to become available"
Summary: USB printer CANON PIXMA MP500 does not print with CUPS: "Waiting for printer ...
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 18
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-02-15 19:26 UTC by Patrick Proche
Modified: 2013-04-11 18:57 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-04-11 18:57:08 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
Troubleshoot file from system-config-printer (132.13 KB, text/plain)
2013-02-15 19:26 UTC, Patrick Proche
no flags Details
CUPS error log (1.73 MB, text/plain)
2013-02-19 17:35 UTC, Patrick Proche
no flags Details
Error log 20130310 (8.83 MB, text/plain)
2013-03-10 23:03 UTC, Patrick Proche
no flags Details

Description Patrick Proche 2013-02-15 19:26:49 UTC
Created attachment 697960 [details]
Troubleshoot file from system-config-printer

Description of problem:

USB printer CANON PIXMA MP500 does never print anything from any application, no matter as root or unpriviled user. When sending for example a test page from 'system-config-printer', it says first "Starting page: 1,29%", always stops at "1,29%", then says: "Untaetig [idl] - waiting for printer to become available".

No matter if I try printing from 'system-config-printer', evince, any other application or 'cat [file] | lpr', it does not print.

Also, when I browse to "http://localhost:631/admin', it says: "Internal Server Error".

'systemctl -t service --all' prints:
configure-printer               loaded inactive dead    Configure Plugged-In Printer
cups.service                                        loaded active   running CUPS Printing Service

The CANON MP500 works fine as a scanner, no problems at all.

'lpinfo -l -v' does NOT show the printer, the CUPS usb backend shows:
DEBUG: list_devices
DEBUG: libusb_get_device_list=14
DEBUG2: Printer found with device ID: MFG:Canon;CMD:BJL,BJRaster3,BSCCe;SOJ:TXT01;MDL:MP500;CLS:PRINTER;DES:Canon MP500;VER:1.09;STA:10;FSI:03;HRI:OTH; Device URI: usb://Canon/MP500?serial=50F9FF&interface=1
direct usb://Canon/MP500?serial=50F9FF&interface=1 "Canon MP500" "Canon MP500" "MFG:Canon;CMD:BJL,BJRaster3,BSCCe;SOJ:TXT01;MDL:MP500;CLS:PRINTER;DES:Canon MP500;VER:1.09;STA:10;FSI:03;HRI:OTH;" ""

UDEV entry is:
# Canon PIXMA MP500
ATTR{idVendor}=="04a9", ATTR{idProduct}=="170c", MODE:="0664", GROUP:="usb"

The '/etc/cups/cupsd.conf' file has these lines at the end which obviously produce an error. I tried to delete thes lines, but after restarting cups and send a page to the printer, they show up again:
JobPrivateAccess default
JobPrivateValues default
SubscriptionPrivateAccess default
SubscriptionPrivateValues default

Also tried to change the values, but no result.

'dmesg' gives:
[   79.669312] usb 1-2.1: new high-speed USB device number 6 using ehci_hcd
[   79.751690] usb 1-2.1: New USB device found, idVendor=04a9, idProduct=170c
[   79.751695] usb 1-2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[   79.751698] usb 1-2.1: Product: MP500
[   79.751702] usb 1-2.1: Manufacturer: Canon
[   79.751705] usb 1-2.1: SerialNumber: 50F9FF
[   79.756395] scsi7 : usb-storage 1-2.1:1.2
[   79.815121] usblp 1-2.1:1.1: usblp0: USB Bidirectional printer dev 6 if 1 alt 0 proto 2 vid 0x04A9 pid 0x170C
[   79.815420] usbcore: registered new interface driver usblp
[   80.766495] scsi 7:0:0:0: Direct-Access     Canon    MP500Storage     0109 PQ: 0 ANSI: 2
[   80.779978] sd 7:0:0:0: [sdn] Attached SCSI removable disk
[  246.332450] lp0: using parport0 (interrupt-driven).
[  685.918273] fuse init (API version 7.20)
[ 1687.025224] usblp0: removed
[ 1687.030580] usblp 1-2.1:1.1: usblp0: USB Bidirectional printer dev 6 if 1 alt 0 proto 2 vid 0x04A9 pid 0x170C

Tried to downgrade cups, but useless, no printing. Tried different drivers, no printing.

It used to work fine in FC14, I did an installation from scratch to FC18. Since then, no printing.

Version-Release number of selected component (if applicable):
cups-1.5.4-20.fc18.x86_64
cups-libs-1.5.4-20.fc18.x86_64
gutenprint-cups-5.2.9-2.fc18.x86_64

How reproducible:
Always

Steps to Reproduce:
1. boot machine
2. print
3. nothing happens
  
Actual results:
No printing at all.

Expected results:
Printing, as it did before in FC14 with exactly the same hardware.

Additional info:
Attached is the troubleshoot file from system-config-printer.

Comment 1 Jiri Popelka 2013-02-18 15:50:34 UTC
(In reply to comment #0)
> 'systemctl -t service --all' prints:
> configure-printer               loaded inactive dead   

Not sure whether this is good or bad, could you add output of 'systemctl status onfigure-printer' ?

Note to myself:
There's already a usb quirk rule for MP500 (https://bugs.launchpad.net/bugs/1032456)

Comment 2 Jiri Popelka 2013-02-18 15:52:04 UTC
(In reply to comment #1)
> 'systemctl status onfigure-printer'

there's typo, should say configure-printer@

Comment 3 Patrick Proche 2013-02-18 18:21:53 UTC
UNIT                                                                  LOAD   ACTIVE   SUB     DESCRIPTION
[...]
configure-printer                                 loaded inactive dead    Configure Plugged-In Printer
crond.service                                                         loaded active   running Command Scheduler
cups.service                                                          loaded active   running CUPS Printing Service
[...]

Comment 4 Patrick Proche 2013-02-18 18:25:55 UTC
Pls note that I am on holidays from tomorrow on, so I will not answer for approx. two weeks.
I did a 'yum update' and upgraded to a new kernel today, but the behavior is the same. I read 'https://bugs.launchpad.net/ubuntu/+source/cups/+bug/1032456' but the problem is, I do not even get half a page, I get nothing.
Patrick

Comment 5 Jiri Popelka 2013-02-19 13:34:30 UTC
comment #3 does not look like output of 'systemctl status'

Once you're back, please try these instructions:
1) update to gutenprint-5.2.9-9.fc18
   - download RPMs from http://koji.fedoraproject.org/koji/taskinfo?taskID=5032746 and run su -c "yum --nogpgcheck localupdate *.rpm" in that directory
2) turn printer off
3) delete the printer queue in http://localhost:631/printers/ or in system-config-printer
4) su -c 'cupsctl LogLevel=debug2'
   su -c '/sbin/systemctl stop cups.service'
   su -c '>/var/log/cups/error_log'
   su -c '/sbin/systemctl start cups.service'
5) turn printer on
6) once the printer queue seems to be auto-configured
   - systemctl -t service --all | grep configure-printer
   - systemctl status configure-printer (where X,Y are from previous command)
7) try to print test page
8) attach /var/log/cups/error_log

Comment 6 Patrick Proche 2013-02-19 13:52:33 UTC
I just tried, but yum does not let me because of dependencies (poppler and related).

Comment 7 Jiri Popelka 2013-02-19 14:08:37 UTC
What exactly do you see ? I've tried it now and it's been OK.

Comment 8 Patrick Proche 2013-02-19 17:18:40 UTC
Sorry!
>systemctl status configure-printer

configure-printer - Configure Plugged-In Printer
          Loaded: loaded (/usr/lib/systemd/system/configure-printer@.service; static)
          Active: inactive (dead)

Comment 9 Patrick Proche 2013-02-19 17:34:15 UTC
Sorry again, I could update the gutenprint packages. No problem with dependencies anymore.

Followed your steps 1 to 8:

Installed the RPMs, nothing in the printer queue.

# systemctl -t service --all | grep configure-printer

shows nothing.

# systemctl status configure-printer
configure-printer - Configure Plugged-In Printer
          Loaded: loaded (/usr/lib/systemd/system/configure-printer@.service; static)
          Active: inactive (dead)

Printed test page from system-config-printer. as before, it shows that it starts the printing, but hangs after a few seconds with:

"Ausfuehrung laeuft [=transaction active] - Waiting for printer to become available."

No page. I attach the error log.

Comment 10 Patrick Proche 2013-02-19 17:35:06 UTC
Created attachment 699558 [details]
CUPS error log

Comment 11 Jiri Popelka 2013-02-20 10:06:16 UTC
(In reply to comment #9)
> nothing in the printer queue.

Not sure we understand each other.
With 'printer queue' I had meant the printer, not the jobs queue.
Did you delete the printer ?

Note:
what I'm trying to achieve is to recreate the 'printer queue' before we try anything else as it could perhaps be somehow badly auto-configured.

Comment 12 Jiri Popelka 2013-02-20 11:07:01 UTC
At the moment I can see these oddities in the error_log:

> D [Job 124] libusb_get_device_list=14

Does that claim that there are 14 usb devices ?

> D [Job 124] Failed to open device, code: -3

-3 == LIBUSB_ERROR_ACCESS == the user has insufficient permissions

Comment 13 Tim Waugh 2013-02-20 13:37:44 UTC
Ah, I wonder if SELinux is blocking it.  I've occasionally seen an AVC message preventing the usb backend from getting at the device node, but haven't been able to reproduce it to investigate further.

Patrick: if you run 'setenforce 0' to set SELinux into permissive mode, does it make any difference?

Comment 14 Patrick Proche 2013-03-10 23:01:17 UTC
I tried "setenforce 0" before, but I tried it again just now. Made and still makes no difference.

I deleted the printer in system-config-printer and followed the steps 2 to 8 above:

# systemctl -t service --all | grep configure-printer
NO RESULT (why? see below)

# systemctl status configure-printer
configure-printer - Configure Plugged-In Printer
          Loaded: loaded (/usr/lib/systemd/system/configure-printer@.service; static)
          Active: failed (Result: exit-code) since So 2013-03-10 23:11:23 CET; 35min ago
         Process: 3842 ExecStart=/usr/lib/udev/udev-configure-printer add %i (code=exited, status=1/FAILURE)

Mär 10 23:11:22 localhost.localdomain systemd[1]: Starting Configure Plugged-In Printer...
Mär 10 23:11:22 localhost.localdomain systemd[1]: Started Configure Plugged-In Printer.
Mär 10 23:11:22 localhost.localdomain udev-configure-printer[3842]: add usb-007-006
Mär 10 23:11:23 localhost.localdomain udev-configure-printer[3842]: no device named /dev/bus/usb/007/006 found
Mär 10 23:11:23 localhost.localdomain systemd[1]: configure-printer: main process exited, code=exited, status=1/FAILURE
Mär 10 23:11:23 localhost.localdomain systemd[1]: Unit configure-printer entered failed state

# systemctl status configure-printer
configure-printer - Configure Plugged-In Printer
          Loaded: loaded (/usr/lib/systemd/system/configure-printer@.service; static)
          Active: inactive (dead) since So 2013-03-10 23:37:22 CET; 8min ago
         Process: 4711 ExecStart=/usr/lib/udev/udev-configure-printer add %i (code=exited, status=0/SUCCESS)

Mär 10 23:37:20 localhost.localdomain systemd[1]: Starting Configure Plugged-In Printer...
Mär 10 23:37:20 localhost.localdomain systemd[1]: Started Configure Plugged-In Printer.
Mär 10 23:37:20 localhost.localdomain udev-configure-printer[4711]: add usb-007-008
Mär 10 23:37:20 localhost.localdomain udev-configure-printer[4711]: device devpath is /devices/pci0000:00/0000:00:1a.7/usb7/7-2/7-2.1
Mär 10 23:37:20 localhost.localdomain udev-configure-printer[4711]: MFG:Canon MDL:MP500 SERN:- serial:50F9FF

Configured the printer in system-config-printer with address "usb://Canon/MP500?serial=50F9FF&interface=1", then printed the test page.

I attach the new error log.

Comment 15 Patrick Proche 2013-03-10 23:03:03 UTC
Created attachment 708100 [details]
Error log 20130310

Comment 16 Patrick Proche 2013-03-26 17:02:51 UTC
Do you need more information regarding my printer?

Comment 18 Tim Waugh 2013-04-11 09:35:28 UTC
Could you please try this systemd update?  I wonder if the bug it fixes might be the cause of the problem.

https://bugzilla.redhat.com/show_bug.cgi?id=922279#c6
https://admin.fedoraproject.org/updates/systemd-201-2.fc18.1

Comment 19 Patrick Proche 2013-04-11 18:57:08 UTC
After trying around with changing udev rules, I managed to print. I must note in my favour that these udev rules worked before, no idea why not later.

I am very sorry to have caused this mess. Of course I mark this as closed.


Note You need to log in before you can comment on or make changes to this bug.