Bug 1380955

Summary: Printing of TIFF File Works Only Once
Product: [Fedora] Fedora Reporter: ghborrmann
Component: cupsAssignee: Zdenek Dohnal <zdohnal>
Status: CLOSED EOL QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 24CC: ghborrmann, jpopelka, twaugh, zdohnal
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-08-08 19:17:18 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Attachments:
Description Flags
/var/log/cups/error_log from two successive print attempts none

Description ghborrmann 2016-10-01 22:23:37 UTC
Description of problem:

Entering the command line
    lp CasaPhoneBook_1609.tiff
works as expected, with my HP LaserJet 1200 printer printing properly.  Repeating the command does not work -- nothing is printed.


Version-Release number of selected component (if applicable):
cups x86_64 Version 1:2.1.4-2.fc24


How reproducible: Every time.


Steps to Reproduce:
1.  Boot the System
2.  Execute: lp Documents/CasaPhoneBook_1609.tiff
3.  Repeat the above command

Actual results:
The first command works as expected.  The second command produces nothing.
The second command appears to activate the printer (the status light is flashing as is normal when it is accepting data from the computer), but nothing is printed and the flashing stops after about 5 minutes.

Expected results:
The second command should produce a printed page like the first one.


Additional info:
I have attempted the same thing as above with a different file -
/usr/share/cups/data/default-testpage.pdf.  The second command works perfectly.
I have activated cups debug output, and have compared the journal entries for the two print attempts.  Aside from some difference in the order of some of the entries (they seem trivial to me), the one significant difference I can find occurs near the end of the journal segment, after many Read/Writes of 8192 bytes of print data.  The relevant entries from the first (successful) printing are:

Oct 01 10:19:06 Tann24Xb cupsd[720]: Read 2496 bytes of print data...
Oct 01 10:19:07 Tann24Xb cupsd[720]: Got USB transaction timeout during read.
Oct 01 10:19:07 Tann24Xb cupsd[720]: Report: clients=0
Oct 01 10:19:07 Tann24Xb cupsd[720]: Report: jobs=27
Oct 01 10:19:07 Tann24Xb cupsd[720]: Report: jobs-active=1
Oct 01 10:19:07 Tann24Xb cupsd[720]: Report: printers=2
Oct 01 10:19:07 Tann24Xb cupsd[720]: Report: stringpool-string-count=3908
Oct 01 10:19:07 Tann24Xb cupsd[720]: Report: stringpool-alloc-bytes=9600
Oct 01 10:19:07 Tann24Xb cupsd[720]: Report: stringpool-total-bytes=54280
Oct 01 10:19:07 Tann24Xb cupsd[720]: Wrote 2496 bytes of print data...
Oct 01 10:19:07 Tann24Xb cupsd[720]: Sent 1370560 bytes...
Oct 01 10:19:07 Tann24Xb cupsd[720]: Waiting for read thread to exit...
Oct 01 10:19:14 Tann24Xb cupsd[720]: Read thread still active, aborting the pen
ding read...
Oct 01 10:19:15 Tann24Xb kernel: usblp 1-2.2:1.0: usblp0: USB Bidirectional pri
nter dev 6 if 0 alt 1 proto 2 vid 0x03F0 pid 0x0317
Oct 01 10:19:15 Tann24Xb cupsd[720]: PID 1671 (/usr/lib/cups/backend/usb) exite
d with no errors.
Oct 01 10:19:15 Tann24Xb cupsd[720]: time-at-completed=1475331555

From the second (unsuccessful) printing:

Oct 01 10:32:07 Tann24Xb cupsd[720]: Read 2496 bytes of print data...
Oct 01 10:32:08 Tann24Xb cupsd[720]: Wrote 2496 bytes of print data...
Oct 01 10:32:08 Tann24Xb cupsd[720]: Report: clients=0
Oct 01 10:32:08 Tann24Xb cupsd[720]: Report: jobs=28
Oct 01 10:32:08 Tann24Xb cupsd[720]: Report: jobs-active=1
Oct 01 10:32:08 Tann24Xb cupsd[720]: Report: printers=2
Oct 01 10:32:08 Tann24Xb cupsd[720]: Report: stringpool-string-count=3908
Oct 01 10:32:08 Tann24Xb cupsd[720]: Report: stringpool-alloc-bytes=9600
Oct 01 10:32:08 Tann24Xb cupsd[720]: Report: stringpool-total-bytes=54280
Oct 01 10:32:08 Tann24Xb cupsd[720]: Sent 1370560 bytes...
Oct 01 10:32:08 Tann24Xb cupsd[720]: Waiting for read thread to exit...
Oct 01 10:32:08 Tann24Xb cupsd[720]: Got USB transaction timeout during read.
Oct 01 10:32:08 Tann24Xb kernel: usblp 1-2.2:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 1 proto 2 vid 0x03F0 pid 0x0317
Oct 01 10:32:08 Tann24Xb cupsd[720]: PID 1724 (/usr/lib/cups/backend/usb) exited with no errors.
Oct 01 10:32:08 Tann24Xb cupsd[720]: time-at-completed=1475332328

I note that the successful job waits for 7 seconds before aborting the pending read and continuing. The unsuccessful job does not wait at all, and apparently never aborts that read.  Perhaps the second job's write of 2496 bytes is bad data because of the USB timeout.  In any event, I don't understand why there should be any USB read timeout at all, but timeouts also occurred in the two successful printings of the pdf file (although much earlier in the 8192 byte read/write cycle).  I have examined the journal entries for several other sessions where I attempted printing more than once.  In all cases, the first job was successful, and showed the 7-second delay as above; all subsequent jobs were unsuccessful, and exhibited no delay after the "Waiting for read thread to exit" journal entry.

Comment 1 ghborrmann 2016-10-05 01:17:42 UTC
To investigate further, I have executed the cups filters and backend independently.  Each of the filters (imagetopdf and foomatic-rip) executed successfully and produced the desired output. The backend (usb) also executed successfully and produced the desired output from the printer.  However, the "Waiting for read thread to exit" and "Got USB transaction timeout during read" messages were also seen here, so apparently these messages are normal.  Repeated execution of the backend worked identically; all produced printer output.

I have verified that the printer behavior for the non-working cases (status light flashing for 5 minutes) is the same behavior as when data transmission is stopped before completion.  Thus, the problem appears to be somewhere in the chain of data transmission from filter to filter to backend.

Comment 2 Zdenek Dohnal 2016-12-16 16:01:47 UTC
Hi, 

thank you for contacting us, would you mind attaching some example tiff file?

Comment 3 Zdenek Dohnal 2016-12-16 16:12:15 UTC
I managed to find some .tiff file, so I printed with CUPS. It works good, problem seems to be in your printer. Looking into it.

Comment 4 ghborrmann 2016-12-17 02:56:07 UTC
I don't think there is anything special about my TIFF file, but I will supply it if you still think it would be helpful.  This bug has also shown up when printing a short text file, although it doesn't seem to occur every time.  As I indicated in my report of this bug, the difference appears to be connected with the message "Waiting for read thread to exit...".  The successful job waits for 7 seconds before aborting the pending read; the unsuccessful one immediately reports a USB transaction timeout.  I have used this printer (LaserJet 1200) on Fedora 23 and Windows without problems.

Comment 5 Zdenek Dohnal 2016-12-19 09:53:53 UTC
I think you encountered bug #873123 , would you mind trying steps from that bugzilla, if it helps you?

Comment 6 ghborrmann 2016-12-20 04:20:38 UTC
I tried the combinations of lpadmin commands as per bug #8723123, with no effect.

Earlier today, I successfully printed about a dozen different TIFF files, so I thought this bug had been eliminated by updates since my first bug report.  However, I thought I would confirm this by trying the file that originally exhibited the problem (CasaPhoneBook_1609.tiff).  Just like back in October, that file printed the first time, but not the second.  After that failure, every additional attempt to print it was unsuccessful.  At this point, I checked out the lpadmin commands mentioned above with no effect.  I then tried printing one of today's files (EJ0013.tiff) - it worked.  It even worked twice in a row, but a subsequent attempt to print the original file (CasaPhoneBook_1609.tiff) failed.
I went back to the files I was working with in October and tried to print another one (CasaPhoneBook_1610.tiff).  That, too, printed successfully one time but not the second.  I found an even earlier file scanned in September (NYTimes_Forum_160911.tiff).  That file had no problems printing twice in a row.

Thus, my earlier comment -- that I didn't think there was anything special about my TIFF file -- appears to be wrong.  There is obviously something about those October files which is not present in my files of today.  I am somewhat reluctant to attach my tiff file, since it contains some personal information.  Is there some way to purge the tiff file of its picture, while keeping all of its structure intact?

The common feature of all of the failed print attempts is the presence in the journal of the "Got USB transaction timeout during read" message, which I believe is generated by libusb trying to read back-channel data from the printer.

Comment 7 Zdenek Dohnal 2016-12-20 10:46:34 UTC
I understand you, if that file contains some personal information, you do not have to attach it. What is the size of that file? It is similar to files which can be printed or much bigger/smaller?
Did you use debug2 level in cupsd.conf? If you have not done it yet, you can do it, perhaps we  will get more info (and you can set in cups-files.conf ErrorLog to /var/log/cups/error_log, so you will have all info in that and you will not have to filtrate from journal, and add it as attachment).
And about tiff file editor, maybe gimp?

Comment 8 ghborrmann 2016-12-22 02:48:10 UTC
The unsuccessful 1609 file has a size of 625120 bytes; the likewise unsuccessful 1610 file has 1102714 bytes.  The successful file EJ0013 has 1140872 bytes.

I had not used debug2 level; only debug.  I am attaching the error_log obtained after I set the level to debug2.  Following the changes to cupsd.conf and cups-files.conf, I rebooted and then issued 'lp CasaPhoneBook_1609.tiff' twice.  The second command was issued only after successful printing from the first one.  As usual, the second command produced no printed output; the printer status light remained blinking until it timed out after five minutes.

Comment 9 ghborrmann 2016-12-22 02:53:14 UTC
Created attachment 1234597 [details]
/var/log/cups/error_log from two successive print attempts

Oops - I forgot to add the attachment.  See my previous comment.

Comment 10 Fedora End Of Life 2017-07-25 23:18:52 UTC
This message is a reminder that Fedora 24 is nearing its end of life.
Approximately 2 (two) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 24. 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 EOL if it remains open with a Fedora  'version'
of '24'.

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.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 24 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, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

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.

Comment 11 Fedora End Of Life 2017-08-08 19:17:18 UTC
Fedora 24 changed to end-of-life (EOL) status on 2017-08-08. Fedora 24 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. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

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