New issue
Advanced search Search tips
Note: Color blocks (like █ or █) mean that a user may not be available. Tooltip shows the reason.

Issue 804702 link

Starred by 4 users
Status: Fixed
Owner:
█ bhthompson@chromium.org
Last visit > 30 days ago
Closed: Apr 2018
Cc:
weifangsun@chromium.org
jayhlee@google.com
skau@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Chrome printing bug: Native Printing Get Stuck When Printing Several Pages At The Same Time

Project Member Reported by ryutas@chromium.org, Jan 23 2018 
Chrome version: 
OS version:64.0.3282.101 (from 62 to 64 Beta )
Case#: 14678939
Dell Chromebook 11 

Printer: Color HP3600 

Description:Native Printing Get Stuck When Printing Several Pages At The Same Time.


-Steps to reproduce: 
If customer sends out a print job of one page, everything works as expected 
If customer sends a file with several pages (the one in this logs is of 28 pages), the job gets stuck and does not print.
(error message: Error printing 28 pages to A1 Color HP3600)
https://drive.google.com/open?id=1d6ch-XtXm3cS9k2CH1lsIztx1qACoUCx

-Current Behavior / Reproduction: 
Jobs are getting stuck, customer believes that is due to the size of the file that they are trying to print. 

-Expected Behavior: 
For all the pages to print.

- Troubleshooting steps taken: 
Tried with different devices and different users. Same behavior.
Since December when we implemented native printing over LPD/IPP

- Is this reproducible in Beta/Dev? 
Yes, from version 62 to Beta 


User info:https://drive.google.com/open?id=1ykjrZ2P1GkH51Iwdz3YAzZrHch6sHWy5SJ2JY4xwPKM

Drive link to logs: https://drive.google.com/open?id=1d6ch-XtXm3cS9k2CH1lsIztx1qACoUCx
(3:30 PST time stamp)

2018-01-11T15:25:05.761740-08:00 INFO cupsd[25621]: REQUEST localhost - - "POST /printers/1975bbe1-1cde-4579-b0db-2230654820a8 HTTP/1.1" 200 291 Create-Job successful-ok
2018-01-11T15:25:06.274519-08:00 INFO cupsd[25621]: REQUEST localhost - - "POST /printers/1975bbe1-1cde-4579-b0db-2230654820a8 HTTP/1.1" 200 709097 Send-Document successful-ok
2018-01-11T15:25:06.275616-08:00 NOTICE cupsd[25621]: [Job 2] 2 filters for job:
2018-01-11T15:25:06.275636-08:00 NOTICE cupsd[25621]: [Job 2] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
2018-01-11T15:25:06.275646-08:00 NOTICE cupsd[25621]: [Job 2] foomatic-rip (application/vnd.cups-pdf to printer/1975bbe1-1cde-4579-b0db-2230654820a8, cost 0)
2018-01-11T15:25:06.276250-08:00 NOTICE cupsd[25621]: [Job 2] Started filter /usr/libexec/cups/filter/pdftopdf (print-color-mode=monochrome sides=one-sided media=na_letter_8.5x11in job-uuid=urn:uuid:4c72ba2e-5023-38a8-48c9-042e4bcf8413 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1515713105 time-at-processing=1515713106 document-name-supplied=Middle\\ School\\ By\\ DCI Duplex=None PageSize=Letter) (PID 2)
2018-01-11T15:25:06.276614-08:00 NOTICE cupsd[25621]: [Job 2] Started filter /usr/libexec/cups/filter/foomatic-rip (print-color-mode=monochrome sides=one-sided media=na_letter_8.5x11in job-uuid=urn:uuid:4c72ba2e-5023-38a8-48c9-042e4bcf8413 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1515713105 time-at-processing=1515713106 document-name-supplied=Middle\\ School\\ By\\ DCI Duplex=None PageSize=Letter) (PID 3)
2018-01-11T15:25:06.276961-08:00 NOTICE cupsd[25621]: [Job 2] Started backend /usr/libexec/cups/backend/ipp (PID 4)
2018-01-11T15:25:06.277187-08:00 INFO cupsd[25621]: REQUEST localhost - - "POST /printers/1975bbe1-1cde-4579-b0db-2230654820a8 HTTP/1.1" 200 199 Close-Job successful-ok
2018-01-11T15:25:06.340564-08:00 NOTICE cupsd[25621]: [Job 2] PID 2 (/usr/libexec/cups/filter/pdftopdf) exited with no errors.
2018-01-11T15:25:12.196792-08:00 NOTICE cupsd[25621]: [Job 2] PID 3 (/usr/libexec/cups/filter/foomatic-rip) exited with no errors.
2018-01-11T15:25:32.826136-08:00 NOTICE cupsd[25621]: [Job 2] PID 4 (/usr/libexec/cups/backend/ipp) exited with no errors.
2018-01-11T15:26:23.747172-08:00 INFO kernel: [14406.218701] tpm_tis tpm_tis: command 0x65 (size 20) returned code 0x0
2018-01-11T15:26:23.777229-08:00 INFO kernel: [14406.248682] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-01-11T15:26:23.807121-08:00 INFO kernel: [14406.278862] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0
2018-01-11T15:29:10.878793-08:00 INFO periodic_scheduler[25889]: cros-machine-id-regen: running /usr/sbin/cros-machine-id-regen -r periodic -t 21600
2018-01-11T15:29:10.898450-08:00 NOTICE cros-machine-id-regen[25903]: Not regenerating since we did so 1612 seconds ago.
2018-01-11T15:29:10.899748-08:00 INFO periodic_scheduler[25904]: cros-machine-id-regen: job completed
2018-01-11T15:29:11.088142-08:00 INFO periodic_scheduler[25911]: crash_sender: running /sbin/crash_sender
2018-01-11T15:29:11.159745-08:00 INFO periodic_scheduler[25932]: crash_sender: job completed
2018-01-11T15:30:41.502633-08:00 INFO cupsd[25621]: REQUEST localhost - - "POST /printers/8cf9957c-1c5a-4a94-bb33-85b6a56602d2 HTTP/1.1" 200 286 Create-Job successful-ok
2018-01-11T15:30:49.023865-08:00 INFO cupsd[25621]: REQUEST localhost - - "POST /printers/8cf9957c-1c5a-4a94-bb33-85b6a56602d2 HTTP/1.1" 200 3601775 Send-Document successful-ok
2018-01-11T15:30:49.024764-08:00 NOTICE cupsd[25621]: [Job 3] 3 filters for job:
2018-01-11T15:30:49.024776-08:00 NOTICE cupsd[25621]: [Job 3] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
2018-01-11T15:30:49.024782-08:00 NOTICE cupsd[25621]: [Job 3] gstoraster (application/vnd.cups-pdf to application/vnd.cups-raster, cost 99)
2018-01-11T15:30:49.024788-08:00 NOTICE cupsd[25621]: [Job 3] hpcups (application/vnd.cups-raster to printer/8cf9957c-1c5a-4a94-bb33-85b6a56602d2, cost 0)
2018-01-11T15:30:49.025918-08:00 NOTICE cupsd[25621]: [Job 3] Started filter /usr/libexec/cups/filter/pdftopdf (print-color-mode=color sides=one-sided media=na_letter_8.5x11in job-uuid=urn:uuid:240196dc-e427-3c7c-5d20-bd3b3d80cf99 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1515713441 time-at-processing=1515713449 document-name-supplied=Middle\\ School\\ By\\ DCI Duplex=None PageSize=Letter) (PID 14)
2018-01-11T15:30:49.028061-08:00 NOTICE cupsd[25621]: [Job 3] Started filter /usr/libexec/cups/filter/gstoraster (print-color-mode=color sides=one-sided media=na_letter_8.5x11in job-uuid=urn:uuid:240196dc-e427-3c7c-5d20-bd3b3d80cf99 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1515713441 time-at-processing=1515713449 document-name-supplied=Middle\\ School\\ By\\ DCI Duplex=None PageSize=Letter) (PID 15)
2018-01-11T15:30:49.030287-08:00 NOTICE cupsd[25621]: [Job 3] Started filter /usr/libexec/cups/filter/hpcups (print-color-mode=color sides=one-sided media=na_letter_8.5x11in job-uuid=urn:uuid:240196dc-e427-3c7c-5d20-bd3b3d80cf99 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1515713441 time-at-processing=1515713449 document-name-supplied=Middle\\ School\\ By\\ DCI Duplex=None PageSize=Letter) (PID 16)
2018-01-11T15:30:49.030599-08:00 NOTICE cupsd[25621]: [Job 3] Started backend /usr/libexec/cups/backend/lpd (PID 17)
2018-01-11T15:30:49.030787-08:00 INFO cupsd[25621]: REQUEST localhost - - "POST /printers/8cf9957c-1c5a-4a94-bb33-85b6a56602d2 HTTP/1.1" 200 199 Close-Job successful-ok
2018-01-11T15:30:49.328177-08:00 NOTICE cupsd[25621]: [Job 3] PID 14 (/usr/libexec/cups/filter/pdftopdf) exited with no errors.
2018-01-11T15:31:09.180384-08:00 ERR hpcups[26044]: common/utils.c 220: Invalid Library hanlder pLibHandler = NULL.
2018-01-11T15:31:09.181158-08:00 INFO cupsd[25621]: REQUEST localhost - - "POST /jobs/ HTTP/1.1" 200 203 Cancel-Job successful-ok
2018-01-11T15:31:09.188206-08:00 NOTICE cupsd[25621]: [Job 3] PID 16 (/usr/libexec/cups/filter/hpcups) exited with no errors.
2018-01-11T15:31:10.199287-08:00 NOTICE cupsd[25621]: [Job 3] PID 17 (/usr/libexec/cups/backend/lpd) stopped with status 1.
2018-01-11T15:31:14.174814-08:00 NOTICE cupsd[25621]: [Job 3] Backend returned status 1 (failed)

sample affected file:https://drive.google.com/open?id=1n_ymDKlsFN3cvGzdyb0_d1n3U2L4XyuF

Comment 1 by ryutas@chromium.org, Jan 23 2018 

bhthompson@
Please triage this case.

Comment 2 by skau@chromium.org, Jan 23 2018

Cc: skau@chromium.org

Comment 3 by skau@chromium.org, Jan 23 2018

Labels: -Pri-3 Pri-2
We'll need to investigate this.  I ran the job through the printing pipeline and it's trying to send 81M to the printer.  Depending on how munch memory the printer has, this would explain the reported behavior.  However, the hpcups filter seems to be the culprit as the CUPS Raster output for the given file is only 26M.

Comment 4 by skau@chromium.org, Jan 23 2018

Cc: weifangsun@chromium.org

Comment 5 by christianelias@google.com, Jan 24 2018 

Hello team,

The customer that reported the original issue has found a strange behavior and he wants to know if it's related:

"Occasionally, a user is unable to select a printer. When clicking on the
printer, they receive the message, "Error setting up printer..."

When this occurs, it is ALL printers on the machine, not any particular
printer. We have found that rebooting will immediately clear this condition
and printing then works for a period of time, hours or days. I have
attached another debug log. The errors were reported at 08:55. The device
is an HP Chromebook 14. It seems that it may be model specific as I cannot
recreate the issue on my Lenovo N23 Chromebook."

I have attached the Debug Logs. I appreciate the assistance
debug-logs_20180124-085537
1.2 MB View Download

Comment 6 by skau@chromium.org, Jan 24 2018 

That issue seems to be unrelated.  However, it appears that cupsd never started.

init: cups-post-upstart-socket-bridge main process (1375) terminated with status 1

What build is the log from?

Comment 7 by tbar...@spreckelsdistrict.org, Jan 24 2018 

Chrome version 63.0.3239.140. Screenshot attached.
version.png
29.5 KB View Download

Comment 8 by skau@chromium.org, Jan 24 2018 

The bug described in #5 should be resolved in 10176.18.0 (M64).  The bug was http://crbug.com/783208 (Crash report so view is restricted).

Comment 9 by kkaluri@chromium.org, Feb 6 2018

Labels: OS-Chrome

Comment 10 by ryutas@chromium.org, Feb 20 2018 

Is there any update that can be shared?

Comment 11 by weifangsun@chromium.org, Feb 20 2018 

Per Comment #8, I believe this should be fixed in the M64 build which is currently rolling out to Stable. Please advise if this issue has been reproducible on M64 for further investigation.

Comment 12 by weifangsun@chromium.org, Apr 25 2018

Status: Fixed (was: Untriaged)
Closing this issue as fixed. Please reopen if the issue is still occurring.
►

Sign in to add a comment