Bug 967873 - printer blocked when second page contains only a few lines
printer blocked when second page contains only a few lines
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: cups (Show other bugs)
18
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: Tim Waugh
Fedora Extras Quality Assurance
:
: 967879 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-05-28 09:05 EDT by joerg.lechner
Modified: 2013-07-16 00:35 EDT (History)
3 users (show)

See Also:
Fixed In Version: cups-1.6.2-12.fc19
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-07-01 20:34:20 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
error_log of first printing after reinstallation, F19 TC5 LXDE i686 (29.97 KB, text/plain)
2013-06-21 15:17 EDT, joerg.lechner
no flags Details
F18_64 /var/log/cups/error_log (10.54 KB, text/plain)
2013-06-22 00:27 EDT, joerg.lechner
no flags Details
F18_64 printer no page eject --> error_log zipped (99.97 KB, application/gzip)
2013-06-22 02:11 EDT, joerg.lechner
no flags Details
error_ log first printing after installation, F19 TC6 LXDE i686 --- zipped version (14.83 KB, application/gzip)
2013-06-22 07:53 EDT, joerg.lechner
no flags Details
F18 test, 3 prints, 2 successful, 3rd unsuccessful (7.17 MB, text/plain)
2013-06-24 11:19 EDT, joerg.lechner
no flags Details
attachement to comment 20, first print successful, second print unsuccessful (121.31 KB, application/gzip)
2013-06-24 12:29 EDT, joerg.lechner
no flags Details

  None (edit)
Description joerg.lechner 2013-05-28 09:05:33 EDT
Description of problem:
new installation FC19, RC4, LXDE Live iso i686.
there was previously an error in Gutenprint-Cups, which seems now to be solved, because the new version of mtpaint (mtpaint-3.40-11.fc19) seems to comprize part of kprinter now (Reason Bug 964588)
Previously (without install of kprinter) there was an error in Gutenprint-Cups. When I printed 2 pages text, the second page only with a few lines (about 5 or 6). Then there was no page eject on my Canon Pixma MP540 for the second page. The printer was blocked totally. I had manually - by hand - to pull out the hanging sheet of paper, It was not possible to switch off the printer. I had to power off the printer by unplugging from the power to be able to start again. This happens also in FC18 still now, I think I don't have mtpaint-3.40-11 in my fc18 installation (64 bit, Gnome Desktop).

Is it worthwhile to write a bug? Or is the solution of this problem with mtpaint-3.40-11 sufficient? I think on FC18 Gnome Desktop I have no mtpaint installed.


Version-Release number of selected component (if applicable):
current version of Gutenprint-Cups (27-05-2013), or elder version

How reproducible:
In my system with a Canon Pixma MP540 it's easy.
Print 2 pages text, second page should contain only 5 or 6 lines on the top.
If this happens also with other printers, I don't know.

Steps to Reproduce:
1. printing 2 pages text, second page contains onla some lines
2.
3.

Actual results:
Printer blocked totally while trying to finish printing on the second page

Expected results:
printing 2 pages of text.


Additional info:
Comment 1 Tim Waugh 2013-05-28 12:08:47 EDT
*** Bug 967879 has been marked as a duplicate of this bug. ***
Comment 4 Tim Waugh 2013-06-14 07:13:29 EDT
I'm finding it hard to understand the problem you're describing.

What is the relevance of mtpaint?

Please use smaller steps in your 'how to reproduce', e.g. start a particular application, select File->Print, select this, click that, etc.
Comment 5 joerg.lechner 2013-06-15 05:37:02 EDT
I have had another cups-gutenprint error in mtpaint. There is written a bug about. Mtpaint did not display a printer menue. This problem was solved by including kprinter (or part of it) in that build, where mtpaint is included.
As I have read, now in F19 mtpaint and with it kprinter is included (if I have read correctly). Therefore this problem should not appear anymore in F19. But I can look only into F19 LXDE desktop. It's the only F19 Testsystem I can use in my old PC. I did not test F18 (Gnome desktop) in the last time aghain. I will try this test after the last updates with F18 again and then report here.

The test steps in my configuration are very simple (F18, Gnome desktop on a Samsung X22 Laptop, Canon Printer Pixma MP540, a file to print comprizing 1 full page and a second page with some lines (i.e. about 6 lines). Try to print this file. My printer stops after having printed the 6 lines of the second page, the printer is then in a blocked state, I have to pull out the partly printed page by hand, unplug the printer from the power, and start again.

But I will do this F18 - Canon MP540 test in about one hour again and report the current situation.
Comment 6 joerg.lechner 2013-06-15 07:09:45 EDT
Test with F18 after Yum Extender update, just right now.
gutenprint-cups 5.2.9-7.fc18
Printing from Firefox (e-mails, for me the easiest way to find a for this test suitable file to print)
After Laptop start and printer start, I printed 2x one page, first time 5 lines, second time nearly one full page successfully. Then a file comprizing one page and about 10 lines (it's not neccessary to have exact 10 lines, but I think it should be about less than a half page)  on the following second page. First page was successfully printed, after having printed the 10 lines of the second page, there were about 10 line feeds, since that event the printer is blocked. The printer shows that the printing is not yet finished, I feel the printer is waiting for something, which does not come.
I hope I have made this test understandable.
Comment 7 Tim Waugh 2013-06-17 07:10:14 EDT
OK, thanks.

Could you please perform the following steps in order to get debugging logs?:

1. su -c 'cupsctl --debug-logging'
2. Try printing again
3. su -c 'cupsctl --no-debug-logging'

Finally, attach /var/log/cups/error_log to this report using the 'Add an attachment' link above.
Comment 8 joerg.lechner 2013-06-17 14:16:38 EDT
Tried to test with cups debug logging. I don't know what went wrong.
I printed 1 page with 20 lines successfully.
Activated debug logging
Started to print again.
The printer showed on the printer display "job printing from PC"
But also after 4 minutes waiting time, there was no printing.
Deactivated debug logging.
--> No error logfile of this print, there is still an error log file from my last unsuccessful print tryings two hours ago, but this logfile is not reliable, I had tried too much. Therefore I had made a "clean system" by restarting before the final test.
I can only give the access_log, which is not much helpful.

localhost - root [17/Jun/2013:19:44:55 +0200] "PUT /admin/conf/cupsd.conf HTTP/1.1" 201 3168 - -
localhost - - [17/Jun/2013:19:45:26 +0200] "POST /printers/Canon-MP540-series HTTP/1.1" 200 49891 Print-Job successful-ok
localhost - - [17/Jun/2013:19:49:23 +0200] "PUT /admin/conf/cupsd.conf HTTP/1.1" 401 0 - -
localhost - root [17/Jun/2013:19:49:23 +0200] "PUT /admin/conf/cupsd.conf HTTP/1.1" 201 3159 - -
localhost - - [17/Jun/2013:19:49:53 +0200] "POST / HTTP/1.1" 200 253 Create-Printer-Subscription successful-ok
localhost - - [17/Jun/2013:19:49:59 +0200] "POST / HTTP/1.1" 200 342 Create-Printer-Subscription successful-ok
localhost - - [17/Jun/2013:19:49:59 +0200] "POST / HTTP/1.1" 200 342 Create-Printer-Subscription successful-ok
localhost - - [17/Jun/2013:19:51:02 +0200] "POST /jobs/ HTTP/1.1" 200 140 Cancel-Job successful-ok
localhost - - [17/Jun/2013:19:51:33 +0200] "POST / HTTP/1.1" 200 153 Cancel-Subscription successful-ok
localhost - - [17/Jun/2013:19:51:33 +0200] "POST / HTTP/1.1" 200 153 Cancel-Subscription successful-ok
localhost - - [17/Jun/2013:19:51:35 +0200] "POST / HTTP/1.1" 200 153 Cancel-Subscription successful-ok

Do You have an idea, how to proceed?
~
Comment 9 Tim Waugh 2013-06-21 05:02:02 EDT
access_log is no help at all, but error_log might tell us exactly what the problem is.  Please try to get the error_log.

To start from "clean", just do this:

1. As root, do:

systemctl stop cups.{service,socket,path}
>/var/log/cups/error_log
systemctl start cups.{socket,path,service}
cupsctl --debug-logging

2. Now do whatever you need to do to make the problem happen

3. As root:

cupsctl --no-debug-logging

4. Finally, attach /var/log/cups/error_log here
Comment 10 joerg.lechner 2013-06-21 15:04:07 EDT
Sorry I have commented this already in closed bug about mtpaint printing error (Bug 964588), sorry for this.

Reinstall, the attachement error_log is the first print after installation -- result: no page eject --> printer says: "printing from PC", the printer seems to be waiting. I have deleted the "old" error_log before starting this test.

If this is not helpful, we should try to verify on F18.

What I did:
[root@localhost cups]# rm error_log
rm: reguläre Datei „error_log“ entfernen? y
[root@localhost cups]# systemctl stop cups.service
Warning: Stopping cups.service, but it can still be activated by:
  cups.socket
  cups.path
[root@localhost cups]# systemctl stop cups.socket
[root@localhost cups]# systemctl stop cups.path /var/log/cups/error_log
Failed to issue method call: Unit var-log-cups-error_log.mount not loaded.
[root@localhost cups]# systemctl stop cups.path
[root@localhost cups]# systemctl start cups.socket
[root@localhost cups]# systemctl start cups.path
[root@localhost cups]# systemctl start cups.service
[root@localhost cups]# cupsctrl --debug-logging
bash: cupsctrl: Kommando nicht gefunden.
[root@localhost cups]# cupsctl --debug-logging
[root@localhost cups]# cupsctl --no-debug-logging
[root@localhost cups]# dir
access_log  error_log  page_log
[root@localhost cups]# vi error_log
[root@localhost cups]#

The test was:
-installation F19 TC6 LXDE iso i686
-Yum Extender Update
-Firefox installation
-printer installation (Canon Pixma MP540)
-reload of system
-printing 1 e-mail from Firefox, about ten lines text

Result: print ok, but no page eject, printer waiting in state "printing from PC"

I add the error_log as attachement.
Comment 11 joerg.lechner 2013-06-21 15:17:23 EDT
Created attachment 763940 [details]
error_log of first printing after reinstallation, F19 TC5 LXDE i686

/var/log/cups/error_log
Comment 12 joerg.lechner 2013-06-22 00:06:31 EDT
Performed the same test with the same result -no page eject, printer waiting, --> printer blocked on a Samsung X22 Laptop, F18_64. Kernel 3.9.6-200.fc18,
Gutenberg-Cups 5.2.9.-7.fc18. Yum Extender shows mtpaint installed, but I can not find it in the menues. Yum-Extender shows no kprinter installed.

File I have printed (in F19 and in F18 test)

Von:		bugzilla <bugzilla@redhat.com>
An:		joerg.lechner <joerg.lechner@aol.de>
Betreff:		[Bug 964588] no printing (gutenprint-cups, printer Canon Pixma MP540) with mtpaint FC19 RC2
Datum:		Do, 20 Jun 2013 1:05 pm

https://bugzilla.redhat.com/show_bug.cgi?id=964588

--- Comment #27 from Tim Waugh <twaugh@redhat.com> ---
'iotop' is for finding processes that use a lot of I/O.  To find processing
using a lot of CPU use 'top'.

-- 
You are receiving this mail because:
You reported the bug.

I try to attach the error_log as attachement file, if not possible, copy&paste. If this is not sufficient I can send the error_log in a separate e-mail
Comment 13 joerg.lechner 2013-06-22 00:27:07 EDT
Created attachment 764024 [details]
F18_64 /var/log/cups/error_log

printer blocked, seems to wait for an page eject, which seems not to come.
Comment 14 joerg.lechner 2013-06-22 02:11:29 EDT
Created attachment 764046 [details]
F18_64 printer no page eject --> error_log zipped

I zipped now the error_log (original 26MB).
It's the output of the last F18_64 Test.
Printing the following mail:
 
https://bugzilla.redhat.com/show_bug.cgi?id=964588

--- Comment #27 from Tim Waugh <twaugh@redhat.com> ---
'iotop' is for finding processes that use a lot of I/O.  To find processing
using a lot of CPU use 'top'.

-- 
You are receiving this mail because:
You reported the bug.
Comment 15 joerg.lechner 2013-06-22 07:53:02 EDT
Created attachment 764073 [details]
error_ log first printing after installation, F19 TC6 LXDE i686  --- zipped version

zipped error_log. Result of comment 10, which I could not attach yesterday (file too big 34MB)
The mail, that was printed is:

https://bugzilla.redhat.com/show_bug.cgi?id=964588

--- Comment #27 from Tim Waugh <twaugh@redhat.com> ---
'iotop' is for finding processes that use a lot of I/O.  To find processing
using a lot of CPU use 'top'.

-- 
You are receiving this mail because:
You reported the bug.
Comment 16 Tim Waugh 2013-06-24 06:58:58 EDT
There is no print job in the error_log.

Please follow the instructions in comment #9 *exactly as written*.  The four commands in step one should be copied and pasted into the terminal, exactly as they are.
Comment 17 joerg.lechner 2013-06-24 11:13:30 EDT
test performed on F18
[root@localhost cups]# 
[root@localhost cups]# systemctl stop cups.{service,socket,path}
[root@localhost cups]# >/var/log/cups/error_log
[root@localhost cups]# systemctl start cups.{socket,path,service}
[root@localhost cups]# cupsctl --debug-logging
[root@localhost cups]# cupsctl --no-debug-logging
[root@localhost cups]#

two times successful print of mail:

Terje Røsten <terjeros@phys.ntnu.no> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|CLOSED                      |ASSIGNED
                 CC|                            |jpopelka@redhat.com,
                   |                            |twaugh@redhat.com
          Component|mtpaint                     |gutenprint
         Resolution|ERRATA                      |---
           Assignee|terjeros@phys.ntnu.no       |twaugh@redhat.com

--- Comment #23 from Terje Røsten <terjeros@phys.ntnu.no> ---
mtpaint issue resolved, gutenprint issue still present, changing component.

-- 
You are receiving this mail because:
You reported the bug.

tried to print mail:

Von:		bugzilla <bugzilla@redhat.com>
An:		joerg.lechner <joerg.lechner@aol.de>
Betreff:		[Bug 964588] no printing (gutenprint-cups, printer Canon Pixma MP540) with mtpaint FC19 RC2
Datum:		Do, 20 Jun 2013 1:05 pm

https://bugzilla.redhat.com/show_bug.cgi?id=964588

--- Comment #27 from Tim Waugh <twaugh@redhat.com> ---
'iotop' is for finding processes that use a lot of I/O.  To find processing
using a lot of CPU use 'top'.

-- 
You are receiving this mail because:
You reported the bug.

The printer does not print, still waiting. Blocked.

------------> attachement of logfile error_log

I will make a second test with the unsuccessful printed file only.

------------> attachement of the logfile second test
Comment 18 joerg.lechner 2013-06-24 11:19:32 EDT
Created attachment 764675 [details]
F18 test, 3 prints, 2 successful, 3rd unsuccessful

Printed 2 times the same mail successfully, tried to print the mail, which had last time no print success. Totally no printing, printer still says "printing from pc". Printer Queue says file in execution.
Comment 19 Tim Waugh 2013-06-24 12:04:07 EDT
Thanks, that's much better.

So there are two notable things.  Firstly, the actual problem that causes the job to get stuck is this (only messages from the usb backend included):

D [24/Jun/2013:16:52:16 +0200] [Job 40] Device protocol: 2
I [24/Jun/2013:16:52:16 +0200] [Job 40] Sending data to printer.
D [24/Jun/2013:16:52:17 +0200] [Job 40] Read 4096 bytes of print data...
D [24/Jun/2013:16:53:16 +0200] [Job 40] Got USB transaction timeout during read.
D [24/Jun/2013:16:53:17 +0200] [Job 40] Got USB transaction timeout during write.
D [24/Jun/2013:16:54:16 +0200] [Job 40] Got USB transaction timeout during read.
D [24/Jun/2013:16:54:17 +0200] [Job 40] Got USB transaction timeout during write.
D [24/Jun/2013:16:56:16 +0200] [Job 40] Got USB transaction timeout during read.
D [24/Jun/2013:16:56:17 +0200] [Job 40] Got USB transaction timeout during write.

Secondly, even during a normal print run there are lots of messages like this:

D [24/Jun/2013:16:51:32 +0200] [Job 39] Read 211 bytes of back-channel data...

nearly always with the same amount of data.

The USB timeout happened on a read, even when the backend had the data to send to the printer "in hand", so we would expect it to be trying to write. My guess is that it's looking to see if there is back-channel data.

So in both cases, it appears as though the back-channel data is causing an issue.

Probably needs USBLP_QUIRK_BIDIR.

Joerg: please run this command and report the output here:

lsusb
Comment 20 joerg.lechner 2013-06-24 12:26:08 EDT
First I add an additional error_log.

Test procedure:
Printer power off/on
Laptop Fedora 18 restart.

Line commands as You have requested.

First print of the previously failing print (same mail as failed last time) was successful. Second print, mail was printed, no page eject, printer blocked.

And sorry "I am a hobby Fedora tester", this means I have been using Fedora as user since years, but I have very low Linux/Unix knowledge.
Therefore: USBLP_QUIRK_BIDIR seems to no line command, is this a module to be installed (sorry for the silly question)?

----> attachement to the last test.
Comment 21 joerg.lechner 2013-06-24 12:29:35 EDT
Created attachment 764693 [details]
attachement to comment 20, first print successful, second print unsuccessful

Description in comment 20
Comment 22 joerg.lechner 2013-06-24 13:19:09 EDT
Sorry Tim, it took some minutes before I have understood Your comment.
Here the output of lusb:

[root@localhost cups]# lsusb
Bus 001 Device 002: ID 0ac8:c302 Z-Star Microelectronics Corp. Vega USB 2.0 Camera
Bus 002 Device 003: ID 04a9:1730 Canon, Inc. 
Bus 007 Device 002: ID 0a5c:2101 Broadcom Corp. BCM2045 Bluetooth
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
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 006 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 007 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
[root@localhost cups]#
Comment 23 Jiri Popelka 2013-06-25 04:25:34 EDT
(In reply to joerg.lechner from comment #20)
> Therefore: USBLP_QUIRK_BIDIR seems to no line command, is this a module to
> be installed (sorry for the silly question)?

No problem, I think nobody except cups maintainters actually knows that ;-)

Please follow (exactly) steps in bug #873123, comment #0 and let us know if some of them makes any change.
Comment 25 joerg.lechner 2013-06-25 07:21:46 EDT
Hi Jiri,
I ran the following commands, with these commands I have had 4 successful prints of the "critical" mail. Did this as root Is it necessary to try also the other versions?


[root@localhost joerg]# lsusb
Bus 001 Device 002: ID 0ac8:c302 Z-Star Microelectronics Corp. Vega USB 2.0 Camera
Bus 001 Device 003: ID 058f:6366 Alcor Micro Corp. Multi Flash Reader
Bus 002 Device 002: ID 04a9:1730 Canon, Inc. 
Bus 007 Device 002: ID 0a5c:2101 Broadcom Corp. BCM2045 Bluetooth
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
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 006 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 007 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
[root@localhost joerg]# lpstat -p
printer Canon-MP540-series is idle.  enabled since Di 25 Jun 2013 09:37:42 CEST
[root@localhost joerg]# lpadmin -p Canon-MP540-series -o usb-unidir-default=true 
[root@localhost joerg]#
Comment 26 Tim Waugh 2013-06-25 09:17:27 EDT
That's great news.  No, you don't need to try the others.

This fix will be in the next cups update.
Comment 27 Fedora Update System 2013-06-26 11:15:12 EDT
cups-1.6.2-12.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/cups-1.6.2-12.fc19
Comment 28 Fedora Update System 2013-06-26 13:04:33 EDT
Package cups-1.6.2-12.fc19:
* should fix your issue,
* was pushed to the Fedora 19 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-1.6.2-12.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-11691/cups-1.6.2-12.fc19
then log in and leave karma (feedback).
Comment 29 Fedora Update System 2013-07-01 20:34:20 EDT
cups-1.6.2-12.fc19 has been pushed to the Fedora 19 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 30 joerg.lechner 2013-07-14 09:24:02 EDT
There seems to be an error in cups 1.6.2-15.fc19 x86_64, can not print mail from Firefox. There are also no waiting prints displayed in the queue. The printer was automatically installed by F19. Testpage print ok. Seems to be the "old error", no choice of paper feeder.
Comment 31 joerg.lechner 2013-07-16 00:35:15 EDT
cups 1.6.3-1.fc19 x86_64
For me mail printing from Firefox is ok again.

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