Bug 1935318 - old samsung USB devices malfunction with the current (250ms) timeout for usb bulk transaction
Summary: old samsung USB devices malfunction with the current (250ms) timeout for usb ...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups
Version: 33
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Zdenek Dohnal
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1942326 1943939 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-03-04 16:06 UTC by Marco
Modified: 2021-04-24 20:11 UTC (History)
5 users (show)

Fixed In Version: cups-2.3.3op2-4.fc33 cups-2.3.3op2-4.fc32 cups-2.3.3op2-4.fc34
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-04-16 14:35:10 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
jobs log (15.85 KB, text/plain)
2021-03-09 11:29 UTC, Marco
no flags Details
error printed (440.30 KB, application/pdf)
2021-03-09 11:30 UTC, Marco
no flags Details
cups_job_log (17.63 KB, text/plain)
2021-03-09 12:44 UTC, Marco
no flags Details
usb.pcap (517.74 KB, application/vnd.tcpdump.pcap)
2021-03-12 10:01 UTC, Marco
no flags Details
cups_job_log (17.56 KB, text/plain)
2021-03-15 10:46 UTC, Marco
no flags Details
usb.pcap (360.98 KB, application/vnd.tcpdump.pcap)
2021-03-15 10:47 UTC, Marco
no flags Details
journal_whole_log (171.69 KB, text/plain)
2021-03-15 10:48 UTC, Marco
no flags Details
cups_whole_log (38.76 KB, text/plain)
2021-03-15 10:49 UTC, Marco
no flags Details
ppd from samsung driver (12.10 KB, text/plain)
2021-03-16 17:12 UTC, Marco
no flags Details

Description Marco 2021-03-04 16:06:12 UTC
Description of problem:

after upgrade to version 2.3.3op2 my samsung ML-1665 printer only print error:
INTERNAL ERROR - Including Corrupted Data


Version-Release number of selected component (if applicable):
2.3.3op2

How reproducible:
Print any files

Steps to Reproduce:
1. open file 
2. print it
3.

Actual results:
Only solution found is downgrade to cups-2.3.3-13
sudo dnf downgrade cups

Expected results:


Additional info:

Comment 1 Zdenek Dohnal 2021-03-05 05:17:19 UTC
Hi Marco,

thank you for reporting the issue!

Would you mind following the steps here [1] and attaching all requested files to this ticket as an attachments?

Thank you in advance!

[1] https://fedoraproject.org/wiki/How_to_debug_printing_problems#My_printer_doesn.27t_print_correctly_or_at_all.2C_but_I_can_see_the_printer_in_print_dialog

Comment 2 Marco 2021-03-09 11:29:22 UTC
Created attachment 1761972 [details]
jobs log

Comment 3 Marco 2021-03-09 11:30:34 UTC
Created attachment 1761973 [details]
error printed

Comment 4 Zdenek Dohnal 2021-03-09 11:45:01 UTC
Hi Marco,

unfortunately the job log is cropped and you didn't provide all information from the manual.

Would you mind getting the job log once more (the clean way is redirecting to a file) and providing other information?

Thank you in advance!

Comment 5 Marco 2021-03-09 12:44:59 UTC
Created attachment 1761993 [details]
cups_job_log

Hoping this can help. Thx

Comment 6 Zdenek Dohnal 2021-03-09 13:00:22 UTC
Still missing the other data from [1]. Would you mind providing them?

Ad job log - I don't see any errors/warnings during filtering process, but there is a timeout during usb communication. Would you mind capturing USB communication via wireshark too? Here is the manual https://wiki.wireshark.org/CaptureSetup/USB 


[1]  https://fedoraproject.org/wiki/How_to_debug_printing_problems#My_printer_doesn.27t_print_correctly_or_at_all.2C_but_I_can_see_the_printer_in_print_dialog

Comment 7 Marco 2021-03-09 13:43:19 UTC
I'm following your link, but wireshark doesn't show USB devices,but are there in dumpcap. Same result setting facl (sudo setfacl -m u:$USER:r /dev/usbmon*) and switching off selinux.

$sudo dumpcap -D
1. wlp2s0
2. any
3. lo (Loopback)
4. enp1s0
5. virbr0
6. bluetooth0
7. bluetooth-monitor
8. usbmon2
9. usbmon1
10. usbmon0
11. nflog
12. nfqueue
13. virbr0-nic

Comment 8 Zdenek Dohnal 2021-03-10 13:29:01 UTC
Marco,

there is no specific USB devices - USB capture is done by connecting to usbmonN via wireshark/tcpdump (N is a number of USB bus where the device is connected).

So first you find out the bus number:

$ lsusb
Bus 002 Device 010: ID 03f0:012a HP, Inc HP LaserJet M1536dnf MFP
      =

then use it in tcpdump (my bus number is 2):

$ sudo tcpdump -i usbmon2 -s0 -w usb.pcap


========================================================================================

The ticket is still missing data mentioned in https://bugzilla.redhat.com/show_bug.cgi?id=1935318#c1 , please provide them too.

Comment 9 Marco 2021-03-12 10:01:52 UTC
Created attachment 1762924 [details]
usb.pcap

Bus 001 Device 003: ID 04e8:3301 Samsung Electronics Co., Ltd ML-1660 Series
sudo tcpdump -i usbmon1 -s0 -w usb.pcap
attached usb.pcap

Comment 11 Marco 2021-03-15 10:46:37 UTC
Created attachment 1763358 [details]
cups_job_log

Comment 12 Marco 2021-03-15 10:47:55 UTC
Created attachment 1763359 [details]
usb.pcap

Comment 13 Marco 2021-03-15 10:48:56 UTC
Created attachment 1763360 [details]
journal_whole_log

Comment 14 Marco 2021-03-15 10:49:36 UTC
Created attachment 1763361 [details]
cups_whole_log

Comment 15 Zdenek Dohnal 2021-03-15 11:09:40 UTC
The link I sent you contains the steps:

- attach the created files to the ticket and turn off debugging
You did this by attaching job log and usb capture.

- attach your printer PPD file from /etc/cups/ppd/ if available
Still waiting for this... and please mention what driver and from where you install your printer driver. The filter which you use during printing isn't in Fedora.

- attach the file you wanted to print
Still waiting for this... does the issue happen for all documents? If so, the file is not necessary.

- tell what application you printed from
Still waiting for this info... does the issue happen regardless if you print from firefox or evince? If it is an application specific, please let me know.

- mention your printer model
Provided in the initial comment.

Would you mind providing missing information?

Is it not clear from the link? I'm enhancing the wiki based on feedback, so I would like to know what made you upload the info non-related to the use case I sent you, but didn't upload the mentioned data.

Thank you in advance!

Comment 16 Marco 2021-03-16 16:51:31 UTC
At the beginning I use splix, a fedora package. After last cups update I removed splix and installed Samsung Unified Linux Driver (1.0.36-1.0.39) but same result. I will attack the ppd

I used libreoffice to print but the problem is with other software too (evince).
The issue happen for all documents.
The issue happen after last cups update
Rolling back cups to previous version the issue disappear.

The wiki is clear, but this is my second bug here ;)

Thx in advance!

Comment 17 Marco 2021-03-16 17:12:11 UTC
Created attachment 1763728 [details]
ppd from samsung driver

Comment 18 Zdenek Dohnal 2021-03-23 07:57:23 UTC
Thanks for the data, now I'm trying to narrow the frame where the issue was introduced.

(In reply to Marco from comment #0)
> Only solution found is downgrade to cups-2.3.3-13

That's quite old cups version - from August last year... Did you have a problem with cups-2.3.3op1-1.fc33 too or you just didn't try it?

If the mentioned cups version isn't in repos already, you can install rpms from this link https://koji.fedoraproject.org/koji/buildinfo?buildID=1658219 .

Comment 19 Marco 2021-03-23 09:01:32 UTC
Hi Zdenek,
the problem was introduced upgrading from cups-2.3.3op1-1.fc33 to 2.3.3op2-1.fc33.
With cups-2.3.3op1-1.fc33 it works fine.
Thx for help!

Comment 20 Zdenek Dohnal 2021-03-23 10:52:34 UTC
Thanks for confirming!

Here is the code for usb backend (2.3.3op2):

1703     rbytes     = sizeof(readbuffer);
1704     readstatus = libusb_bulk_transfer(g.printer->handle,
1705               g.printer->read_endp,
1706               readbuffer, rbytes,
1707               &rbytes, 250);
1708     if (readstatus == LIBUSB_SUCCESS && rbytes > 0)
1709     {
1710       fprintf(stderr, "DEBUG: Read %d bytes of back-channel data...\n", (int)rbytes);
1711       cupsBackChannelWrite((const char *)readbuffer, (size_t)rbytes, 1.0);
1712     }
1713     else if (readstatus == LIBUSB_ERROR_TIMEOUT)
1714       fputs("DEBUG: Got USB transaction timeout during read.\n", stderr);

So that's the part of code which message from logs:

mar 09 12:16:53 mepmob cupsd[92848]: ATTR: job-media-progress=62
mar 09 12:16:53 mepmob cupsd[92848]: Got USB transaction timeout during read.
=============================================================================
mar 09 12:16:53 mepmob cupsd[92848]: ATTR: job-media-progress=64

comes from.

The change in 2.3.3op2 happened at line 1707 - '250' is a timeout limit for reading operation, it was '60000' in 2.3.3op1. So your device is probably too slow for this timeout and results in a garbled job. I will try to set longer timeout.

I tried to set longer timeout at https://koji.fedoraproject.org/koji/taskinfo?taskID=64412423 , would you mind trying those rpms if it helps?

Comment 21 Marco 2021-03-23 13:22:55 UTC
Hi Zdenek,
downloaded all rpm files from koji and installed with
# dnf localinstall cups* --allowerasing
systemctl restart
and........ it works!!!

Comment 22 Zdenek Dohnal 2021-03-23 13:38:13 UTC
Ok, thanks for the info!

I would like to try shorter timeout - would you mind trying https://koji.fedoraproject.org/koji/taskinfo?taskID=64422836 (timeout 1000ms) ?

Comment 23 Zdenek Dohnal 2021-03-24 09:31:40 UTC
*** Bug 1942326 has been marked as a duplicate of this bug. ***

Comment 24 Zdenek Dohnal 2021-03-24 09:35:36 UTC
Ok, Miklos from the other bug tested rpms with 1s timeout and it didn't work for his samsung device, so I'll clear the needinfo and we will stick with 2s.

Comment 25 Zdenek Dohnal 2021-03-24 12:18:39 UTC
Created PR upstream https://github.com/OpenPrinting/cups/pull/160

Comment 26 Miklos Szeredi 2021-03-24 14:00:25 UTC
Still flaky.  Please restore the original timeout, if it wasn't reduced because of a bug report, otherwise we'll have this issue forever.

Thanks,
Miklos

Comment 27 Zdenek Dohnal 2021-03-25 06:43:52 UTC
Have you got the issue even with 2s timeout?

IMO it will depend on how big print job is... so even the original 60s! timeout can fail if USB implementation in printer is poor.

So I'm trying to balance between supporting devices from 2008 and don't putting too much burden on the current devices by timeouts being too high.

Comment 28 Miklos Szeredi 2021-03-25 08:07:32 UTC
(In reply to Zdenek Dohnal from comment #27)
> Have you got the issue even with 2s timeout?

Yes, intermittently.

> 
> IMO it will depend on how big print job is... so even the original 60s!
> timeout can fail if USB implementation in printer is poor.

Never had any issue with this printer.

The hardware is reliable and is cheap to operate.  Unlike some new stuff.  Would be crazy having to make it a pile of rubbish because of a software issue.

> 
> So I'm trying to balance between supporting devices from 2008 and don't
> putting too much burden on the current devices by timeouts being too high.

Can you blacklist old devices then?

Thanks,
Miklos

Comment 29 Zdenek Dohnal 2021-03-25 09:02:04 UTC
(In reply to Miklos Szeredi from comment #28)
> (In reply to Zdenek Dohnal from comment #27)
> > Have you got the issue even with 2s timeout?
> 
> Yes, intermittently.

Ok, raising the timeout to 10s. Would you mind testing it?

https://koji.fedoraproject.org/koji/taskinfo?taskID=64556662

> 
> > 
> > IMO it will depend on how big print job is... so even the original 60s!
> > timeout can fail if USB implementation in printer is poor.
> 
> Never had any issue with this printer.
> 
> The hardware is reliable and is cheap to operate.  Unlike some new stuff. 
> Would be crazy having to make it a pile of rubbish because of a software
> issue.

You may never experienced an issue because CUPS tries to workaround most hardware issues in its code, but sometimes these workarounds can cause other bugs...

> 
> > 
> > So I'm trying to balance between supporting devices from 2008 and don't
> > putting too much burden on the current devices by timeouts being too high.
> 
> Can you blacklist old devices then?

It can be done by adding its idVendor and idProduct into /usr/share/cups/usb/org.cups.usb-quirks , but still I would prefer a balance of some kind.

> 
> Thanks,
> Miklos

Comment 30 Miklos Szeredi 2021-03-25 12:27:07 UTC
Thanks.  So far the 10s version works fine.  I haven't tried big batches only single pages yet.

My guess is that the delays are probably related to warm up time (since that takes a couple of seconds) but I'm not an expert in this area.

Comment 31 Zdenek Dohnal 2021-03-25 12:59:11 UTC
(In reply to Miklos Szeredi from comment #30)
> Thanks.  So far the 10s version works fine.  I haven't tried big batches
> only single pages yet.

Ok, please try your usual printing workflow and let me know. I will be on vacation since Saturday, so if you manage to test tomorrow early in the morning, it would be the best - so I can pass it upstream at least.

> 
> My guess is that the delays are probably related to warm up time (since that
> takes a couple of seconds) but I'm not an expert in this area.

It can be - the timeout is set on bulk transfer for specific endpoint where goes data from printer, so if the device takes too long with response, it will be noted there.

Would you mind trying 5s timeout too? https://koji.fedoraproject.org/koji/taskinfo?taskID=64572218

Comment 32 Zdenek Dohnal 2021-03-26 07:20:58 UTC
(In reply to Zdenek Dohnal from comment #31)
> > 
> > My guess is that the delays are probably related to warm up time (since that
> > takes a couple of seconds) but I'm not an expert in this area.
> 
> It can be - the timeout is set on bulk transfer for specific endpoint where
> goes data from printer, so if the device takes too long with response, it
> will be noted there.

I checked the code again and compared with job log Marco provided and IMO it is not connected to warm up period - printer is already accepting print data via other endpoint - if the printer is not ready those reads/writes should fail too, because IMO if the printer is not ready for communication, it shouldn't be ready on all endpoints, not just on a specific one for back-channel.

Comment 33 Zdenek Dohnal 2021-04-07 05:41:41 UTC
*** Bug 1943939 has been marked as a duplicate of this bug. ***

Comment 34 Zdenek Dohnal 2021-04-09 04:26:01 UTC
Hi all,

any progress on testing those rpms? I cannot fix this permanently until I have verification from you, because I don't have this printer type.

Comment 35 Zdenek Dohnal 2021-04-09 04:57:15 UTC
I put all links for testing rpms I would like to ask you to try:

1) rpms with 5s timeout on bulk transfer and 5s sleep
https://koji.fedoraproject.org/koji/taskinfo?taskID=65549196


2) rpms with 10s timeout on bulk transfer and 10s sleep
https://koji.fedoraproject.org/koji/taskinfo?taskID=65549348


3) rpms with 60s timeout bulk transfer and 250ms sleep
https://koji.fedoraproject.org/koji/taskinfo?taskID=65549989


Please try all those rpms and provide a feedback for each of them.


Thank you in advance!

Comment 36 Miklos Szeredi 2021-04-12 11:09:34 UTC
Till now I used the 10s version from comment 29 without a hitch.

Now upgraded to the 5s version from comment 35, will report on the result.

Comment 37 Miklos Szeredi 2021-04-13 08:26:11 UTC
The 5s version printed okay, but started flashing the green led after the job was done, which is unusual.

Comment 38 Fedora Update System 2021-04-14 11:19:04 UTC
FEDORA-2021-259ced3016 has been submitted as an update to Fedora 34. https://bodhi.fedoraproject.org/updates/FEDORA-2021-259ced3016

Comment 39 Fedora Update System 2021-04-14 11:33:30 UTC
FEDORA-2021-b84cd7da6f has been submitted as an update to Fedora 33. https://bodhi.fedoraproject.org/updates/FEDORA-2021-b84cd7da6f

Comment 40 Fedora Update System 2021-04-14 11:50:09 UTC
FEDORA-2021-ce94b88d4e has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2021-ce94b88d4e

Comment 41 Fedora Update System 2021-04-14 15:14:38 UTC
FEDORA-2021-b84cd7da6f has been pushed to the Fedora 33 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-b84cd7da6f`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-b84cd7da6f

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 42 Fedora Update System 2021-04-14 15:35:18 UTC
FEDORA-2021-ce94b88d4e has been pushed to the Fedora 32 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-ce94b88d4e`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-ce94b88d4e

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 43 Fedora Update System 2021-04-14 17:14:23 UTC
FEDORA-2021-259ced3016 has been pushed to the Fedora 34 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-259ced3016`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-259ced3016

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 44 Fedora Update System 2021-04-16 14:35:10 UTC
FEDORA-2021-b84cd7da6f has been pushed to the Fedora 33 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 45 Fedora Update System 2021-04-21 21:48:52 UTC
FEDORA-2021-ce94b88d4e has been pushed to the Fedora 32 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 46 Fedora Update System 2021-04-24 20:11:46 UTC
FEDORA-2021-259ced3016 has been pushed to the Fedora 34 stable repository.
If problem still persists, please make note of it in this bug report.


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