You are not logged in.

#1 2016-07-30 04:33:47

vgt
Member
Registered: 2015-02-26
Posts: 8

CUPS: printing jobs are shown completed yet nothing happens.

Here is some basic information:

Description:    HP LaserJet 1020
Location:    Home
Driver:    HP LaserJet 1020 Foomatic/foo2zjs-z1 (recommended) (grayscale)
Connection:    usb://HP/LaserJet%201020?serial=FN1FD6Q
Defaults:    job-sheets=none, none media=iso_a4_210x297mm sides=one-sided

It can print some files but when it comes to other files, the web ui shows that the jobs are complete with no error message, but nothing happens.
How can I fix it?

edit 1:
Thanks for @AndyRTR, I checked the log on debug level, the logs are list below:

D [30/Jul/2016:23:06:39 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:39 +0800] Report: clients=1
D [30/Jul/2016:23:06:39 +0800] Report: jobs=10
D [30/Jul/2016:23:06:39 +0800] Report: jobs-active=0
D [30/Jul/2016:23:06:39 +0800] Report: printers=1
D [30/Jul/2016:23:06:39 +0800] Report: stringpool-string-count=13477
D [30/Jul/2016:23:06:39 +0800] Report: stringpool-alloc-bytes=7880
D [30/Jul/2016:23:06:39 +0800] Report: stringpool-total-bytes=244112
D [30/Jul/2016:23:06:39 +0800] [Client 33] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:39 +0800] [Client 33] Waiting for request.
D [30/Jul/2016:23:06:39 +0800] [Client 33] POST / HTTP/1.1
D [30/Jul/2016:23:06:39 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=200
D [30/Jul/2016:23:06:39 +0800] [Client 33] No authentication data provided.
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 33] 2.0 CUPS-Get-Printers 37
D [30/Jul/2016:23:06:39 +0800] CUPS-Get-Printers
D [30/Jul/2016:23:06:39 +0800] [Client 33] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [30/Jul/2016:23:06:39 +0800] [Client 33] Content-Length: 1183
D [30/Jul/2016:23:06:39 +0800] [Client 33] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:39 +0800] [Client 33] con->http=0x55b2212fba40
D [30/Jul/2016:23:06:39 +0800] [Client 33] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1183, response=0x55b221300160(IPP_STATE_DATA), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:39 +0800] [Client 33] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:39 +0800] [Client 33] bytes=0, http_state=0, data_remaining=1183
D [30/Jul/2016:23:06:39 +0800] [Client 33] Flushing write buffer.
D [30/Jul/2016:23:06:39 +0800] [Client 33] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:39 +0800] [Client 33] Waiting for request.
D [30/Jul/2016:23:06:39 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:39 +0800] [Client 33] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:39 +0800] [Client 33] Closing connection.
D [30/Jul/2016:23:06:39 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:39 +0800] [Client 34] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:39 +0800] [Client 34] Waiting for request.
D [30/Jul/2016:23:06:39 +0800] [Client 34] POST / HTTP/1.1
D [30/Jul/2016:23:06:39 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:39 +0800] [Client 34] Read: status=200
D [30/Jul/2016:23:06:39 +0800] [Client 34] No authentication data provided.
D [30/Jul/2016:23:06:39 +0800] [Client 34] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 34] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 34] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 34] Read: status=100
D [30/Jul/2016:23:06:39 +0800] [Client 34] 2.0 CUPS-Get-Default 38
D [30/Jul/2016:23:06:39 +0800] CUPS-Get-Default
D [30/Jul/2016:23:06:39 +0800] CUPS-Get-Default client-error-not-found: No default printer.
D [30/Jul/2016:23:06:39 +0800] [Client 34] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [30/Jul/2016:23:06:39 +0800] [Client 34] Content-Length: 113
D [30/Jul/2016:23:06:39 +0800] [Client 34] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:39 +0800] [Client 34] con->http=0x55b2212fba40
D [30/Jul/2016:23:06:39 +0800] [Client 34] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x55b221304650(IPP_STATE_DATA), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:39 +0800] [Client 34] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:39 +0800] [Client 34] bytes=0, http_state=0, data_remaining=113
D [30/Jul/2016:23:06:39 +0800] [Client 34] Flushing write buffer.
D [30/Jul/2016:23:06:39 +0800] [Client 34] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:39 +0800] [Client 34] Waiting for request.
D [30/Jul/2016:23:06:39 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:40 +0800] [Client 34] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:40 +0800] [Client 34] Closing connection.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 35] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:40 +0800] [Client 35] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] [Client 35] POST / HTTP/1.1
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 35] Read: status=200
D [30/Jul/2016:23:06:40 +0800] [Client 35] No authentication data provided.
D [30/Jul/2016:23:06:40 +0800] [Client 35] 2.0 Get-Printer-Attributes 39
D [30/Jul/2016:23:06:40 +0800] Get-Printer-Attributes ipp://localhost:631/printers/hpljet1020
D [30/Jul/2016:23:06:40 +0800] [Client 35] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/hpljet1020) from localhost
D [30/Jul/2016:23:06:40 +0800] [Client 35] Content-Length: 1183
D [30/Jul/2016:23:06:40 +0800] [Client 35] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:40 +0800] [Client 35] con->http=0x55b2212fba40
D [30/Jul/2016:23:06:40 +0800] [Client 35] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1183, response=0x55b221300130(IPP_STATE_DATA), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:40 +0800] [Client 35] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:40 +0800] [Client 35] bytes=0, http_state=0, data_remaining=1183
D [30/Jul/2016:23:06:40 +0800] [Client 35] Flushing write buffer.
D [30/Jul/2016:23:06:40 +0800] [Client 35] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:40 +0800] [Client 35] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:40 +0800] [Client 35] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:40 +0800] [Client 35] Closing connection.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 36] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:40 +0800] [Client 36] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] [Client 36] POST / HTTP/1.1
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=200
D [30/Jul/2016:23:06:40 +0800] [Client 36] No authentication data provided.
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 36] 2.0 Get-Printer-Attributes 40
D [30/Jul/2016:23:06:40 +0800] Get-Printer-Attributes ipp://localhost:631/printers/hpljet1020
D [30/Jul/2016:23:06:40 +0800] [Client 36] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/hpljet1020) from localhost
D [30/Jul/2016:23:06:40 +0800] [Client 36] Content-Length: 1183
D [30/Jul/2016:23:06:40 +0800] [Client 36] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:40 +0800] [Client 36] con->http=0x55b2212fba40
D [30/Jul/2016:23:06:40 +0800] [Client 36] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1183, response=0x55b221300130(IPP_STATE_DATA), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:40 +0800] [Client 36] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:40 +0800] [Client 36] bytes=0, http_state=0, data_remaining=1183
D [30/Jul/2016:23:06:40 +0800] [Client 36] Flushing write buffer.
D [30/Jul/2016:23:06:40 +0800] [Client 36] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:40 +0800] [Client 36] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:40 +0800] [Client 36] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:40 +0800] [Client 36] Closing connection.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 37] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:40 +0800] [Client 37] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] [Client 37] POST /printers/hpljet1020 HTTP/1.1
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 37] Read: status=200
D [30/Jul/2016:23:06:40 +0800] [Client 37] No authentication data provided.
D [30/Jul/2016:23:06:40 +0800] [Client 37] 2.0 Get-Printer-Attributes 41
D [30/Jul/2016:23:06:40 +0800] Get-Printer-Attributes ipp://localhost/printers/hpljet1020
D [30/Jul/2016:23:06:40 +0800] [Client 37] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/hpljet1020) from localhost
D [30/Jul/2016:23:06:40 +0800] [Client 37] Content-Length: 212
D [30/Jul/2016:23:06:40 +0800] [Client 37] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:40 +0800] [Client 37] con->http=0x55b2212fba40
D [30/Jul/2016:23:06:40 +0800] [Client 37] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=212, response=0x55b2213000f0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:40 +0800] [Client 37] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:40 +0800] [Client 37] bytes=0, http_state=0, data_remaining=212
D [30/Jul/2016:23:06:40 +0800] [Client 37] Flushing write buffer.
D [30/Jul/2016:23:06:40 +0800] [Client 37] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:40 +0800] [Client 37] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:40 +0800] [Client 38] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:40 +0800] [Client 38] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] [Client 38] GET /printers/hpljet1020.ppd HTTP/1.1
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 38] Read: status=200
D [30/Jul/2016:23:06:40 +0800] [Client 38] No authentication data provided.
D [30/Jul/2016:23:06:40 +0800] [Client 38] Processing GET /printers/hpljet1020.ppd
D [30/Jul/2016:23:06:40 +0800] [Client 38] filename="/etc/cups/ppd/hpljet1020.ppd", type=application/vnd.cups-ppd
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdSendHeader: code=200, type="application/vnd.cups-ppd", auth_type=0
D [30/Jul/2016:23:06:40 +0800] [Client 38] Sending file.
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] con->http=0x55b2212f30f0
D [30/Jul/2016:23:06:40 +0800] [Client 38] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=24309, response=(nil)(), pipe_pid=0, file=18
D [30/Jul/2016:23:06:40 +0800] [Client 38] Flushing write buffer.
D [30/Jul/2016:23:06:40 +0800] [Client 38] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:40 +0800] [Client 38] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:40 +0800] [Client 38] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:40 +0800] [Client 38] Closing connection.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 37] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:40 +0800] [Client 37] Closing connection.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 39] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:40 +0800] [Client 39] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] [Client 39] POST / HTTP/1.1
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=200
D [30/Jul/2016:23:06:40 +0800] [Client 39] No authentication data provided.
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 39] 2.0 Get-Printer-Attributes 42
D [30/Jul/2016:23:06:40 +0800] Get-Printer-Attributes ipp://localhost:631/printers/hpljet1020
D [30/Jul/2016:23:06:40 +0800] [Client 39] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/hpljet1020) from localhost
D [30/Jul/2016:23:06:40 +0800] [Client 39] Content-Length: 1183
D [30/Jul/2016:23:06:40 +0800] [Client 39] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:40 +0800] [Client 39] con->http=0x55b2212fba40
D [30/Jul/2016:23:06:40 +0800] [Client 39] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1183, response=0x55b221300130(IPP_STATE_DATA), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:40 +0800] [Client 39] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:40 +0800] [Client 39] bytes=0, http_state=0, data_remaining=1183
D [30/Jul/2016:23:06:40 +0800] [Client 39] Flushing write buffer.
D [30/Jul/2016:23:06:40 +0800] [Client 39] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:40 +0800] [Client 39] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:40 +0800] [Client 40] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:40 +0800] [Client 40] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] [Client 41] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:40 +0800] [Client 41] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] [Client 40] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:40 +0800] [Client 40] Closing connection.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 41] POST / HTTP/1.1
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=200
D [30/Jul/2016:23:06:40 +0800] [Client 41] No authentication data provided.
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] Read: status=100
D [30/Jul/2016:23:06:40 +0800] [Client 41] 2.0 CUPS-Get-Printers 1
D [30/Jul/2016:23:06:40 +0800] CUPS-Get-Printers
D [30/Jul/2016:23:06:40 +0800] [Client 41] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [30/Jul/2016:23:06:40 +0800] [Client 41] Content-Length: 860
D [30/Jul/2016:23:06:40 +0800] [Client 41] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:40 +0800] [Client 41] con->http=0x55b2212f74c0
D [30/Jul/2016:23:06:40 +0800] [Client 41] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=860, response=0x55b221300230(IPP_STATE_DATA), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:40 +0800] [Client 41] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:40 +0800] [Client 41] bytes=0, http_state=0, data_remaining=860
D [30/Jul/2016:23:06:40 +0800] [Client 41] Flushing write buffer.
D [30/Jul/2016:23:06:40 +0800] [Client 41] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:40 +0800] [Client 41] Waiting for request.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:40 +0800] [Client 41] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:40 +0800] [Client 41] Closing connection.
D [30/Jul/2016:23:06:40 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:44 +0800] [Client 42] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:44 +0800] [Client 42] Waiting for request.
D [30/Jul/2016:23:06:44 +0800] [Client 43] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:44 +0800] [Client 43] Waiting for request.
D [30/Jul/2016:23:06:44 +0800] [Client 42] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:44 +0800] [Client 42] Closing connection.
D [30/Jul/2016:23:06:44 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:44 +0800] [Client 43] POST / HTTP/1.1
D [30/Jul/2016:23:06:44 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=200
D [30/Jul/2016:23:06:44 +0800] [Client 43] No authentication data provided.
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] Read: status=100
D [30/Jul/2016:23:06:44 +0800] [Client 43] 2.0 CUPS-Get-Printers 1
D [30/Jul/2016:23:06:44 +0800] CUPS-Get-Printers
D [30/Jul/2016:23:06:44 +0800] [Client 43] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [30/Jul/2016:23:06:44 +0800] [Client 43] Content-Length: 860
D [30/Jul/2016:23:06:44 +0800] [Client 43] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:44 +0800] [Client 43] con->http=0x55b2212f74c0
D [30/Jul/2016:23:06:44 +0800] [Client 43] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=860, response=0x55b221300230(IPP_STATE_DATA), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:44 +0800] [Client 43] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:44 +0800] [Client 43] bytes=0, http_state=0, data_remaining=860
D [30/Jul/2016:23:06:44 +0800] [Client 43] Flushing write buffer.
D [30/Jul/2016:23:06:44 +0800] [Client 43] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:44 +0800] [Client 43] Waiting for request.
D [30/Jul/2016:23:06:44 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:44 +0800] [Client 43] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:44 +0800] [Client 43] Closing connection.
D [30/Jul/2016:23:06:44 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:44 +0800] [Client 44] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:44 +0800] [Client 44] Waiting for request.
D [30/Jul/2016:23:06:44 +0800] [Client 45] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:44 +0800] [Client 45] Waiting for request.
D [30/Jul/2016:23:06:44 +0800] [Client 44] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:44 +0800] [Client 44] Closing connection.
D [30/Jul/2016:23:06:44 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:44 +0800] [Client 45] POST / HTTP/1.1
D [30/Jul/2016:23:06:44 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:44 +0800] [Client 45] Read: status=200
D [30/Jul/2016:23:06:44 +0800] [Client 45] No authentication data provided.
D [30/Jul/2016:23:06:44 +0800] [Client 45] 2.0 CUPS-Get-Printers 1
D [30/Jul/2016:23:06:44 +0800] CUPS-Get-Printers
D [30/Jul/2016:23:06:44 +0800] [Client 45] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [30/Jul/2016:23:06:44 +0800] [Client 45] Content-Length: 860
D [30/Jul/2016:23:06:44 +0800] [Client 45] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:44 +0800] [Client 45] con->http=0x55b2212f74c0
D [30/Jul/2016:23:06:44 +0800] [Client 45] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=860, response=0x55b221300230(IPP_STATE_DATA), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:44 +0800] [Client 45] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:44 +0800] [Client 45] bytes=0, http_state=0, data_remaining=860
D [30/Jul/2016:23:06:44 +0800] [Client 45] Flushing write buffer.
D [30/Jul/2016:23:06:44 +0800] [Client 45] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:44 +0800] [Client 45] Waiting for request.
D [30/Jul/2016:23:06:44 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [30/Jul/2016:23:06:44 +0800] [Client 45] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:44 +0800] [Client 45] Closing connection.
D [30/Jul/2016:23:06:44 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:06:45 +0800] [Client 46] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:45 +0800] [Client 46] Waiting for request.
D [30/Jul/2016:23:06:45 +0800] [Client 47] Accepted from localhost (Domain)
D [30/Jul/2016:23:06:45 +0800] [Client 47] Waiting for request.
D [30/Jul/2016:23:06:45 +0800] [Client 47] POST /printers/hpljet1020 HTTP/1.1
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=200
D [30/Jul/2016:23:06:45 +0800] [Client 47] No authentication data provided.
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] 2.1 Print-Job 1
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] [Client 47] Read: status=100
D [30/Jul/2016:23:06:45 +0800] Print-Job ipp://localhost:631/printers/hpljet1020
D [30/Jul/2016:23:06:45 +0800] [Job ???] Auto-typing file...
I [30/Jul/2016:23:06:45 +0800] [Job ???] Request file type is application/pdf.
D [30/Jul/2016:23:06:45 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [30/Jul/2016:23:06:45 +0800] add_job: requesting-user-name="dozo"
D [30/Jul/2016:23:06:45 +0800] Adding default job-sheets values "none,none"...
I [30/Jul/2016:23:06:45 +0800] [Job 77] Adding start banner page "none".
D [30/Jul/2016:23:06:45 +0800] Discarding unused job-created event...
D [30/Jul/2016:23:06:45 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [30/Jul/2016:23:06:45 +0800] [Job 77] Adding end banner page "none".
I [30/Jul/2016:23:06:45 +0800] [Job 77] File of type application/pdf queued by "dozo".
D [30/Jul/2016:23:06:45 +0800] [Job 77] hold_until=0
I [30/Jul/2016:23:06:45 +0800] [Job 77] Queued on "hpljet1020" by "dozo".
D [30/Jul/2016:23:06:45 +0800] [Job 77] time-at-processing=1469891205
D [30/Jul/2016:23:06:45 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [30/Jul/2016:23:06:45 +0800] Discarding unused printer-state-changed event...
D [30/Jul/2016:23:06:45 +0800] [Job 77] 3 filters for job:
D [30/Jul/2016:23:06:45 +0800] [Job 77] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [30/Jul/2016:23:06:45 +0800] [Job 77] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100)
D [30/Jul/2016:23:06:45 +0800] [Job 77] foomatic-rip (application/vnd.cups-postscript to printer/hpljet1020, cost 0)
D [30/Jul/2016:23:06:45 +0800] [Job 77] job-sheets=none,none
D [30/Jul/2016:23:06:45 +0800] [Job 77] argv[0]="hpljet1020"
D [30/Jul/2016:23:06:45 +0800] [Job 77] argv[1]="77"
D [30/Jul/2016:23:06:45 +0800] [Job 77] argv[2]="dozo"
D [30/Jul/2016:23:06:45 +0800] [Job 77] argv[3]="ACFrOgClCvhbgqnf3MIb9ks4FQ2WgtLT-YCSos9...bBHFeIX9_UD7uwgNtWVPE272vdUp0z_7ocgKk="
D [30/Jul/2016:23:06:45 +0800] [Job 77] argv[4]="1"
D [30/Jul/2016:23:06:45 +0800] [Job 77] argv[5]="PageSize=A4 Collate ColorModel=Grayscale Duplex=None job-uuid=urn:uuid:67713b34-d00b-32d7-73a5-3678c4eceda4 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1469891205 time-at-processing=1469891205"
D [30/Jul/2016:23:06:45 +0800] [Job 77] argv[6]="/var/spool/cups/d00077-001"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[7]="CUPS_STATEDIR=/run/cups"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[8]="HOME=/var/spool/cups/tmp"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[10]="SERVER_ADMIN=root@markSeven"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[11]="SOFTWARE=CUPS/2.1.4"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[13]="USER=root"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[14]="CUPS_MAX_MESSAGE=2047"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[17]="IPP_PORT=631"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[18]="CHARSET=utf-8"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[19]="LANG=en_US.UTF-8"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[20]="PPD=/etc/cups/ppd/hpljet1020.ppd"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[21]="RIP_MAX_CACHE=128m"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[22]="CONTENT_TYPE=application/pdf"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[23]="DEVICE_URI=usb://HP/LaserJet%201020?serial=FN1FD6Q"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[24]="PRINTER_INFO=HP LaserJet 1020"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[25]="PRINTER_LOCATION=Home"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[26]="PRINTER=hpljet1020"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[27]="PRINTER_STATE_REASONS=none"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[28]="CUPS_FILETYPE=document"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
D [30/Jul/2016:23:06:45 +0800] [Job 77] envp[30]="AUTH_I****"
I [30/Jul/2016:23:06:45 +0800] [Job 77] Started filter /usr/lib/cups/filter/pdftopdf (PID 10047)
I [30/Jul/2016:23:06:45 +0800] [Job 77] Started filter /usr/lib/cups/filter/pdftops (PID 10048)
I [30/Jul/2016:23:06:45 +0800] [Job 77] Started filter /usr/lib/cups/filter/foomatic-rip (PID 10049)
I [30/Jul/2016:23:06:45 +0800] [Job 77] Started backend /usr/lib/cups/backend/usb (PID 10050)
D [30/Jul/2016:23:06:45 +0800] Discarding unused job-state-changed event...
D [30/Jul/2016:23:06:45 +0800] [Client 47] Returning IPP successful-ok for Print-Job (ipp://localhost:631/printers/hpljet1020) from localhost
D [30/Jul/2016:23:06:45 +0800] [Client 47] Content-Length: 192
D [30/Jul/2016:23:06:45 +0800] [Client 47] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [30/Jul/2016:23:06:45 +0800] [Client 47] con->http=0x55b2212f74c0
D [30/Jul/2016:23:06:45 +0800] [Client 47] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=192, response=0x55b221303d10(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [30/Jul/2016:23:06:45 +0800] [Client 47] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [30/Jul/2016:23:06:45 +0800] [Client 47] bytes=0, http_state=0, data_remaining=192
D [30/Jul/2016:23:06:45 +0800] [Client 47] Flushing write buffer.
D [30/Jul/2016:23:06:45 +0800] [Client 47] New state is HTTP_STATE_WAITING
D [30/Jul/2016:23:06:45 +0800] [Client 47] Waiting for request.
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [30/Jul/2016:23:06:45 +0800] [Client 47] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [30/Jul/2016:23:06:45 +0800] [Client 47] Closing connection.
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [30/Jul/2016:23:06:45 +0800] [Job 77] pdftops - copying to temp print file \"/var/spool/cups/tmp/0274057a54cba\"
D [30/Jul/2016:23:06:45 +0800] [Job 77] pdftopdf: Last filter determined by the PPD: foomatic-rip; FINAL_CONTENT_TYPE: application/vnd.cups-postscript => pdftopdf will log pages in page_log.
D [30/Jul/2016:23:06:45 +0800] [Job 77] PAGE: 1 1
D [30/Jul/2016:23:06:45 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [30/Jul/2016:23:06:45 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [30/Jul/2016:23:06:45 +0800] Discarding unused job-progress event...
D [30/Jul/2016:23:06:45 +0800] [Job 77] Calling FindDeviceById(cups-hpljet1020)
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found device /org/freedesktop/ColorManager/devices/cups_hpljet1020
D [30/Jul/2016:23:06:45 +0800] [Job 77] Calling org.freedesktop.ColorManager.Device.Get(ProfilingInhibitors)
D [30/Jul/2016:23:06:45 +0800] [Job 77] \'CM Color Calibration\' Mode in SPOOLER-LESS: Off
D [30/Jul/2016:23:06:45 +0800] [Job 77] Getting input from file 
D [30/Jul/2016:23:06:45 +0800] [Job 77] foomatic-rip version 1.10.0 running...
D [30/Jul/2016:23:06:45 +0800] [Job 77] Parsing PPD file ...
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option ColorSpace
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option PageSize
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option Quality
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option Resolution
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option ImageableArea
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option PaperDimension
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option InputSlot
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option MediaType
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option Density
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option Copies
D [30/Jul/2016:23:06:45 +0800] [Job 77] Loading USB quirks from \"/usr/share/cups/usb\".
D [30/Jul/2016:23:06:45 +0800] [Job 77] Loaded 79 quirks.
D [30/Jul/2016:23:06:45 +0800] [Job 77] Printing on printer with URI: usb://HP/LaserJet%201020?serial=FN1FD6Q
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option halftone
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option NupOrient
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option NupPages
D [30/Jul/2016:23:06:45 +0800] [Job 77] Added option Font
D [30/Jul/2016:23:06:45 +0800] [Job 77] Parameter Summary
D [30/Jul/2016:23:06:45 +0800] [Job 77] -----------------
D [30/Jul/2016:23:06:45 +0800] [Job 77] Spooler: cups
D [30/Jul/2016:23:06:45 +0800] [Job 77] Printer: hpljet1020
D [30/Jul/2016:23:06:45 +0800] [Job 77] Shell: /bin/bash
D [30/Jul/2016:23:06:45 +0800] [Job 77] PPD file: /etc/cups/ppd/hpljet1020.ppd
D [30/Jul/2016:23:06:45 +0800] [Job 77] ATTR file: 
D [30/Jul/2016:23:06:45 +0800] [Job 77] Printer model: HP LaserJet 1020 Foomatic/foo2zjs-z1 (recommended)
D [30/Jul/2016:23:06:45 +0800] [Job 77] Job title: ACFrOgClCvhbgqnf3MIb9ks4FQ2WgtLT-YCSos9...bBHFeIX9_UD7uwgNtWVPE272vdUp0z_7ocgKk=
D [30/Jul/2016:23:06:45 +0800] [Job 77] File(s) to be printed:
D [30/Jul/2016:23:06:45 +0800] [Job 77] <STDIN>
D [30/Jul/2016:23:06:45 +0800] [Job 77] Ghostscript extra search path (\'GS_LIB\'): /usr/share/cups/fonts
D [30/Jul/2016:23:06:45 +0800] [Job 77] Printing system options:
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'Collate\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Unknown boolean option \"Collate\".
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'ColorModel=Grayscale\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Unknown option ColorModel=Grayscale.
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'Duplex=None\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Unknown option Duplex=None.
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'job-uuid=urn:uuid:67713b34-d00b-32d7-73a5-3678c4eceda4\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Unknown option job-uuid=urn:uuid:67713b34-d00b-32d7-73a5-3678c4eceda4.
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'job-originating-host-name=localhost\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Unknown option job-originating-host-name=localhost.
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'date-time-at-creation=\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Unknown option date-time-at-creation=.
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'date-time-at-processing=\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Unknown option date-time-at-processing=.
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'time-at-creation=1469891205\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Unknown option time-at-creation=1469891205.
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'time-at-processing=1469891205\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Unknown option time-at-processing=1469891205.
D [30/Jul/2016:23:06:45 +0800] [Job 77] CM Color Calibration Mode in CUPS: Off
D [30/Jul/2016:23:06:45 +0800] [Job 77] Options from the PPD file:
D [30/Jul/2016:23:06:45 +0800] [Job 77] Pondering option \'PageSize=A4\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] ================================================
D [30/Jul/2016:23:06:45 +0800] [Job 77] File: <STDIN>
D [30/Jul/2016:23:06:45 +0800] [Job 77] ================================================
D [30/Jul/2016:23:06:45 +0800] [Job 77] Printer make and model: HP HP LaserJet 1020
D [30/Jul/2016:23:06:45 +0800] [Job 77] Switching to Poppler\'s pdftops instead of Ghostscript for old HP LaserJet (\"LaserJet <number>\", no letters before <number>) printers to work around bugs in the printer\'s PS interpreters
D [30/Jul/2016:23:06:45 +0800] [Job 77] Running command line for pstops: pstops 77 dozo ACFrOgClCvhbgqnf3MIb9ks4FQ2WgtLT-YCSos9...bBHFeIX9_UD7uwgNtWVPE272vdUp0z_7ocgKk= 1 \'PageSize=A4 ColorModel=Grayscale Duplex=None job-uuid=urn:uuid:67713b34-d00b-32d7-73a5-3678c4eceda4 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1469891205 time-at-processing=1469891205\'
D [30/Jul/2016:23:06:45 +0800] [Job 77] Using image rendering resolution 600 dpi
D [30/Jul/2016:23:06:45 +0800] [Job 77] Running command line for pdftops: pdftops -level2 -origpagesizes -nocenter -r 600 /var/spool/cups/tmp/0274057a54cba -
D [30/Jul/2016:23:06:45 +0800] [Job 77] Started filter pdftops (PID 10052)
D [30/Jul/2016:23:06:45 +0800] [Job 77] Started filter pstops (PID 10053)
D [30/Jul/2016:23:06:45 +0800] [Job 77] PID 10047 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [30/Jul/2016:23:06:45 +0800] [Job 77] libusb_get_device_list=8
D [30/Jul/2016:23:06:45 +0800] [Job 77] STATE: +connecting-to-device
D [30/Jul/2016:23:06:45 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [30/Jul/2016:23:06:45 +0800] Discarding unused printer-state-changed event...
D [30/Jul/2016:23:06:45 +0800] [Job 77] STATE: -connecting-to-device
D [30/Jul/2016:23:06:45 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [30/Jul/2016:23:06:45 +0800] [Job 77] Device protocol: 2
I [30/Jul/2016:23:06:45 +0800] [Job 77] Sending data to printer.
D [30/Jul/2016:23:06:45 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:45 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [30/Jul/2016:23:06:45 +0800] [Job 77] Set job-printer-state-message to "Sending data to printer.", current level=INFO
D [30/Jul/2016:23:06:45 +0800] [Job 77] Read 58 bytes of back-channel data...
D [30/Jul/2016:23:06:45 +0800] [Job 77] Read 58 bytes of back-channel data...
D [30/Jul/2016:23:06:45 +0800] [Job 77] Read 58 bytes of back-channel data...
D [30/Jul/2016:23:06:45 +0800] [Job 77] Read 58 bytes of back-channel data...
D [30/Jul/2016:23:06:45 +0800] [Job 77] Read 58 bytes of back-channel data...
D [30/Jul/2016:23:06:45 +0800] Discarding unused job-progress event...
D [30/Jul/2016:23:06:45 +0800] Discarding unused printer-state-changed event...
D [30/Jul/2016:23:06:45 +0800] [Job 77] Page = 595x842; 11,11 to 584,831
D [30/Jul/2016:23:06:45 +0800] [Job 77] slow_collate=0, slow_duplex=0, slow_order=0
D [30/Jul/2016:23:06:45 +0800] [Job 77] Before copy_comments - %!PS-Adobe-3.0
D [30/Jul/2016:23:06:45 +0800] [Job 77] %!PS-Adobe-3.0
D [30/Jul/2016:23:06:45 +0800] [Job 77] %Produced by poppler pdftops version: 0.42.0 (http://poppler.freedesktop.org)
D [30/Jul/2016:23:06:45 +0800] [Job 77] %%Creator: PDFium
D [30/Jul/2016:23:06:45 +0800] [Job 77] %%LanguageLevel: 2
D [30/Jul/2016:23:06:45 +0800] [Job 77] %%DocumentSuppliedResources: (atend)
D [30/Jul/2016:23:06:45 +0800] [Job 77] %%DocumentMedia: A4 595 842 0 () ()
D [30/Jul/2016:23:06:45 +0800] [Job 77] %%BoundingBox: 0 0 595 842
D [30/Jul/2016:23:06:45 +0800] [Job 77] %%Pages: 1
D [30/Jul/2016:23:06:45 +0800] [Job 77] %%EndComments
D [30/Jul/2016:23:06:45 +0800] [Job 77] Before copy_prolog - %%BeginProlog
D [30/Jul/2016:23:06:45 +0800] [Job 77] Before copy_setup - %%BeginSetup
D [30/Jul/2016:23:06:45 +0800] [Job 77] Filetype: PostScript
D [30/Jul/2016:23:06:45 +0800] [Job 77] Reading PostScript input ...
D [30/Jul/2016:23:06:45 +0800] [Job 77] --> This document is DSC-conforming!
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found %RBINumCopies: 1
D [30/Jul/2016:23:06:45 +0800] [Job 77] -----------
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginProlog
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%EndProlog
D [30/Jul/2016:23:06:45 +0800] [Job 77] -----------
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginSetup
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *Quality normal
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: Quality=normal
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: Quality=normal
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: Quality=normal
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *halftone default
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: halftone=default
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: halftone=default
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: halftone=default
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *Resolution 1200x600dpi
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: Resolution=1200x600dpi
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: Resolution=1200x600dpi
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: Resolution=1200x600dpi
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *PageSize A4
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: PageSize=A4
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: PageSize=A4
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: PageSize=A4
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *InputSlot Auto
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: InputSlot=Auto
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: InputSlot=Auto
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: InputSlot=Auto
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *MediaType Standard
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: MediaType=Standard
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: MediaType=Standard
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: MediaType=Standard
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *Density Density3
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: Density=Density3
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: Density=Density3
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: Density=Density3
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *NupOrient port
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: NupOrient=port
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: NupOrient=port
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: NupOrient=port
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *NupPages 1up
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: NupPages=1up
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: NupPages=1up
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: NupPages=1up
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %%BeginFeature: *Copies 1
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: Copies=1
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:45 +0800] [Job 77] Found: %% FoomaticRIPOptionSetting: Copies=1
D [30/Jul/2016:23:06:45 +0800] [Job 77] Option: Copies=1
D [30/Jul/2016:23:06:45 +0800] [Job 77] Setting option
D [30/Jul/2016:23:06:46 +0800] [Job 77] Before page loop - %%Page: 1 1
D [30/Jul/2016:23:06:46 +0800] [Job 77] Copying page 1...
D [30/Jul/2016:23:06:46 +0800] [Job 77] pagew = 572.3, pagel = 819.3
D [30/Jul/2016:23:06:46 +0800] [Job 77] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [30/Jul/2016:23:06:46 +0800] [Job 77] PageLeft = 11.3, PageRight = 583.7
D [30/Jul/2016:23:06:46 +0800] [Job 77] PageTop = 830.7, PageBottom = 11.3
D [30/Jul/2016:23:06:46 +0800] [Job 77] PageWidth = 595.0, PageLength = 842.0
D [30/Jul/2016:23:06:46 +0800] [Job 77] Found: %%EndSetup
D [30/Jul/2016:23:06:46 +0800] [Job 77] -----------
D [30/Jul/2016:23:06:46 +0800] [Job 77] New page: %%Page: 1 1
D [30/Jul/2016:23:06:46 +0800] [Job 77] \"Setup\" section is missing, inserting it.
D [30/Jul/2016:23:06:46 +0800] [Job 77] Found: %%BeginPageSetup
D [30/Jul/2016:23:06:46 +0800] [Job 77] Inserting option code into \"PageSetup\" section.
D [30/Jul/2016:23:06:47 +0800] [Job 77] Wrote 1 pages...
D [30/Jul/2016:23:06:47 +0800] [Job 77] PID 10052 (pdftops) exited with no errors.
D [30/Jul/2016:23:06:47 +0800] [Job 77] PID 10053 (pstops) exited with no errors.
D [30/Jul/2016:23:06:47 +0800] [Job 77] PID 10048 (/usr/lib/cups/filter/pdftops) exited with no errors.
D [30/Jul/2016:23:06:47 +0800] [Job 77] Flushing FIFO.
D [30/Jul/2016:23:06:47 +0800] [Job 77] Starting renderer with command: \"foo2zjs-wrapper -z1 -P -L0     -r1200x600 -p9 -T3 -m1 -s7   -n1 \"
D [30/Jul/2016:23:06:47 +0800] [Job 77] Starting process \"kid3\" (generation 1)
D [30/Jul/2016:23:06:47 +0800] [Job 77] Starting process \"kid4\" (generation 2)
D [30/Jul/2016:23:06:47 +0800] [Job 77] Starting process \"renderer\" (generation 2)
D [30/Jul/2016:23:06:47 +0800] [Job 77] JCL: \033%-12345X@PJL
D [30/Jul/2016:23:06:47 +0800] [Job 77] <job data> 
D [30/Jul/2016:23:06:47 +0800] [Job 77] GPL Ghostscript 9.19: Unrecoverable error, exit code 1
D [30/Jul/2016:23:06:47 +0800] [Job 77] Not a pbm file!
D [30/Jul/2016:23:06:47 +0800] [Job 77] renderer exited with status 0
D [30/Jul/2016:23:06:47 +0800] [Job 77] Read 324 bytes of print data...
D [30/Jul/2016:23:06:47 +0800] [Job 77] Wrote 324 bytes of print data...
D [30/Jul/2016:23:06:47 +0800] [Job 77] Read 56 bytes of back-channel data...
D [30/Jul/2016:23:06:47 +0800] [Job 77] kid4 exited with status 0
D [30/Jul/2016:23:06:47 +0800] [Job 77] kid3 finished
D [30/Jul/2016:23:06:47 +0800] [Job 77] Sent 324 bytes...
D [30/Jul/2016:23:06:47 +0800] [Job 77] PID 10049 (/usr/lib/cups/filter/foomatic-rip) did not catch or ignore signal 13.
D [30/Jul/2016:23:06:47 +0800] [Job 77] Waiting for read thread to exit...
D [30/Jul/2016:23:06:54 +0800] [Job 77] Read thread still active, aborting the pending read...
D [30/Jul/2016:23:06:55 +0800] [Job 77] PID 10050 (/usr/lib/cups/backend/usb) exited with no errors.
D [30/Jul/2016:23:06:55 +0800] [Job 77] time-at-completed=1469891215
D [30/Jul/2016:23:06:55 +0800] Discarding unused job-completed event...
I [30/Jul/2016:23:06:55 +0800] [Job 77] Job completed.
I [30/Jul/2016:23:06:55 +0800] Expiring subscriptions...
D [30/Jul/2016:23:06:55 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:55 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [30/Jul/2016:23:06:55 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [30/Jul/2016:23:06:55 +0800] Discarding unused printer-state-changed event...
D [30/Jul/2016:23:06:55 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:55 +0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [30/Jul/2016:23:06:55 +0800] [Job 77] Removing document files.
D [30/Jul/2016:23:06:55 +0800] cupsdMarkDirty(---J-)
D [30/Jul/2016:23:06:55 +0800] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [30/Jul/2016:23:06:56 +0800] [Job 77] Unloading...
I [30/Jul/2016:23:07:16 +0800] Saving job.cache...
D [30/Jul/2016:23:07:16 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
D [30/Jul/2016:23:08:53 +0800] cupsdAddCert: Adding certificate for PID 0
D [30/Jul/2016:23:08:53 +0800] Closing client 31 after 300 seconds of inactivity.
D [30/Jul/2016:23:08:53 +0800] [Client 31] Closing connection.
D [30/Jul/2016:23:08:53 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:08:53 +0800] Report: clients=2
D [30/Jul/2016:23:08:53 +0800] Report: jobs=11
D [30/Jul/2016:23:08:53 +0800] Report: jobs-active=0
D [30/Jul/2016:23:08:53 +0800] Report: printers=1
D [30/Jul/2016:23:08:53 +0800] Report: stringpool-string-count=13479
D [30/Jul/2016:23:08:53 +0800] Report: stringpool-alloc-bytes=7944
D [30/Jul/2016:23:08:53 +0800] Report: stringpool-total-bytes=244160
D [30/Jul/2016:23:11:41 +0800] Closing client 39 after 300 seconds of inactivity.
D [30/Jul/2016:23:11:41 +0800] [Client 39] Closing connection.
D [30/Jul/2016:23:11:41 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [30/Jul/2016:23:11:41 +0800] Report: clients=1
D [30/Jul/2016:23:11:41 +0800] Report: jobs=11
D [30/Jul/2016:23:11:41 +0800] Report: jobs-active=0
D [30/Jul/2016:23:11:41 +0800] Report: printers=1
D [30/Jul/2016:23:11:41 +0800] Report: stringpool-string-count=13477
D [30/Jul/2016:23:11:41 +0800] Report: stringpool-alloc-bytes=7880
D [30/Jul/2016:23:11:41 +0800] Report: stringpool-total-bytes=244112
D [30/Jul/2016:23:11:46 +0800] Closing client 46 after 300 seconds of inactivity.
D [30/Jul/2016:23:11:46 +0800] [Client 46] Closing connection.
D [30/Jul/2016:23:11:46 +0800] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"

There are two kinds of errors:

D [30/Jul/2016:23:06:39 +0800] [Client 33] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)

and

D [30/Jul/2016:23:06:47 +0800] [Job 77] GPL Ghostscript 9.19: Unrecoverable error, exit code 1

I think that the latter is the reason for the error. But I don't know how to dig into it.

Besides, I find that my printer works when "FileType = pdf", and doesn't work when "FileType = PostScript".

Thanks!

Last edited by vgt (2016-07-30 15:22:27)


a novice at the college of coders

Offline

#2 2016-07-30 08:34:00

AndyRTR
Developer
From: Magdeburg/Germany
Registered: 2005-10-07
Posts: 1,641

Re: CUPS: printing jobs are shown completed yet nothing happens.

Enable server debug logging to find out what's oing on.

Offline

#3 2016-07-30 15:23:36

vgt
Member
Registered: 2015-02-26
Posts: 8

Re: CUPS: printing jobs are shown completed yet nothing happens.

AndyRTR wrote:

Enable server debug logging to find out what's oing on.

Thanks, I've updated the post.


a novice at the college of coders

Offline

#4 2016-07-30 15:54:03

AndyRTR
Developer
From: Magdeburg/Germany
Registered: 2005-10-07
Posts: 1,641

Re: CUPS: printing jobs are shown completed yet nothing happens.

What driver do you use? It might help to recreate the printer queue. And you may also want to have a look at cups-filters logs (debug to file setting).

Offline

#5 2016-08-01 03:55:38

vgt
Member
Registered: 2015-02-26
Posts: 8

Re: CUPS: printing jobs are shown completed yet nothing happens.

AndyRTR wrote:

What driver do you use? It might help to recreate the printer queue. And you may also want to have a look at cups-filters logs (debug to file setting).

I use foo2zjs-z1, which is part of package foo2zjs from AUR


a novice at the college of coders

Offline

Board footer

Powered by FluxBB