{"action":"created","issue":{"url":"https://api.github.com/repos/OpenPrinting/cups-filters/issues/58","repository_url":"https://api.github.com/repos/OpenPrinting/cups-filters","labels_url":"https://api.github.com/repos/OpenPrinting/cups-filters/issues/58/labels{/name}","comments_url":"https://api.github.com/repos/OpenPrinting/cups-filters/issues/58/comments","events_url":"https://api.github.com/repos/OpenPrinting/cups-filters/issues/58/events","html_url":"https://github.com/OpenPrinting/cups-filters/issues/58","id":356262310,"node_id":"MDU6SXNzdWUzNTYyNjIzMTA=","number":58,"title":"HP LaserJet Pro P1102 always stuck \"sending data to printer\"","user":{"login":"pezcurrel","id":33592962,"node_id":"MDQ6VXNlcjMzNTkyOTYy","avatar_url":"https://avatars1.githubusercontent.com/u/33592962?v=4","gravatar_id":"","url":"https://api.github.com/users/pezcurrel","html_url":"https://github.com/pezcurrel","followers_url":"https://api.github.com/users/pezcurrel/followers","following_url":"https://api.github.com/users/pezcurrel/following{/other_user}","gists_url":"https://api.github.com/users/pezcurrel/gists{/gist_id}","starred_url":"https://api.github.com/users/pezcurrel/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/pezcurrel/subscriptions","organizations_url":"https://api.github.com/users/pezcurrel/orgs","repos_url":"https://api.github.com/users/pezcurrel/repos","events_url":"https://api.github.com/users/pezcurrel/events{/privacy}","received_events_url":"https://api.github.com/users/pezcurrel/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":26,"created_at":"2018-09-02T08:12:08Z","updated_at":"2018-09-12T01:14:51Z","closed_at":null,"author_association":"NONE","body":"Hi,\r\nI'm running an up-to-date Arch Linux box with...\r\n\r\nkernel 4.18.5\r\ncups 2.2.8\r\nlibcups 2.2.8\r\ncups-filters 1.21.1\r\nghostscript 9.23\r\npoppler 0.67.0\r\n\r\n...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).\r\nThe 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.\r\n\r\nWhen I send a job, this is what cups is stuck doing (\"ps -AF --forest\")...\r\n\r\n```\r\nroot       442     1  0 38059 10544   3 05:27 ?        00:00:00 /usr/bin/cupsd -l\r\ncups      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\r\ncups      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\r\ncups      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\r\ncups      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\r\ncups      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\r\n```\r\n\r\n...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).\r\n\r\nAs 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...\r\n\r\n```\r\ngs -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\r\n```\r\n\r\nNote 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).\r\n\r\nHere comes the relevant part of \"/var/log/cups/error_log\"...\r\n\r\n```\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients\", busy=\"Not busy\"\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Server address is \"/run/cups/cups.sock\".\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Accepted from localhost (Domain)\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] POST / HTTP/1.1\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients\", busy=\"Active clients\"\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=200, state=6\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] No authentication data provided.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] 2.0 Get-Printer-Attributes 8\r\nD [02/Sep/2018:06:44:08 +0200] Get-Printer-Attributes ipp://localhost:631/printers/HP_LaserJet_Professional_P1102_su_Gargantua\r\nD [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.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Content-Length: 1435\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdSendHeader: code=200, type=\"application/ipp\", auth_type=0\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] con->http=0x555ab3182c80\r\nD [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\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] bytes=0, http_state=0, data_remaining=1435\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Flushing write buffer.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] New state is HTTP_STATE_WAITING\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Not busy\", busy=\"Active clients\"\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] POST /printers/HP_LaserJet_Professional_P1102_su_Gargantua HTTP/1.1\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients\", busy=\"Not busy\"\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=200, state=6\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] No authentication data provided.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] 2.0 Get-Printer-Attributes 9\r\nD [02/Sep/2018:06:44:08 +0200] Get-Printer-Attributes ipp://localhost/printers/HP_LaserJet_Professional_P1102_su_Gargantua\r\nD [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.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Content-Length: 421992\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdSendHeader: code=200, type=\"application/ipp\", auth_type=0\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] con->http=0x555ab3182c80\r\nD [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\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] bytes=0, http_state=0, data_remaining=421992\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Flushing write buffer.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] New state is HTTP_STATE_WAITING\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Not busy\", busy=\"Active clients\"\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] POST /printers/HP_LaserJet_Professional_P1102_su_Gargantua HTTP/1.1\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients\", busy=\"Not busy\"\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=200, state=6\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] No authentication data provided.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] 2.0 Create-Job 10\r\nD [02/Sep/2018:06:44:08 +0200] Create-Job ipp://localhost/printers/HP_LaserJet_Professional_P1102_su_Gargantua\r\nD [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients and dirty files\", busy=\"Active clients\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Applying default options...\r\nD [02/Sep/2018:06:44:08 +0200] add_job: requesting-user-name=\"gnucco\"\r\nD [02/Sep/2018:06:44:08 +0200] Adding default job-sheets values \"none,none\"...\r\nI [02/Sep/2018:06:44:08 +0200] [Job 554] Adding start banner page \"none\".\r\nD [02/Sep/2018:06:44:08 +0200] Discarding unused job-created event...\r\nI [02/Sep/2018:06:44:08 +0200] [Job 554] Queued on \"HP_LaserJet_Professional_P1102_su_Gargantua\" by \"gnucco\".\r\nD [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.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Content-Length: 201\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdSendHeader: code=200, type=\"application/ipp\", auth_type=0\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] con->http=0x555ab3182c80\r\nD [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\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] bytes=0, http_state=0, data_remaining=201\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Flushing write buffer.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] New state is HTTP_STATE_WAITING\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Dirty files\", busy=\"Active clients and dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] POST /printers/HP_LaserJet_Professional_P1102_su_Gargantua HTTP/1.1\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients and dirty files\", busy=\"Dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=200, state=6\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] No authentication data provided.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] 2.0 Send-Document 11\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=100, state=6\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Read: status=100, state=6\r\nD [02/Sep/2018:06:44:08 +0200] Send-Document ipp://localhost:631/printers/HP_LaserJet_Professional_P1102_su_Gargantua\r\nD [02/Sep/2018:06:44:08 +0200] cupsdIsAuthorized: requesting-user-name=\"gnucco\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Auto-typing file...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Request file type is application/pdf.\r\nD [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients and dirty files\", busy=\"Active clients and dirty files\"\r\nI [02/Sep/2018:06:44:08 +0200] [Job 554] File of type application/pdf queued by \"gnucco\".\r\nI [02/Sep/2018:06:44:08 +0200] [Job 554] Adding end banner page \"none\".\r\nD [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients and dirty files\", busy=\"Active clients and dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] time-at-processing=1535863448\r\nD [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients and dirty files\", busy=\"Active clients and dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Active clients and dirty files\", busy=\"Active clients and dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] Discarding unused printer-state-changed event...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] 2 filters for job:\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)\r\nD [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)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] job-sheets=none,none\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] argv[0]=\"HP_LaserJet_Professional_P1102_su_Gargantua\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] argv[1]=\"554\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] argv[2]=\"gnucco\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] argv[3]=\"provastampa.odt\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] argv[4]=\"1\"\r\nD [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\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] argv[6]=\"/var/spool/cups/d00554-001\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[0]=\"CUPS_CACHEDIR=/var/cache/cups\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[1]=\"CUPS_DATADIR=/usr/share/cups\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[2]=\"CUPS_DOCROOT=/usr/share/cups/doc\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[3]=\"CUPS_FONTPATH=/usr/share/cups/fonts\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[4]=\"CUPS_REQUESTROOT=/var/spool/cups\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[5]=\"CUPS_SERVERBIN=/usr/lib/cups\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[6]=\"CUPS_SERVERROOT=/etc/cups\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[7]=\"CUPS_STATEDIR=/run/cups\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[8]=\"HOME=/var/spool/cups/tmp\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[9]=\"PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[10]=\"SERVER_ADMIN=root@gargantua.manuelito.lan\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[11]=\"SOFTWARE=CUPS/2.2.8\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[12]=\"TMPDIR=/var/spool/cups/tmp\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[13]=\"USER=root\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[14]=\"CUPS_MAX_MESSAGE=2047\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[15]=\"CUPS_SERVER=/run/cups/cups.sock\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[16]=\"CUPS_ENCRYPTION=IfRequested\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[17]=\"IPP_PORT=631\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[18]=\"CHARSET=utf-8\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[19]=\"LANG=it_IT.UTF-8\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[20]=\"PPD=/etc/cups/ppd/HP_LaserJet_Professional_P1102_su_Gargantua.ppd\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[21]=\"RIP_MAX_CACHE=128m\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[22]=\"CONTENT_TYPE=application/pdf\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[23]=\"DEVICE_URI=usb://HP/LaserJet%20Professional%20P1102?serial=000000000Q87FWBPPR1a\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[24]=\"PRINTER_INFO=HP LaserJet Professional P1102\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[25]=\"PRINTER_LOCATION=Gargantua\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[26]=\"PRINTER=HP_LaserJet_Professional_P1102_su_Gargantua\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[27]=\"PRINTER_STATE_REASONS=none\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[28]=\"CUPS_FILETYPE=document\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[29]=\"FINAL_CONTENT_TYPE=application/vnd.cups-pdf\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] envp[30]=\"AUTH_I****\"\r\nI [02/Sep/2018:06:44:08 +0200] [Job 554] Started filter /usr/lib/cups/filter/pdftopdf (PID 2253)\r\nI [02/Sep/2018:06:44:08 +0200] [Job 554] Started filter /usr/lib/cups/filter/foomatic-rip (PID 2254)\r\nI [02/Sep/2018:06:44:08 +0200] [Job 554] Started backend /usr/lib/cups/backend/usb (PID 2255)\r\nD [02/Sep/2018:06:44:08 +0200] Discarding unused job-state-changed event...\r\nD [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.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Content-Length: 171\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] cupsdSendHeader: code=200, type=\"application/ipp\", auth_type=0\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] con->http=0x555ab3182c80\r\nD [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\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] bytes=0, http_state=0, data_remaining=171\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Flushing write buffer.\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] New state is HTTP_STATE_WAITING\r\nD [02/Sep/2018:06:44:08 +0200] [Client 1] Waiting for request.\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Printing jobs and dirty files\", busy=\"Active clients and dirty files\"\r\nD [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.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Calling FindDeviceById(cups-HP_LaserJet_Professional_P1102_su_Gargantua)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] PAGE: 1 1\r\nD [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Printing jobs and dirty files\", busy=\"Printing jobs and dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Printing jobs and dirty files\", busy=\"Printing jobs and dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] Discarding unused job-progress event...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Found device /org/freedesktop/ColorManager/devices/cups_HP_LaserJet_Professional_P1102_su_Gargantua\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Calling org.freedesktop.ColorManager.Device.Get(ProfilingInhibitors)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] \\'CM Color Calibration\\' Mode in SPOOLER-LESS: Off\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Getting input from file\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] foomatic-rip version 1.21.1 running...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Parsing PPD file ...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option ColorSpace\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option PageSize\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Quality\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Resolution\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option ImageableArea\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option PaperDimension\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option InputSlot\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option MediaType\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] PID 2253 (/usr/lib/cups/filter/pdftopdf) exited with no errors.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Density\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Copies\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Loading USB quirks from \\\"/usr/share/cups/usb\\\".\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Loaded 89 quirks.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Printing on printer with URI: usb://HP/LaserJet%20Professional%20P1102?serial=000000000Q87FWBPPR1a\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option halftone\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option NupOrient\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option NupPages\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Added option Font\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Parameter Summary\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] -----------------\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Spooler: cups\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Printer: HP_LaserJet_Professional_P1102_su_Gargantua\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Shell: /bin/bash\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] PPD file: /etc/cups/ppd/HP_LaserJet_Professional_P1102_su_Gargantua.ppd\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] ATTR file:\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Printer model: HP LaserJet Pro P1102 Foomatic/foo2zjs-z2 (recommended)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Job title: provastampa.odt\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] File(s) to be printed:\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] <STDIN>\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Ghostscript extra search path (\\'GS_LIB\\'): /usr/share/cups/fonts\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Printing system options:\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \\'job-uuid=urn:uuid:d6e5565b-6600-3187-7334-81a19301f117\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option job-uuid=urn:uuid:d6e5565b-6600-3187-7334-81a19301f117.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \\'job-originating-host-name=localhost\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option job-originating-host-name=localhost.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \\'date-time-at-creation=\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option date-time-at-creation=.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \\'date-time-at-processing=\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option date-time-at-processing=.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \\'time-at-creation=1535863448\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option time-at-creation=1535863448.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \\'time-at-processing=1535863448\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option time-at-processing=1535863448.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \\'document-name-supplied=DhRNfu\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Unknown option document-name-supplied=DhRNfu.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] CM Color Calibration Mode in CUPS: Off\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Options from the PPD file:\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \\'InputSlot=Auto\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Pondering option \\'PageSize=Letter\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] ================================================\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] File: <STDIN>\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] ================================================\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Filetype: PDF\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Neither PDF renderer command line nor Ghostscript-based renderer command line found\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Driver does not understand PDF input, converting to PostScript\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Storing temporary files in /var/spool/cups/tmp\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] libusb_get_device_list=6\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Starting process \\\"pdf-to-ps\\\" (generation 1)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] STATE: +connecting-to-device\r\nD [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Dirty files\", busy=\"Printing jobs and dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] Discarding unused printer-state-changed event...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] STATE: -connecting-to-device\r\nD [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Printing jobs and dirty files\", busy=\"Dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] Discarding unused printer-state-changed event...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Device protocol: 2\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Printer does not like usblp kernel module to be re-attached after job\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Invio dei dati alla stampante.\r\nD [02/Sep/2018:06:44:08 +0200] cupsdMarkDirty(---J-)\r\nD [02/Sep/2018:06:44:08 +0200] cupsdSetBusyState: newbusy=\"Printing jobs and dirty files\", busy=\"Printing jobs and dirty files\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Set job-printer-state-message to \"Invio dei dati alla stampante.\", current level=INFO\r\nD [02/Sep/2018:06:44:08 +0200] Discarding unused job-progress event...\r\nD [02/Sep/2018:06:44:08 +0200] Discarding unused printer-state-changed event...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Printer make and model: HP HP LaserJet Professional P1102\r\nD [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\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] No resolution information found in the PPD file.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Using image rendering resolution 300 dpi\r\nD [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\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Started filter gs (PID 2261)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Started filter pstops (PID 2262)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Page = 612x792; 11,11 to 601,781\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] slow_collate=0, slow_duplex=0, slow_order=0\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Before copy_comments - %!PS-Adobe-3.0\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] %!PS-Adobe-3.0\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] %%BoundingBox: 0 0 612 792\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] %%HiResBoundingBox: 0 0 612.00 792.00\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] %%Creator: GPL Ghostscript 923 (ps2write)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] %%LanguageLevel: 2\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] %%CreationDate: D:20180902064408+02\\'00\\'\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] %%Pages: 1\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] %%EndComments\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Before copy_prolog - %%BeginProlog\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Filetype: PostScript\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Reading PostScript input ...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] --> This document is DSC-conforming!\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Found %RBINumCopies: 1\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] -----------\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Found: %%BeginProlog\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Inserting option code into \\\"Prolog\\\" section.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Flushing FIFO.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] \\\"Prolog\\\" section is missing, inserting it.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Inserting option code into \\\"Prolog\\\" section.\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Starting renderer with command: \\\"foo2zjs-wrapper -z2 -P -L0     -r1200x600 -p1 -T3 -m1 -s7   -n1 \\\"\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Starting process \\\"kid3\\\" (generation 1)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Closing renderer\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Starting process \\\"kid4\\\" (generation 2)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Starting process \\\"renderer\\\" (generation 2)\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] JCL: \\033%-12345X@PJL\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] <job data>\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Not a pbm file!\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] renderer exited with status 0\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Read 312 bytes of print data...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Wrote 312 bytes of print data...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] kid4 exited with status 0\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] kid3 finished\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] kid3 exited with status 0\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Read 56 bytes of back-channel data...\r\nD [02/Sep/2018:06:44:08 +0200] [Job 554] Read 59 bytes of back-channel data...\r\nD [02/Sep/2018:06:44:38 +0200] [Job 554] Read 58 bytes of back-channel data...\r\nI [02/Sep/2018:06:44:38 +0200] Saving job.cache...\r\nD [02/Sep/2018:06:44:38 +0200] cupsdSetBusyState: newbusy=\"Printing jobs\", busy=\"Printing jobs and dirty files\"\r\nD [02/Sep/2018:06:44:38 +0200] Report: clients=1\r\nD [02/Sep/2018:06:44:38 +0200] Report: jobs=16\r\nD [02/Sep/2018:06:44:38 +0200] Report: jobs-active=1\r\nD [02/Sep/2018:06:44:38 +0200] Report: printers=1\r\nD [02/Sep/2018:06:44:38 +0200] Report: stringpool-string-count=17621\r\nD [02/Sep/2018:06:44:38 +0200] Report: stringpool-alloc-bytes=11496\r\nD [02/Sep/2018:06:44:38 +0200] Report: stringpool-total-bytes=319600\r\nD [02/Sep/2018:06:45:08 +0200] [Job 554] Read 58 bytes of back-channel data...\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/OpenPrinting/cups-filters/issues/comments/420478205","html_url":"https://github.com/OpenPrinting/cups-filters/issues/58#issuecomment-420478205","issue_url":"https://api.github.com/repos/OpenPrinting/cups-filters/issues/58","id":420478205,"node_id":"MDEyOklzc3VlQ29tbWVudDQyMDQ3ODIwNQ==","user":{"login":"severach","id":7297892,"node_id":"MDQ6VXNlcjcyOTc4OTI=","avatar_url":"https://avatars0.githubusercontent.com/u/7297892?v=4","gravatar_id":"","url":"https://api.github.com/users/severach","html_url":"https://github.com/severach","followers_url":"https://api.github.com/users/severach/followers","following_url":"https://api.github.com/users/severach/following{/other_user}","gists_url":"https://api.github.com/users/severach/gists{/gist_id}","starred_url":"https://api.github.com/users/severach/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/severach/subscriptions","organizations_url":"https://api.github.com/users/severach/orgs","repos_url":"https://api.github.com/users/severach/repos","events_url":"https://api.github.com/users/severach/events{/privacy}","received_events_url":"https://api.github.com/users/severach/received_events","type":"User","site_admin":false},"created_at":"2018-09-12T01:14:51Z","updated_at":"2018-09-12T01:14:51Z","author_association":"NONE","body":"    libio/fileops.c\r\n    libio/oldfileops.c\r\n    libio/wfileops.c\r\n\r\nI trimmed the diff to just these 3 files and compiled glib with the reversed patch. Ricoh and Savin print fine.\r\n"}}
{"actor":{"display_login":"severach"}}