Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HP LaserJet Pro P1102 always stuck "sending data to printer" #58

Closed
pezcurrel opened this issue Sep 2, 2018 · 50 comments
Closed

HP LaserJet Pro P1102 always stuck "sending data to printer" #58

pezcurrel opened this issue Sep 2, 2018 · 50 comments

Comments

@pezcurrel
Copy link

pezcurrel commented Sep 2, 2018

Hi,
I'm running an up-to-date Arch Linux box with...

kernel 4.18.5
cups 2.2.8
libcups 2.2.8
cups-filters 1.21.1
ghostscript 9.23
poppler 0.67.0

...and latest foo2zjs (2018-05-19) from http://foo2zjs.rkkda.com (not the AUR - but I get the same problem with foo2zjs-nightly from the AUR).
The printer no longer works since about second half of august (2018); I tried downgrading all the above packages (but the kernel) to versions which got installed before, but to no avail.

When I send a job, this is what cups is stuck doing ("ps -AF --forest")...

root       442     1  0 38059 10544   3 05:27 ?        00:00:00 /usr/bin/cupsd -l
cups      1487   442  0 22029 15884   3 05:38 ?        00:00:00  \_ HP_LaserJet_Professional_P1102_su_Gargantua 552 anonymous Test Page 1 job-uuid=urn:uuid:ac02187b-453e-392d-5c5a-054616f19a67 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1535859507 time-at-processing=1535859507
cups      1493  1487  0 14975  6212   0 05:38 ?        00:00:00  |   \_ pdftops 552 anonymous Test Page 1  job-uuid=urn:uuid:ac02187b-453e-392d-5c5a-054616f19a67 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1535859507 time-at-processing=1535859507 /var/spool/cups/tmp/foomatic-kqwNwc
cups      1494  1493  0 51206 27368   0 05:38 ?        00:00:00  |       \_ gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -dShowAcroForm -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r300 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c save pop -f /var/spool/cups/tmp/foomatic-kqwNwc
cups      1495  1493  0 15197  6308   0 05:38 ?        00:00:00  |       \_ pdftops 552 anonymous Test Page 1  job-uuid=urn:uuid:ac02187b-453e-392d-5c5a-054616f19a67 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1535859507 time-at-processing=1535859507
cups      1488   442  0 38166  6372   3 05:38 ?        00:00:00  \_ usb://HP/LaserJet%20Professional%20P1102?serial=000000000Q87FWBPPR1a 552 anonymous Test Page 1 job-uuid=urn:uuid:ac02187b-453e-392d-5c5a-054616f19a67 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1535859507 time-at-processing=1535859507

...until I cancel the job (I waited as long as half an hour, at most). While the job is still active cups web interface says "processing - sending data to the printer" for the job; nothing gets printed, but the green led on the printer blinks as it does when printing (so it seems it's receiving something).

As long as the job is running I have a temp file in "/var/spool/cups/tmp", in the case above it's "foomatic-kqwNwc" (see the "gs" command), which is a complete and well-formed pdf; in order to do some tests, I copied it to "/tmp" before canceling the job; then, on the terminal, piping together the above "gs" command, the "foo2zjs-wrapper" command from "/var/log/cups/error_log" (log level debug, see at the end of post), and the "/usr/lib/cups/backend/usb" command, I managed to print, ie the printer just works flawlessly...

gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -dShowAcroForm -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r300 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c 'save pop' -f /tmp/foomatic-kqwNwc | foo2zjs-wrapper -z2 -P -L0 -r1200x600 -p9 -T3 -m1 -s7 -n1 | DEVICE_URI="usb://HP/LaserJet%20Professional%20P1102?serial=000000000Q87FWBPPR1a"  /usr/lib/cups/backend/usb 552 anonymous Test 1 fakeoption

Note that in order for this to work, the temp file one can copy from "/var/spool/cups/tmp" to "/tmp" must be set readable for the user who will run the command, then any job on the queue must be canceled, and then the printer has to be turned off and then on. Then, the command above works even subsequent times, ie it works every time until another job is queued from some applications to cups. The command works even when cups is not running (obviously).

Here comes the relevant part of "/var/log/cups/error_log"...

D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [02/Sep/2018:06:44:08 +0200] [Client 1] Server address is "/run/cups/cups.sock".
D [02/Sep/2018:06:44:08 +0200] [Client 1] Accepted from localhost (Domain)
D [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.
D [02/Sep/2018:06:44:08 +0200] [Client 1] POST / HTTP/1.1
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=200, state=6
D [02/Sep/2018:06:44:08 +0200] [Client 1] No authentication data provided.
D [02/Sep/2018:06:44:08 +0200] [Client 1] 2.0 Get-Printer-Attributes 8
D [02/Sep/2018:06:44:08 +0200] Get-Printer-Attributes ipp://localhost:631/printers/HP_LaserJet_Professional_P1102_su_Gargantua
D [02/Sep/2018:06:44:08 +0200] [Client 1] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/HP_LaserJet_Professional_P1102_su_Gargantua) from localhost.
D [02/Sep/2018:06:44:08 +0200] [Client 1] Content-Length: 1435
D [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [02/Sep/2018:06:44:08 +0200] [Client 1] con->http=0x555ab3182c80
D [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1435, response=0x555ab316abb0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [02/Sep/2018:06:44:08 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [02/Sep/2018:06:44:08 +0200] [Client 1] bytes=0, http_state=0, data_remaining=1435
D [02/Sep/2018:06:44:08 +0200] [Client 1] Flushing write buffer.
D [02/Sep/2018:06:44:08 +0200] [Client 1] New state is HTTP_STATE_WAITING
D [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [02/Sep/2018:06:44:08 +0200] [Client 1] POST /printers/HP_LaserJet_Professional_P1102_su_Gargantua HTTP/1.1
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=200, state=6
D [02/Sep/2018:06:44:08 +0200] [Client 1] No authentication data provided.
D [02/Sep/2018:06:44:08 +0200] [Client 1] 2.0 Get-Printer-Attributes 9
D [02/Sep/2018:06:44:08 +0200] Get-Printer-Attributes ipp://localhost/printers/HP_LaserJet_Professional_P1102_su_Gargantua
D [02/Sep/2018:06:44:08 +0200] [Client 1] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/HP_LaserJet_Professional_P1102_su_Gargantua) from localhost.
D [02/Sep/2018:06:44:08 +0200] [Client 1] Content-Length: 421992
D [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [02/Sep/2018:06:44:08 +0200] [Client 1] con->http=0x555ab3182c80
D [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=421992, response=0x555ab316a2f0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [02/Sep/2018:06:44:08 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [02/Sep/2018:06:44:08 +0200] [Client 1] bytes=0, http_state=0, data_remaining=421992
D [02/Sep/2018:06:44:08 +0200] [Client 1] Flushing write buffer.
D [02/Sep/2018:06:44:08 +0200] [Client 1] New state is HTTP_STATE_WAITING
D [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [02/Sep/2018:06:44:08 +0200] [Client 1] POST /printers/HP_LaserJet_Professional_P1102_su_Gargantua HTTP/1.1
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=200, state=6
D [02/Sep/2018:06:44:08 +0200] [Client 1] No authentication data provided.
D [02/Sep/2018:06:44:08 +0200] [Client 1] 2.0 Create-Job 10
D [02/Sep/2018:06:44:08 +0200] Create-Job ipp://localhost/printers/HP_LaserJet_Professional_P1102_su_Gargantua
D [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [02/Sep/2018:06:44:08 +0200] [Job 554] Applying default options...
D [02/Sep/2018:06:44:08 +0200] add_job: requesting-user-name="gnucco"
D [02/Sep/2018:06:44:08 +0200] Adding default job-sheets values "none,none"...
I [02/Sep/2018:06:44:08 +0200] [Job 554] Adding start banner page "none".
D [02/Sep/2018:06:44:08 +0200] Discarding unused job-created event...
I [02/Sep/2018:06:44:08 +0200] [Job 554] Queued on "HP_LaserJet_Professional_P1102_su_Gargantua" by "gnucco".
D [02/Sep/2018:06:44:08 +0200] [Client 1] Returning IPP successful-ok for Create-Job (ipp://localhost/printers/HP_LaserJet_Professional_P1102_su_Gargantua) from localhost.
D [02/Sep/2018:06:44:08 +0200] [Client 1] Content-Length: 201
D [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [02/Sep/2018:06:44:08 +0200] [Client 1] con->http=0x555ab3182c80
D [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=201, response=0x555ab31782e0(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [02/Sep/2018:06:44:08 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [02/Sep/2018:06:44:08 +0200] [Client 1] bytes=0, http_state=0, data_remaining=201
D [02/Sep/2018:06:44:08 +0200] [Client 1] Flushing write buffer.
D [02/Sep/2018:06:44:08 +0200] [Client 1] New state is HTTP_STATE_WAITING
D [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [02/Sep/2018:06:44:08 +0200] [Client 1] POST /printers/HP_LaserJet_Professional_P1102_su_Gargantua HTTP/1.1
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=200, state=6
D [02/Sep/2018:06:44:08 +0200] [Client 1] No authentication data provided.
D [02/Sep/2018:06:44:08 +0200] [Client 1] 2.0 Send-Document 11
D [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=100, state=6
D [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=100, state=6
D [02/Sep/2018:06:44:08 +0200] Send-Document ipp://localhost:631/printers/HP_LaserJet_Professional_P1102_su_Gargantua
D [02/Sep/2018:06:44:08 +0200] cupsdIsAuthorized: requesting-user-name="gnucco"
D [02/Sep/2018:06:44:08 +0200] [Job 554] Auto-typing file...
D [02/Sep/2018:06:44:08 +0200] [Job 554] Request file type is application/pdf.
D [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [02/Sep/2018:06:44:08 +0200] [Job 554] File of type application/pdf queued by "gnucco".
I [02/Sep/2018:06:44:08 +0200] [Job 554] Adding end banner page "none".
D [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [02/Sep/2018:06:44:08 +0200] [Job 554] time-at-processing=1535863448
D [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [02/Sep/2018:06:44:08 +0200] Discarding unused printer-state-changed event...
D [02/Sep/2018:06:44:08 +0200] [Job 554] 2 filters for job:
D [02/Sep/2018:06:44:08 +0200] [Job 554] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [02/Sep/2018:06:44:08 +0200] [Job 554] foomatic-rip (application/vnd.cups-pdf to printer/HP_LaserJet_Professional_P1102_su_Gargantua, cost 0)
D [02/Sep/2018:06:44:08 +0200] [Job 554] job-sheets=none,none
D [02/Sep/2018:06:44:08 +0200] [Job 554] argv[0]="HP_LaserJet_Professional_P1102_su_Gargantua"
D [02/Sep/2018:06:44:08 +0200] [Job 554] argv[1]="554"
D [02/Sep/2018:06:44:08 +0200] [Job 554] argv[2]="gnucco"
D [02/Sep/2018:06:44:08 +0200] [Job 554] argv[3]="provastampa.odt"
D [02/Sep/2018:06:44:08 +0200] [Job 554] argv[4]="1"
D [02/Sep/2018:06:44:08 +0200] [Job 554] argv[5]="InputSlot=Auto PageSize=Letter job-uuid=urn:uuid:d6e5565b-6600-3187-7334-81a19301f117 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1535863448 time-at-processing=1535863448 document-name-supplied=DhRNfu"
D [02/Sep/2018:06:44:08 +0200] [Job 554] argv[6]="/var/spool/cups/d00554-001"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[7]="CUPS_STATEDIR=/run/cups"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[8]="HOME=/var/spool/cups/tmp"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[10]="SERVER_ADMIN=root@gargantua.manuelito.lan"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[11]="SOFTWARE=CUPS/2.2.8"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[13]="USER=root"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[14]="CUPS_MAX_MESSAGE=2047"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[17]="IPP_PORT=631"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[18]="CHARSET=utf-8"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[19]="LANG=it_IT.UTF-8"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[20]="PPD=/etc/cups/ppd/HP_LaserJet_Professional_P1102_su_Gargantua.ppd"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[21]="RIP_MAX_CACHE=128m"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[22]="CONTENT_TYPE=application/pdf"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[23]="DEVICE_URI=usb://HP/LaserJet%20Professional%20P1102?serial=000000000Q87FWBPPR1a"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[24]="PRINTER_INFO=HP LaserJet Professional P1102"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[25]="PRINTER_LOCATION=Gargantua"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[26]="PRINTER=HP_LaserJet_Professional_P1102_su_Gargantua"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[27]="PRINTER_STATE_REASONS=none"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[28]="CUPS_FILETYPE=document"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-pdf"
D [02/Sep/2018:06:44:08 +0200] [Job 554] envp[30]="AUTH_I****"
I [02/Sep/2018:06:44:08 +0200] [Job 554] Started filter /usr/lib/cups/filter/pdftopdf (PID 2253)
I [02/Sep/2018:06:44:08 +0200] [Job 554] Started filter /usr/lib/cups/filter/foomatic-rip (PID 2254)
I [02/Sep/2018:06:44:08 +0200] [Job 554] Started backend /usr/lib/cups/backend/usb (PID 2255)
D [02/Sep/2018:06:44:08 +0200] Discarding unused job-state-changed event...
D [02/Sep/2018:06:44:08 +0200] [Client 1] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/HP_LaserJet_Professional_P1102_su_Gargantua) from localhost.
D [02/Sep/2018:06:44:08 +0200] [Client 1] Content-Length: 171
D [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [02/Sep/2018:06:44:08 +0200] [Client 1] con->http=0x555ab3182c80
D [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=171, response=0x555ab316abb0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [02/Sep/2018:06:44:08 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [02/Sep/2018:06:44:08 +0200] [Client 1] bytes=0, http_state=0, data_remaining=171
D [02/Sep/2018:06:44:08 +0200] [Client 1] Flushing write buffer.
D [02/Sep/2018:06:44:08 +0200] [Client 1] New state is HTTP_STATE_WAITING
D [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [02/Sep/2018:06:44:08 +0200] [Job 554] pdftopdf: Last filter determined by the PPD: foomatic-rip; FINAL_CONTENT_TYPE: application/vnd.cups-pdf => pdftopdf will log pages in page_log.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Calling FindDeviceById(cups-HP_LaserJet_Professional_P1102_su_Gargantua)
D [02/Sep/2018:06:44:08 +0200] [Job 554] PAGE: 1 1
D [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [02/Sep/2018:06:44:08 +0200] Discarding unused job-progress event...
D [02/Sep/2018:06:44:08 +0200] [Job 554] Found device /org/freedesktop/ColorManager/devices/cups_HP_LaserJet_Professional_P1102_su_Gargantua
D [02/Sep/2018:06:44:08 +0200] [Job 554] Calling org.freedesktop.ColorManager.Device.Get(ProfilingInhibitors)
D [02/Sep/2018:06:44:08 +0200] [Job 554] \'CM Color Calibration\' Mode in SPOOLER-LESS: Off
D [02/Sep/2018:06:44:08 +0200] [Job 554] Getting input from file
D [02/Sep/2018:06:44:08 +0200] [Job 554] foomatic-rip version 1.21.1 running...
D [02/Sep/2018:06:44:08 +0200] [Job 554] Parsing PPD file ...
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option ColorSpace
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option PageSize
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Quality
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Resolution
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option ImageableArea
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option PaperDimension
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option InputSlot
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option MediaType
D [02/Sep/2018:06:44:08 +0200] [Job 554] PID 2253 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Density
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Copies
D [02/Sep/2018:06:44:08 +0200] [Job 554] Loading USB quirks from \"/usr/share/cups/usb\".
D [02/Sep/2018:06:44:08 +0200] [Job 554] Loaded 89 quirks.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Printing on printer with URI: usb://HP/LaserJet%20Professional%20P1102?serial=000000000Q87FWBPPR1a
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option halftone
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option NupOrient
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option NupPages
D [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Font
D [02/Sep/2018:06:44:08 +0200] [Job 554] Parameter Summary
D [02/Sep/2018:06:44:08 +0200] [Job 554] -----------------
D [02/Sep/2018:06:44:08 +0200] [Job 554] Spooler: cups
D [02/Sep/2018:06:44:08 +0200] [Job 554] Printer: HP_LaserJet_Professional_P1102_su_Gargantua
D [02/Sep/2018:06:44:08 +0200] [Job 554] Shell: /bin/bash
D [02/Sep/2018:06:44:08 +0200] [Job 554] PPD file: /etc/cups/ppd/HP_LaserJet_Professional_P1102_su_Gargantua.ppd
D [02/Sep/2018:06:44:08 +0200] [Job 554] ATTR file:
D [02/Sep/2018:06:44:08 +0200] [Job 554] Printer model: HP LaserJet Pro P1102 Foomatic/foo2zjs-z2 (recommended)
D [02/Sep/2018:06:44:08 +0200] [Job 554] Job title: provastampa.odt
D [02/Sep/2018:06:44:08 +0200] [Job 554] File(s) to be printed:
D [02/Sep/2018:06:44:08 +0200] [Job 554] <STDIN>
D [02/Sep/2018:06:44:08 +0200] [Job 554] Ghostscript extra search path (\'GS_LIB\'): /usr/share/cups/fonts
D [02/Sep/2018:06:44:08 +0200] [Job 554] Printing system options:
D [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \'job-uuid=urn:uuid:d6e5565b-6600-3187-7334-81a19301f117\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option job-uuid=urn:uuid:d6e5565b-6600-3187-7334-81a19301f117.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \'job-originating-host-name=localhost\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option job-originating-host-name=localhost.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \'date-time-at-creation=\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option date-time-at-creation=.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \'date-time-at-processing=\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option date-time-at-processing=.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \'time-at-creation=1535863448\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option time-at-creation=1535863448.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \'time-at-processing=1535863448\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option time-at-processing=1535863448.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \'document-name-supplied=DhRNfu\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option document-name-supplied=DhRNfu.
D [02/Sep/2018:06:44:08 +0200] [Job 554] CM Color Calibration Mode in CUPS: Off
D [02/Sep/2018:06:44:08 +0200] [Job 554] Options from the PPD file:
D [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \'InputSlot=Auto\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \'PageSize=Letter\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] ================================================
D [02/Sep/2018:06:44:08 +0200] [Job 554] File: <STDIN>
D [02/Sep/2018:06:44:08 +0200] [Job 554] ================================================
D [02/Sep/2018:06:44:08 +0200] [Job 554] Filetype: PDF
D [02/Sep/2018:06:44:08 +0200] [Job 554] Neither PDF renderer command line nor Ghostscript-based renderer command line found
D [02/Sep/2018:06:44:08 +0200] [Job 554] Driver does not understand PDF input, converting to PostScript
D [02/Sep/2018:06:44:08 +0200] [Job 554] Storing temporary files in /var/spool/cups/tmp
D [02/Sep/2018:06:44:08 +0200] [Job 554] libusb_get_device_list=6
D [02/Sep/2018:06:44:08 +0200] [Job 554] Starting process \"pdf-to-ps\" (generation 1)
D [02/Sep/2018:06:44:08 +0200] [Job 554] STATE: +connecting-to-device
D [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [02/Sep/2018:06:44:08 +0200] Discarding unused printer-state-changed event...
D [02/Sep/2018:06:44:08 +0200] [Job 554] STATE: -connecting-to-device
D [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [02/Sep/2018:06:44:08 +0200] Discarding unused printer-state-changed event...
D [02/Sep/2018:06:44:08 +0200] [Job 554] Device protocol: 2
D [02/Sep/2018:06:44:08 +0200] [Job 554] Printer does not like usblp kernel module to be re-attached after job
D [02/Sep/2018:06:44:08 +0200] [Job 554] Invio dei dati alla stampante.
D [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)
D [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [02/Sep/2018:06:44:08 +0200] [Job 554] Set job-printer-state-message to "Invio dei dati alla stampante.", current level=INFO
D [02/Sep/2018:06:44:08 +0200] Discarding unused job-progress event...
D [02/Sep/2018:06:44:08 +0200] Discarding unused printer-state-changed event...
D [02/Sep/2018:06:44:08 +0200] [Job 554] Printer make and model: HP HP LaserJet Professional P1102
D [02/Sep/2018:06:44:08 +0200] [Job 554] Running command line for pstops: pstops 554 gnucco provastampa.odt 1 \' InputSlot=Auto PageSize=Letter job-uuid=urn:uuid:d6e5565b-6600-3187-7334-81a19301f117 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1535863448 time-at-processing=1535863448 document-name-supplied=DhRNfu\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] No resolution information found in the PPD file.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Using image rendering resolution 300 dpi
D [02/Sep/2018:06:44:08 +0200] [Job 554] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -dShowAcroForm -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r300 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c \'save pop\' -f /var/spool/cups/tmp/foomatic-kqwNwc
D [02/Sep/2018:06:44:08 +0200] [Job 554] Started filter gs (PID 2261)
D [02/Sep/2018:06:44:08 +0200] [Job 554] Started filter pstops (PID 2262)
D [02/Sep/2018:06:44:08 +0200] [Job 554] Page = 612x792; 11,11 to 601,781
D [02/Sep/2018:06:44:08 +0200] [Job 554] slow_collate=0, slow_duplex=0, slow_order=0
D [02/Sep/2018:06:44:08 +0200] [Job 554] Before copy_comments - %!PS-Adobe-3.0
D [02/Sep/2018:06:44:08 +0200] [Job 554] %!PS-Adobe-3.0
D [02/Sep/2018:06:44:08 +0200] [Job 554] %%BoundingBox: 0 0 612 792
D [02/Sep/2018:06:44:08 +0200] [Job 554] %%HiResBoundingBox: 0 0 612.00 792.00
D [02/Sep/2018:06:44:08 +0200] [Job 554] %%Creator: GPL Ghostscript 923 (ps2write)
D [02/Sep/2018:06:44:08 +0200] [Job 554] %%LanguageLevel: 2
D [02/Sep/2018:06:44:08 +0200] [Job 554] %%CreationDate: D:20180902064408+02\'00\'
D [02/Sep/2018:06:44:08 +0200] [Job 554] %%Pages: 1
D [02/Sep/2018:06:44:08 +0200] [Job 554] %%EndComments
D [02/Sep/2018:06:44:08 +0200] [Job 554] Before copy_prolog - %%BeginProlog
D [02/Sep/2018:06:44:08 +0200] [Job 554] Filetype: PostScript
D [02/Sep/2018:06:44:08 +0200] [Job 554] Reading PostScript input ...
D [02/Sep/2018:06:44:08 +0200] [Job 554] --> This document is DSC-conforming!
D [02/Sep/2018:06:44:08 +0200] [Job 554] Found %RBINumCopies: 1
D [02/Sep/2018:06:44:08 +0200] [Job 554] -----------
D [02/Sep/2018:06:44:08 +0200] [Job 554] Found: %%BeginProlog
D [02/Sep/2018:06:44:08 +0200] [Job 554] Inserting option code into \"Prolog\" section.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Flushing FIFO.
D [02/Sep/2018:06:44:08 +0200] [Job 554] \"Prolog\" section is missing, inserting it.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Inserting option code into \"Prolog\" section.
D [02/Sep/2018:06:44:08 +0200] [Job 554] Starting renderer with command: \"foo2zjs-wrapper -z2 -P -L0     -r1200x600 -p1 -T3 -m1 -s7   -n1 \"
D [02/Sep/2018:06:44:08 +0200] [Job 554] Starting process \"kid3\" (generation 1)
D [02/Sep/2018:06:44:08 +0200] [Job 554] Closing renderer
D [02/Sep/2018:06:44:08 +0200] [Job 554] Starting process \"kid4\" (generation 2)
D [02/Sep/2018:06:44:08 +0200] [Job 554] Starting process \"renderer\" (generation 2)
D [02/Sep/2018:06:44:08 +0200] [Job 554] JCL: \033%-12345X@PJL
D [02/Sep/2018:06:44:08 +0200] [Job 554] <job data>
D [02/Sep/2018:06:44:08 +0200] [Job 554] Not a pbm file!
D [02/Sep/2018:06:44:08 +0200] [Job 554] renderer exited with status 0
D [02/Sep/2018:06:44:08 +0200] [Job 554] Read 312 bytes of print data...
D [02/Sep/2018:06:44:08 +0200] [Job 554] Wrote 312 bytes of print data...
D [02/Sep/2018:06:44:08 +0200] [Job 554] kid4 exited with status 0
D [02/Sep/2018:06:44:08 +0200] [Job 554] kid3 finished
D [02/Sep/2018:06:44:08 +0200] [Job 554] kid3 exited with status 0
D [02/Sep/2018:06:44:08 +0200] [Job 554] Read 56 bytes of back-channel data...
D [02/Sep/2018:06:44:08 +0200] [Job 554] Read 59 bytes of back-channel data...
D [02/Sep/2018:06:44:38 +0200] [Job 554] Read 58 bytes of back-channel data...
I [02/Sep/2018:06:44:38 +0200] Saving job.cache...
D [02/Sep/2018:06:44:38 +0200] cupsdSetBusyState: newbusy="Printing jobs", busy="Printing jobs and dirty files"
D [02/Sep/2018:06:44:38 +0200] Report: clients=1
D [02/Sep/2018:06:44:38 +0200] Report: jobs=16
D [02/Sep/2018:06:44:38 +0200] Report: jobs-active=1
D [02/Sep/2018:06:44:38 +0200] Report: printers=1
D [02/Sep/2018:06:44:38 +0200] Report: stringpool-string-count=17621
D [02/Sep/2018:06:44:38 +0200] Report: stringpool-alloc-bytes=11496
D [02/Sep/2018:06:44:38 +0200] Report: stringpool-total-bytes=319600
D [02/Sep/2018:06:45:08 +0200] [Job 554] Read 58 bytes of back-channel data...
@severach
Copy link

severach commented Sep 8, 2018

apple/cups#5396

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

@tillkamppeter I see similar thing in Fedora 29:
Packages:
cups-2.2.8
cups-filters-1.20.3
glibc-2.28

When I install printer (Canon, with ppd foomatic:Canon-imageRunner_C5185i-Postscript.ppd from foomatic) as ipp printer (by "lpadmin -p test -v ipp://hostname:631/printers/printer -m foomatic:Canon-imageRunner_C5185i-Postscript.ppd -E" or when I add it by gnome-control-center) and then send the job to it, it never prints and stays as pending-held until canceling the job. And the printer prints out following text after cancelling:

ERROR:
undefined
OFFENDING COMMAND:
curr
STACK:
/InitialExtGState

Here are logs for the job (after canceling): https://paste.fedoraproject.org/paste/vknps-YyBB~IEsc~n-p1SQ

I think what connects @severach, @pezcurrel and my issues is foomatic-rip filter - it is used in all cases and symptoms are similar for our issues. And this issue started with glibc-2.28 - I'm currently trying to find actual glibc commit after which the issue began.
IMHO a change in glibc influenced something in foomatic-rip filter, which causes the issue.

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

And when I print with -oraw (lp -d test -oraw test-file), file is printed - that makes me think it is really filter problem.

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

Here is the file which goes to the printer, after filtering: https://paste.fedoraproject.org/paste/eX6KaC-wBsX0KBiYGgOrjA

@tillkamppeter
Copy link
Member

As the printer is receiving PostScript and not able to print it I would guess that it is some PS interpreter bug in the printer. See the README file of cups-filters for how to force the pdftops filter to use Poppler or MuPDF for generating PostScript. Does the printer print this way?
Another possibility is to use another language which the printer understands, like PCL or driverless printing (uses PDF, PWG Raster, Apple Raster, or PCLm). Do you get it to work this way?
Note that the PS file you have pasted is incomplete. Did you copy and paste it from an editor? The buffer for copy and paste can perhaps be too small.
If you rename the file to have a .txt extension (mv file.ps file.ps.txt) you can directly attach it to this bug report, without need of Pastebin.

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

File is postscript and its opening ends with:
GPL Ghostscript 9.23 (2018-03-21)
Copyright (C) 2018 Artifex Software, Inc. All rights reserved.
This software comes with NO WARRANTY: see the file PUBLIC for details.
%%[ Error handled by opdfread.ps : undefined; OffendingCommand: cur ]%%

showpage, press to continue<<

@tillkamppeter
Copy link
Member

This error is due to the case that the file is incomplete.

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

@tillkamppeter I redirected cat to fpaste, which creates pastebin.
$ cat printout | fpaste

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

@tillkamppeter Isn't it incomplete because the printing didn't end? Because the job stays in pending-held state (according network traffic and logs)?

@tillkamppeter
Copy link
Member

How did you extract this Postscript file?

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

@tillkamppeter I can reproduce this behavior even with file device printer (with ppd mentioned above), so when you have glibc-2.28, you can see the issue too.

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

@tillkamppeter The same way as described in https://wiki.ubuntu.com/DebuggingPrintingProblems - Getting the data which would go to the printer

@tillkamppeter
Copy link
Member

OK, I will try it.

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

foomatic-tmp-file.txt

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

I told Chris Liddell about the issue and I uploaded file from /var/spool/cups/tmp/foomatic* upon his request.

@severach
Copy link

I think what connects @severach, @pezcurrel and my issues is foomatic-rip filter

HP LaserJet 4100 and Lexmark are printing fine with the foomatic-rip filter. The difference is that their FoomaticRIPCommandLine only contains gs which makes cups run different filters. Any printer model can be broken by changing "gs" to "/usr/bin/gs".

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

I bisected glibc commits and found out in glibc upstream commits:

  • the problem occurred among commits:
    7108f1f944792ac6833 - aarch64: Improve strncmp for mutually misaligned inputs
    2cc7bad0ae0a412e75270b - [BZ 1190] Make EOF sticky in stdio.
    778f1974863d63e858b - Update translations from the Translation Project
    and because the first is only for aarch64 and the last is translations update, then:

2cc7bad0ae0a412e75270b - [BZ 1190] Make EOF sticky in stdio.

is the best candidate (filters work with files too, so there can be a usage of EOF).

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

@severach
Copy link

filters work with files too

Cups moves everything around in pipes. I think it's pipes, not files.

@zdohnal
Copy link
Member

zdohnal commented Sep 11, 2018

@severach yup, you're right, sorry - they're working with pipes.

@tillkamppeter
Copy link
Member

But note that many filters (AFAIK also foomatic-rip) suck the whole stdin into a file before they actually start to work. And PDF (which is foomatic-rip's input format in our example) usually requires to get read completely to get processed due to the fact that the XREF table is at the end of the file.

@severach
Copy link

severach commented Sep 11, 2018

So a slight change in EOF logic makes the EOF not show up as expected and the rip doesn't go on to the next step. The Canon UFR II driver breaks like this quite often.

@0xjmz
Copy link

0xjmz commented Sep 11, 2018

I think I also track the problem to the recent glibc update. If I execute the following code

#include <stdio.h>
#include <unistd.h>

void main(void)
{
    FILE *f;
    int c;

    f = fopen("/etc/issue","r");
    dup2(fileno(f),fileno(stdin));
    while( (c=fgetc(stdin)) != EOF)
        printf("%c",c);
    fclose(f);

    f = fopen("/etc/issue","r");
    dup2(fileno(f),fileno(stdin));
    while( (c=fgetc(stdin)) != EOF)
        printf("%c",c);
    fclose(f);
}

Then in glibc 2.28 a get only one line output on old Debian box as expected two lines. The problem is the combine code of 'standard library' and 'syscalls'. The workaround which solve the problem for me at least is the following patch

diff -Naur a/filter/foomatic-rip/foomaticrip.c b/filter/foomatic-rip/foomaticrip.c
--- a/filter/foomatic-rip/foomaticrip.c	2018-08-20 22:48:20.000000000 +0200
+++ b/filter/foomatic-rip/foomaticrip.c	2018-09-11 20:08:09.542690450 +0200
@@ -585,7 +585,7 @@
         jobhasjcl = 1;
         write_output(buf, startpos);
     }*/
-    if (file != stdin)
+    /*if (file != stdin)*/
         rewind(file);
 
     if (convert) pdfconvertedtops = 0;

That rewinds the 'stdin' handle (descriptor). However I think the real solution should be to get rid of the ugly combination of dup2 and stdio.

I also post this workaround on Arch forum: https://bbs.archlinux.org/viewtopic.php?id=240247

Maybe someone has a more time to prepare more comprehensive patch. Right now this workaround
should works.

@wifiprintguy
Copy link

wifiprintguy commented Sep 11, 2018

I'm fairly certain these printers do not support PostScript...

Confirmed: https://support.hp.com/us-en/document/c01999607/

@rickrich
Copy link

rickrich commented Sep 11, 2018

I compiled the 0xjmz one line patch of foomatic-rip against a VirtualBox instance of Linux Mint 19 targeting a networked LaserJet Pro P1102W. Same thing, it does not work.

But an un-patched VirtualBox instance of Ubuntu 18.04 targeting a networked LaserJet Pro P1102W does work.

@severach
Copy link

severach commented Sep 12, 2018

The P1102 printer doesn't see any postscript. Cups generates postscript. ghostscript renders it to graphics. foo2 encodes it as ZjStream. The P1102 is caught in the quagmire because it uses a command other than gs in FoomaticRIPCommandLine.

libio/fileops.c
libio/oldfileops.c
libio/wfileops.c

I trimmed the glibc diff to just these 3 files, reversed the patch, and compiled. Ricoh and Savin print fine.

https://sourceware.org/bugzilla/show_bug.cgi?id=23636

I don't think patching the filter is right. Changing pipe behavior is going to break a lot more than just printers. I see 3 glibc 2.28 bug reports on the Arch Bug Tracker. This needs to be reverted until more test cases help determine how it should be done.

@rickrich
Copy link

rickrich commented Sep 12, 2018

If I compile 0xjmz test program on Ubuntu 18.04, I get two lines.
If I compile 0xjmz test program on Linux Mint 18.3, I get two lines.
If I compile 0xjmz test program on Linux Mint 19, I get two lines.
If I compile 0xjmz test program on fresh Arch Linux, I get one line.

Ubuntu 18.04 and HP LaserJet Pro P1102 works.
Linux Mint 18.3 and HP LaserJet Pro P1102 works.
Linux Mint 19 and HP LaserJet Pro P1102 doesn't work.
Arch Linux and HP LaserJet Pro P1102 doesn't work.

So, there are two problems.

@0xjmz
Copy link

0xjmz commented Sep 12, 2018

Well, Rickrich probably your printer is using different path. If I grep -Ri dup2.*stdin source code it looks like there are more places to change. I tested the following patch

diff -Naur a/filter/foomatic-rip/foomaticrip.c b/filter/foomatic-rip/foomaticrip.c
--- a/filter/foomatic-rip/foomaticrip.c	2018-08-20 22:48:20.000000000 +0200
+++ b/filter/foomatic-rip/foomaticrip.c	2018-09-12 07:27:39.192764560 +0200
@@ -585,8 +585,7 @@
         jobhasjcl = 1;
         write_output(buf, startpos);
     }*/
-    if (file != stdin)
-        rewind(file);
+    rewind(file);
 
     if (convert) pdfconvertedtops = 0;
 
@@ -659,6 +658,7 @@
 
                 renderer_pid = start_system_process("pdf-to-ps", pdf2ps_cmd, &in, &out);
 
+                rewind(stdin);
                 if (dup2(fileno(out), fileno(stdin)) < 0)
                     rip_die(EXIT_PRNERR_NORETRY_BAD_SETTINGS,
                             "Couldn't dup stdout of pdf-to-ps\n");
diff -Naur a/filter/foomatic-rip/renderer.c b/filter/foomatic-rip/renderer.c
--- a/filter/foomatic-rip/renderer.c	2018-02-07 23:08:41.000000000 +0100
+++ b/filter/foomatic-rip/renderer.c	2018-09-12 07:26:38.631973662 +0200
@@ -420,6 +420,7 @@
         return EXIT_PRNERR_NORETRY_BAD_SETTINGS;
     }
 
+    rewind(stdin);
     if (in && dup2(fileno(in), fileno(stdin)) < 0) {
         _log("kid3: Could not dup stdin\n");
         fclose(kid4in);

against my printer (LaserJet P1006) and it still works. However, I agree with severach glibc should not break the userspace in such a way. The sticky EOF in stdin will break much more applications and in the worst way - silently.

@severach
Copy link

severach commented Sep 12, 2018

/etc/issue on my Arch has one text line and one blank line. That might look line one line if you're not counting carefully. /etc/issue on Manjaro has 1 text line and 2 blank lines.


Paging @barthalion

@rickrich
Copy link

I compiled your three line patch on Linux Mint 19, and it still didn't work.
Note: Linux Mint 19 has libc6 2.27, not 2.28.

So, there are two problems.

@0xjmz
Copy link

0xjmz commented Sep 12, 2018

Ok. In this case unfortunately you have a different problem. This patch is against glibc 2.28 and its sticky EOF commit. And as I see you get two lines (the same output twice) in above C code.

@fweimer
Copy link

fweimer commented Sep 12, 2018

I think I also track the problem to the recent glibc update. If I execute the following code

Is this an attempt at reimplementing freopen? I don't think this is valid; you cannot replace the underlying descriptor in this way.

@0xjmz
Copy link

0xjmz commented Sep 12, 2018

As you can see in the patch the C code is a reimplementation what cups-filters are doing with stdin. And I think that it shouldn't combine standard library with syscalls in this way as well.

@zdohnal
Copy link
Member

zdohnal commented Sep 12, 2018

@0xjmz I tested the first patch on our Canon printers and it works, thanks! But as you said, other printers can take other processing path, so it can help only for some printers.

@0xjmz
Copy link

0xjmz commented Sep 12, 2018

I'm glad to help. My guess is that the second patch make all necessary changes if the problem is with glibc that it should work on all printers. In other words if the printer worked and after upgrade to glibc 2.28 it doesn't the patch should help.

@atsampson
Copy link

The FreeBSD port of cups-filters has included a patch that does clearerr(stdin); after the dup2 since 2015.

@0xjmz
Copy link

0xjmz commented Sep 17, 2018

Nice work. I hope that at this point upstream will fix that bug. On the other hand since FreeBSD has its own libc implementation the bug could appear sooner.

@fweimer
Copy link

fweimer commented Sep 21, 2018

FYI: glibc has declined to revert the bug fix which changed behavior:

@tillkamppeter
Copy link
Member

Can someone test whether everything works again when I apply the patch from @atsampson of the BSD port?

@zdohnal
Copy link
Member

zdohnal commented Sep 21, 2018

@tillkamppeter I can test it for our Canon ImageRunner printers and file devices. If you request more testing, please tell me and specify what I should test.

@tillkamppeter
Copy link
Member

@zdohnal I think your test on the Canon ImageRunner printers would be great. I do not know about any other specific tests needed now.
Everyone else reading here and having this problem, please also test the patch with your printer(s).

@0xjmz
Copy link

0xjmz commented Sep 21, 2018

I can confirm that it works on my printer HP LaserJet. By the way it is exactly the first patch that I sent in this thread, so it should work for people that my patch worked. The BSD guys are using 'clearerr(stdin)' instead I reused 'rewind' that is already in the code.

@tillkamppeter
Copy link
Member

@0xjmz, in your last patch you add the rewind() call at three points whereas the BSD patch adds the clearerr() call only at one point. Is a rewind() or clearerr() actually needed at the given 3 points or is it enough at the one place where the BSD guys have put it? @0xjmz and @zdohnal, which patch did you actually test?

@zdohnal
Copy link
Member

zdohnal commented Sep 21, 2018

@tillkamppeter I tested the patch on printer with ppd from foomatic Canon ImageRunner C5185i and on file device, both works.
@0xjmz IMO your patch clears EOF on file every time when processing goes into print_file(), BSD guys clear it only when file is PDF. I'm not sure if it can cause troubles for f.e. postscript file...

@zdohnal
Copy link
Member

zdohnal commented Sep 21, 2018

@tillkamppeter I tested both - @0xjmz's first patch and patch from BSD, both works for me.

@zdohnal
Copy link
Member

zdohnal commented Sep 21, 2018

@tillkamppeter I didn't test it with @0xjmz second patch.

@0xjmz
Copy link

0xjmz commented Sep 21, 2018

Well, if you take a look at the source code (filter/foomatic-rip/foomaticrip.c) then you notice that 'clearerr' is inserted in the place where function print_file is executed recursively. Thus, STDIN will be used again. However, at the beginning of the function print_file all file descriptors are rewound except STDIN. My first patch simply removed this restriction (STDIN is rewound as well). Therefore, the
clearerr(stdin) is not necessary. By the way the function clearerr is only used to clear EOF flag (rewind). The second patch however, is a clear overshoot. I just grep dup2 occurrences and added rewind just in case. So, I think that it will suffice either BSD or my first patch to make this bug go away.

@tillkamppeter
Copy link
Member

Fixed in commit 64ca9c2
Thank you for the bug report and the patches.

@valpackett
Copy link

If anyone finds this thread as the only google hit for "Read 58 bytes of back-channel data..." and if your printer has worked the last time you tried and now doesn't: the same symptom (usb backend process hanging after logging that message) can happen when something is "stuck" inside the printer's firmware or whatever.

In my case, unplugging the printer from a FreeBSD box into a Windows one also resulted in print jobs getting stuck, so turns out it's the printer and I've had to unplug it from power and plug it back in.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

10 participants