[cups] Problem printing in a Ricof aficio 3025 PCL printer

Fernando V. Molina fmolina at qi.fcen.uba.ar
Tue Aug 25 07:34:40 PDT 2015


Hi Helge,

OK, the directive was ErrorLog journal; I changed the target to 
/var/log/cups/error_log, restarted cups, enabled logging and sent again 
a pdf file to print. Then I found a long (> 9700 lines) log; I am 
copying below a fragment starting from where I found the first reference 
to job 89 (the last job). I omitted the last part, which mainly consists 
of a lot of "Not busy" messages. Please tell me if you need anything 
else.

Thanks a lot for your time.


-------------------- error_log contents, from the point where lob 89 is 
first referenced
D [25/Aug/2015:11:07:57 -0300] Get-Job-Attributes 
ipp://localhost/jobs/89
D [25/Aug/2015:11:07:57 -0300] [Client 324] Returning IPP successful-ok 
for Get-Job-Attributes (ipp://localhost/jobs/89) from localhost
D [25/Aug/2015:11:07:57 -0300] [Client 324] Content-Length: 95
D [25/Aug/2015:11:07:57 -0300] [Client 324] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:07:57 -0300] [Client 324] con->http=0x7f4dace45eb0
D [25/Aug/2015:11:07:57 -0300] [Client 324] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=95, response=0x7f4dace10740(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:07:57 -0300] [Client 324] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:07:57 -0300] [Client 324] bytes=0, http_state=0, 
data_remaining=95
D [25/Aug/2015:11:07:57 -0300] [Client 324] Flushing write buffer.
D [25/Aug/2015:11:07:57 -0300] [Client 324] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:07:57 -0300] [Client 324] Waiting for request.
D [25/Aug/2015:11:07:57 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:07:57 -0300] [Client 324] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:07:57 -0300] [Client 324] Closing connection.
D [25/Aug/2015:11:07:57 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
D [25/Aug/2015:11:07:57 -0300] [Client 323] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:07:57 -0300] [Client 323] Closing connection.
D [25/Aug/2015:11:07:57 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
D [25/Aug/2015:11:07:57 -0300] [Client 325] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:07:57 -0300] [Client 325] Waiting for request.
D [25/Aug/2015:11:07:57 -0300] [Client 325] POST / HTTP/1.1
D [25/Aug/2015:11:07:57 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Dirty files"
D [25/Aug/2015:11:07:57 -0300] [Client 325] Read: status=200
D [25/Aug/2015:11:07:57 -0300] [Client 325] No authentication data 
provided.
D [25/Aug/2015:11:07:57 -0300] [Client 325] 1.1 Get-Jobs 
266/var/log/cups/error_log
D [25/Aug/2015:11:07:57 -0300] Get-Jobs ipp://localhost/printers/
D [25/Aug/2015:11:07:57 -0300] [Client 325] Returning IPP successful-ok 
for Get-Jobs (ipp://localhost/printers/) from localhost
D [25/Aug/2015:11:07:57 -0300] [Client 325] Content-Length: 217
D [25/Aug/2015:11:07:57 -0300] [Client 325] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0/var/log/cups/error_log
D [25/Aug/2015:11:07:57 -0300] [Client 325] con->http=0x7f4dace42ca0
D [25/Aug/2015:11:07:57 -0300] [Client 325] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=217, response=0x7f4dace18ca0(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:07:57 -0300] [Client 325] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:07:57 -0300] [Client 325] bytes=0, http_state=0, 
data_remaining=217
D [25/Aug/2015:11:07:57 -0300] [Client 325] Flushing write buffer.
D [25/Aug/2015:11:07:57 -0300] [Client 325] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:07:57 -0300] [Client 325] Waiting for request.
D [25/Aug/2015:11:07:57 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:07:57 -0300] [Client 325] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:07:57 -0300] [Client 325] Closing connection.
D [25/Aug/2015:11:07:57 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
D [25/Aug/2015:11:07:57 -0300] [Client 326] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:07:57 -0300] [Client 326] Waiting for request.
D [25/Aug/2015:11:07:57 -0300] [Client 326] POST / HTTP/1.1
D [25/Aug/2015:11:07:57 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Dirty files"
D [25/Aug/2015:11:07:57 -0300] [Client 326] Read: status=200
D [25/Aug/2015:11:07:57 -0300] [Client 326] No authentication data 
provided.
D [25/Aug/2015:11:07:57 -0300] [Client 326] 1.1 Get-Jobs 267
D [25/Aug/2015:11:07:57 -0300] Get-Jobs ipp://localhost/printers/
D [25/Aug/2015:11:07:57 -0300] [Client 326] Returning IPP successful-ok 
for Get-Jobs (ipp://localhost/printers/) from localhost
D [25/Aug/2015:11:07:57 -0300] [Client 326] Content-Length: 75
D [25/Aug/2015:11:07:57 -0300] [Client 326] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:07:57 -0300] [Client 326] con->http=0x7f4dace42ca0
D [25/Aug/2015:11:07:57 -0300] [Client 326] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=75, response=0x7f4dace5a750(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:07:57 -0300] [Client 326] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:07:57 -0300] [Client 326] bytes=0, http_state=0, 
data_remaining=75
D [25/Aug/2015:11:07:57 -0300] [Client 326] Flushing write buffer.
D [25/Aug/2015:11:07:57 -0300] [Client 326] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:07:57 -0300] [Client 326] Waiting for request.
D [25/Aug/2015:11:07:57 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:07:57 -0300] [Client 326] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:07:57 -0300] [Client 326] Closing connection.
D [25/Aug/2015:11:07:57 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
D [25/Aug/2015:11:07:58 -0300] [Client 327] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:07:58 -0300] [Client 327] Waiting for request.
D [25/Aug/2015:11:07:58 -0300] [Client 327] POST / HTTP/1.1
D [25/Aug/2015:11:07:58 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Dirty files"
D [25/Aug/2015:11:07:58 -0300] [Client 327] Read: status=200
D [25/Aug/2015:11:07:58 -0300] [Client 327] No authentication data 
provided.
D [25/Aug/2015:11:07:58 -0300] [Client 327] 1.1 Get-Jobs 268
D [25/Aug/2015:11:07:58 -0300] Get-Jobs ipp://localhost/printers/
D [25/Aug/2015:11:07:58 -0300] [Client 327] Returning IPP successful-ok 
for Get-Jobs (ipp://localhost/printers/) from localhost
D [25/Aug/2015:11:07:58 -0300] [Client 327] Content-Length: 75
D [25/Aug/2015:11:07:58 -0300] [Client 327] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:07:58 -0300] [Client 327] con->http=0x7f4dace42ca0
D [25/Aug/2015:11:07:58 -0300] [Client 327] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=75, response=0x7f4dace18ca0(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:07:58 -0300] [Client 327] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:07:58 -0300] [Client 327] bytes=0, http_state=0, 
data_remaining=75
D [25/Aug/2015:11:07:58 -0300] [Client 327] Flushing write buffer.
D [25/Aug/2015:11:07:58 -0300] [Client 327] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:07:58 -0300] [Client 327] Waiting for request.
D [25/Aug/2015:11:07:58 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:07:58 -0300] [Client 327] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:07:58 -0300] [Client 327] Closing connection.
D [25/Aug/2015:11:07:58 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
D [25/Aug/2015:11:07:58 -0300] [Client 328] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:07:58 -0300] [Client 328] Waiting for request.
D [25/Aug/2015:11:07:58 -0300] [Client 328] POST / HTTP/1.1
D [25/Aug/2015:11:07:58 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Dirty files"
D [25/Aug/2015:11:07:58 -0300] [Client 328] Read: status=200
D [25/Aug/2015:11:07:58 -0300] [Client 328] No authentication data 
provided.
D [25/Aug/2015:11:07:58 -0300] [Client 328] 1.1 Get-Notifications 269
D [25/Aug/2015:11:07:58 -0300] Get-Notifications /
D [25/Aug/2015:11:07:58 -0300] cupsdIsAuthorized: 
requesting-user-name="fernando"
D [25/Aug/2015:11:07:58 -0300] [Client 328] Returning IPP successful-ok 
for Get-Notifications (/) from localhost
D [25/Aug/2015:11:07:58 -0300] [Client 328] Content-Length: 127
D [25/Aug/2015:11:07:58 -0300] [Client 328] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:07:58 -0300] [Client 328] con->http=0x7f4dace42ca0
D [25/Aug/2015:11:07:58 -0300] [Client 328] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=127, response=0x7f4dace169f0(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:07:58 -0300] [Client 328] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:07:58 -0300] [Client 328] bytes=0, http_state=0, 
data_remaining=127
D [25/Aug/2015:11:07:58 -0300] [Client 328] Flushing write buffer.
D [25/Aug/2015:11:07:58 -0300] [Client 328] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:07:58 -0300] [Client 328] Waiting for request.
D [25/Aug/2015:11:07:58 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:07:58 -0300] [Client 328] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:07:58 -0300] [Client 328] Closing connection.
D [25/Aug/2015:11:07:58 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
D [25/Aug/2015:11:07:58 -0300] [Client 329] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:07:58 -0300] [Client 329] Waiting for request.
D [25/Aug/2015:11:07:58 -0300] [Client 329] POST / HTTP/1.1
D [25/Aug/2015:11:07:58 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Dirty files"
D [25/Aug/2015:11:07:58 -0300] [Client 329] Read: status=200
D [25/Aug/2015:11:07:58 -0300] [Client 329] No authentication data 
provided.
D [25/Aug/2015:11:07:58 -0300] [Client 329] 1.1 Get-Notifications 270
D [25/Aug/2015:11:07:58 -0300] Get-Notifications /
D [25/Aug/2015:11:07:58 -0300] cupsdIsAuthorized: 
requesting-user-name="fernando"
D [25/Aug/2015:11:07:58 -0300] [Client 329] Returning IPP successful-ok 
for Get-Notifications (/) from localhost
D [25/Aug/2015:11:07:58 -0300] [Client 329] Content-Length: 127
D [25/Aug/2015:11:07:58 -0300] [Client 329] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:07:58 -0300] [Client 329] con->http=0x7f4dace42ca0
D [25/Aug/2015:11:07:58 -0300] [Client 329] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=127, response=0x7f4dace10740(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:07:58 -0300] [Client 329] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:07:58 -0300] [Client 329] bytes=0, http_state=0, 
data_remaining=127
D [25/Aug/2015:11:07:58 -0300] [Client 329] Flushing write buffer.
D [25/Aug/2015:11:07:58 -0300] [Client 329] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:07:58 -0300] [Client 329] Waiting for request.
D [25/Aug/2015:11:07:58 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:07:58 -0300] [Client 329] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:07:58 -0300] [Client 329] Closing connection.
D [25/Aug/2015:11:07:58 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
D [25/Aug/2015:11:08:03 -0300] [Client 330] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:08:03 -0300] [Client 330] Waiting for request.
D [25/Aug/2015:11:08:03 -0300] [Client 330] POST / HTTP/1.1
D [25/Aug/2015:11:08:03 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Dirty files"
D [25/Aug/2015:11:08:03 -0300] [Client 330] Read: status=200
D [25/Aug/2015:11:08:03 -0300] [Client 330] No authentication data 
provided.
D [25/Aug/2015:11:08:03 -0300] [Client 330] 1.1 Cancel-Subscription 271
D [25/Aug/2015:11:08:03 -0300] Cancel-Subscription /
D [25/Aug/2015:11:08:03 -0300] cupsdIsAuthorized: 
requesting-user-name="fernando"
D [25/Aug/2015:11:08:03 -0300] cupsdMarkDirty(----S)
D [25/Aug/2015:11:08:03 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Active clients and dirty files"
D [25/Aug/2015:11:08:03 -0300] [Client 330] Returning IPP successful-ok 
for Cancel-Subscription (/) from localhost
D [25/Aug/2015:11:08:03 -0300] [Client 330] Content-Length: 75
D [25/Aug/2015:11:08:03 -0300] [Client 330] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:08:03 -0300] [Client 330] con->http=0x7f4dace42ca0
D [25/Aug/2015:11:08:03 -0300] [Client 330] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=75, response=0x7f4dace169f0(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:08:03 -0300] [Client 330] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:08:03 -0300] [Client 330] bytes=0, http_state=0, 
data_remaining=75
D [25/Aug/2015:11:08:03 -0300] [Client 330] Flushing write buffer.
D [25/Aug/2015:11:08:03 -0300] [Client 330] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:08:03 -0300] [Client 330] Waiting for request.
D [25/Aug/2015:11:08:03 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:08:03 -0300] [Client 330] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:08:03 -0300] [Client 330] Closing connection.
D [25/Aug/2015:11:08:03 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
D [25/Aug/2015:11:08:03 -0300] [Client 331] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:08:03 -0300] [Client 331] Waiting for request.
D [25/Aug/2015:11:08:03 -0300] [Client 331] POST / HTTP/1.1
D [25/Aug/2015:11:08:03 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Dirty files"
D [25/Aug/2015:11:08:03 -0300] [Client 331] Read: status=200
D [25/Aug/2015:11:08:03 -0300] [Client 331] No authentication data 
provided.
D [25/Aug/2015:11:08:03 -0300] [Client 331] 1.1 Cancel-Subscription 272
D [25/Aug/2015:11:08:03 -0300] Cancel-Subscription /
D [25/Aug/2015:11:08:03 -0300] cupsdIsAuthorized: 
requesting-user-name="fernando"
D [25/Aug/2015:11:08:03 -0300] cupsdMarkDirty(----S)
D [25/Aug/2015:11:08:03 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Active clients and dirty files"
D [25/Aug/2015:11:08:03 -0300] [Client 331] Returning IPP successful-ok 
for Cancel-Subscription (/) from localhost
D [25/Aug/2015:11:08:03 -0300] [Client 331] Content-Length: 75
D [25/Aug/2015:11:08:03 -0300] [Client 331] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:08:03 -0300] [Client 331] con->http=0x7f4dace42ca0
D [25/Aug/2015:11:08:03 -0300] [Client 331] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=75, response=0x7f4dace10740(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:08:03 -0300] [Client 331] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:08:03 -0300] [Client 331] bytes=0, http_state=0, 
data_remaining=75
D [25/Aug/2015:11:08:03 -0300] [Client 331] Flushing write buffer.
D [25/Aug/2015:11:08:03 -0300] [Client 331] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:08:03 -0300] [Client 331] Waiting for request.
D [25/Aug/2015:11:08:03 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:08:03 -0300] [Client 331] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:08:03 -0300] [Client 331] Closing connection.
D [25/Aug/2015:11:08:03 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
D [25/Aug/2015:11:08:05 -0300] [Client 332] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:08:05 -0300] [Client 332] Waiting for request.
D [25/Aug/2015:11:08:05 -0300] Report: clients=87
D [25/Aug/2015:11:08:05 -0300] Report: jobs=62
D [25/Aug/2015:11:08:05 -0300] Report: jobs-active=0
D [25/Aug/2015:11:08:05 -0300] Report: printers=2
D [25/Aug/2015:11:08:05 -0300] Report: stringpool-string-count=14754
D [25/Aug/2015:11:08:05 -0300] Report: stringpool-alloc-bytes=16688
D [25/Aug/2015:11:08:05 -0300] Report: stringpool-total-bytes=279136
D [25/Aug/2015:11:08:05 -0300] [Client 332] POST / HTTP/1.1
D [25/Aug/2015:11:08:05 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Dirty files"
D [25/Aug/2015:11:08:05 -0300] [Client 332] Read: status=200
D [25/Aug/2015:11:08:05 -0300] [Client 332] No authentication data 
provided.
D [25/Aug/2015:11:08:05 -0300] [Client 332] 1.1 CUPS-Get-Printers 1
D [25/Aug/2015:11:08:05 -0300] CUPS-Get-Printers
D [25/Aug/2015:11:08:05 -0300] [Client 332] Returning IPP successful-ok 
for CUPS-Get-Printers (no URI) from localhost
D [25/Aug/2015:11:08:05 -0300] [Client 332] Content-Length: 15525
D [25/Aug/2015:11:08:05 -0300] [Client 332] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:08:05 -0300] [Client 332] con->http=0x7f4dace42ca0
D [25/Aug/2015:11:08:05 -0300] [Client 332] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=15525, response=0x7f4dace169f0(IPP_STATE_DATA), 
pipe_pid=0, file=-1
D [25/Aug/2015:11:08:05 -0300] [Client 332] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:08:05 -0300] [Client 332] bytes=0, http_state=0, 
data_remaining=15525
D [25/Aug/2015:11:08:05 -0300] [Client 332] Flushing write buffer.
D [25/Aug/2015:11:08:05 -0300] [Client 332] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:08:05 -0300] [Client 332] Waiting for request.
D [25/Aug/2015:11:08:05 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:08:05 -0300] [Client 332] POST / HTTP/1.1
D [25/Aug/2015:11:08:05 -0300] cupsdSetBusyState: newbusy="Active 
clients and dirty files", busy="Dirty files"
D [25/Aug/2015:11:08:05 -0300] [Client 332] Read: status=200
D [25/Aug/2015:11:08:05 -0300] [Client 332] No authentication data 
provided.
D [25/Aug/2015:11:08:05 -0300] [Client 332] 1.1 CUPS-Get-Classes 1
D [25/Aug/2015:11:08:05 -0300] CUPS-Get-Classes
D [25/Aug/2015:11:08:05 -0300] [Client 332] Returning IPP successful-ok 
for CUPS-Get-Classes (no URI) from localhost
D [25/Aug/2015:11:08:05 -0300] [Client 332] Content-Length: 75
D [25/Aug/2015:11:08:05 -0300] [Client 332] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:08:05 -0300] [Client 332] con->http=0x7f4dace42ca0
D [25/Aug/2015:11:08:05 -0300] [Client 332] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=75, response=0x7f4dace10740(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:08:05 -0300] [Client 332] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:08:05 -0300] [Client 332] bytes=0, http_state=0, 
data_remaining=75
D [25/Aug/2015:11:08:05 -0300] [Client 332] Flushing write buffer.
D [25/Aug/2015:11:08:05 -0300] [Client 332] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:08:05 -0300] [Client 332] Waiting for request.
D [25/Aug/2015:11:08:05 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Active clients and dirty files"
D [25/Aug/2015:11:08:05 -0300] [Client 332] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:08:05 -0300] [Client 332] Closing connection.
D [25/Aug/2015:11:08:05 -0300] cupsdSetBusyState: newbusy="Dirty files", 
busy="Dirty files"
I [25/Aug/2015:11:08:16 -0300] Saving printers.conf...
I [25/Aug/2015:11:08:16 -0300] Saving job.cache...
I [25/Aug/2015:11:08:16 -0300] Saving subscriptions.conf...
D [25/Aug/2015:11:08:16 -0300] cupsdSetBusyState: newbusy="Not busy", 
busy="Dirty files"
D [25/Aug/2015:11:08:16 -0300] [Client 103] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:08:16 -0300] [Client 103] Closing connection.
D [25/Aug/2015:11:08:16 -0300] cupsdSetBusyState: newbusy="Not busy", 
busy="Not busy"
D [25/Aug/2015:11:08:58 -0300] [Job 30] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 31] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 32] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 33] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 34] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 35] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 36] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 37] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 38] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 39] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 40] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 41] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 42] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 43] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 44] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 45] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 46] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 47] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 48] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 49] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 50] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 51] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 52] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 53] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 54] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 55] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 56] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 57] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 58] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 59] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 60] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 61] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 65] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 66] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 67] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 68] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 69] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 70] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 71] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 74] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 75] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 76] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 78] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 79] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 80] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 81] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 82] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 84] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 85] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 86] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 87] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 88] Unloading...
D [25/Aug/2015:11:08:58 -0300] [Job 89] Unloading...
D [25/Aug/2015:11:09:05 -0300] [Client 333] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:09:05 -0300] [Client 333] Waiting for request.
D [25/Aug/2015:11:09:05 -0300] Report: clients=86
D [25/Aug/2015:11:09:05 -0300] Report: jobs=62
D [25/Aug/2015:11:09:05 -0300] Report: jobs-active=0
D [25/Aug/2015:11:09:05 -0300] Report: printers=2
D [25/Aug/2015:11:09:05 -0300] Report: stringpool-string-count=12172
D [25/Aug/2015:11:09:05 -0300] Report: stringpool-alloc-bytes=10512
D [25/Aug/2015:11:09:05 -0300] Report: stringpool-total-bytes=226744
D [25/Aug/2015:11:09:05 -0300] [Client 333] POST / HTTP/1.1
D [25/Aug/2015:11:09:05 -0300] cupsdSetBusyState: newbusy="Active 
clients", busy="Not busy"
D [25/Aug/2015:11:09:05 -0300] [Client 333] Read: status=200
D [25/Aug/2015:11:09:05 -0300] [Client 333] No authentication data 
provided.
D [25/Aug/2015:11:09:05 -0300] [Client 333] 1.1 CUPS-Get-Printers 1
D [25/Aug/2015:11:09:05 -0300] CUPS-Get-Printers
D [25/Aug/2015:11:09:05 -0300] [Client 333] Returning IPP successful-ok 
for CUPS-Get-Printers (no URI) from localhost
D [25/Aug/2015:11:09:05 -0300] [Client 333] Content-Length: 15525
D [25/Aug/2015:11:09:05 -0300] [Client 333] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:09:05 -0300] [Client 333] con->http=0x7f4dace1ea70
D [25/Aug/2015:11:09:05 -0300] [Client 333] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=15525, response=0x7f4dace3cfc0(IPP_STATE_DATA), 
pipe_pid=0, file=-1
D [25/Aug/2015:11:09:05 -0300] [Client 333] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:09:05 -0300] [Client 333] bytes=0, http_state=0, 
data_remaining=15525
D [25/Aug/2015:11:09:05 -0300] [Client 333] Flushing write buffer.
D [25/Aug/2015:11:09:05 -0300] [Client 333] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:09:05 -0300] [Client 333] Waiting for request.
D [25/Aug/2015:11:09:05 -0300] cupsdSetBusyState: newbusy="Not busy", 
busy="Active clients"
D [25/Aug/2015:11:09:05 -0300] [Client 333] POST / HTTP/1.1
D [25/Aug/2015:11:09:05 -0300] cupsdSetBusyState: newbusy="Active 
clients", busy="Not busy"
D [25/Aug/2015:11:09:05 -0300] [Client 333] Read: status=200
D [25/Aug/2015:11:09:05 -0300] [Client 333] No authentication data 
provided.
D [25/Aug/2015:11:09:05 -0300] [Client 333] 1.1 CUPS-Get-Classes 1
D [25/Aug/2015:11:09:05 -0300] CUPS-Get-Classes
D [25/Aug/2015:11:09:05 -0300] [Client 333] Returning IPP successful-ok 
for CUPS-Get-Classes (no URI) from localhost
D [25/Aug/2015:11:09:05 -0300] [Client 333] Content-Length: 75
D [25/Aug/2015:11:09:05 -0300] [Client 333] cupsdSendHeader: code=200, 
type="application/ipp", auth_type=0
D [25/Aug/2015:11:09:05 -0300] [Client 333] con->http=0x7f4dace1ea70
D [25/Aug/2015:11:09:05 -0300] [Client 333] cupsdWriteClient error=0, 
used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, 
data_remaining=75, response=0x7f4dace18310(IPP_STATE_DATA), pipe_pid=0, 
file=-1
D [25/Aug/2015:11:09:05 -0300] [Client 333] Writing IPP response, 
ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Aug/2015:11:09:05 -0300] [Client 333] bytes=0, http_state=0, 
data_remaining=75
D [25/Aug/2015:11:09:05 -0300] [Client 333] Flushing write buffer.
D [25/Aug/2015:11:09:05 -0300] [Client 333] New state is 
HTTP_STATE_WAITING
D [25/Aug/2015:11:09:05 -0300] [Client 333] Waiting for request.
D [25/Aug/2015:11:09:05 -0300] cupsdSetBusyState: newbusy="Not busy", 
busy="Active clients"
D [25/Aug/2015:11:09:05 -0300] [Client 333] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:09:05 -0300] [Client 333] Closing connection.
D [25/Aug/2015:11:09:05 -0300] cupsdSetBusyState: newbusy="Not busy", 
busy="Not busy"
D [25/Aug/2015:11:09:57 -0300] [Client 334] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:09:57 -0300] [Client 334] Waiting for request.
D [25/Aug/2015:11:09:57 -0300] [Client 334] PUT /admin/conf/cupsd.conf 
HTTP/1.1
D [25/Aug/2015:11:09:57 -0300] cupsdSetBusyState: newbusy="Active 
clients", busy="Not busy"
D [25/Aug/2015:11:09:57 -0300] [Client 334] Read: status=200
D [25/Aug/2015:11:09:57 -0300] [Client 334] No authentication data 
provided.
D [25/Aug/2015:11:09:57 -0300] cupsdIsAuthorized: username=""
D [25/Aug/2015:11:09:57 -0300] [Client 334] cupsdSendHeader: code=401, 
type="text/html", auth_type=0
D [25/Aug/2015:11:09:57 -0300] [Client 334] WWW-Authenticate: Basic 
realm="CUPS", trc="y"
D [25/Aug/2015:11:09:57 -0300] [Client 334] Closing connection.
D [25/Aug/2015:11:09:57 -0300] cupsdSetBusyState: newbusy="Not busy", 
busy="Active clients"
D [25/Aug/2015:11:09:57 -0300] [Client 335] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:09:57 -0300] [Client 335] Waiting for request.
D [25/Aug/2015:11:09:57 -0300] [Client 336] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:09:57 -0300] [Client 336] Waiting for request.
D [25/Aug/2015:11:09:57 -0300] [Client 335] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:09:57 -0300] [Client 335] Closing connection.
D [25/Aug/2015:11:09:57 -0300] cupsdSetBusyState: newbusy="Not busy", 
busy="Not busy"
D [25/Aug/2015:11:09:57 -0300] [Client 337] Accepted from localhost 
(Domain)
D [25/Aug/2015:11:09:57 -0300] [Client 337] Waiting for request.
D [25/Aug/2015:11:09:57 -0300] [Client 336] HTTP_STATE_WAITING Closing 
for error 32 (Broken pipe)
D [25/Aug/2015:11:09:57 -0300] [Client 336] Closing connection.
D [25/Aug/2015:11:09:57 -0300] cupsdSetBusyState: newbusy="Not busy", 
busy="Not busy"
D [25/Aug/2015:11:09:57 -0300] [Client 337] PUT /admin/conf/cupsd.conf 
HTTP/1.1
D [25/Aug/2015:11:09:57 -0300] cupsdSetBusyState: newbusy="Active 
clients", busy="Not busy"
D [25/Aug/2015:11:09:57 -0300] [Client 337] Read: status=200
D [25/Aug/2015:11:09:57 -0300] [Client 337] Authorized as root using 
PeerCred
D [25/Aug/2015:11:09:57 -0300] cupsdIsAuthorized: username="root"
D [25/Aug/2015:11:09:57 -0300] [Client 337] Read: status=100
I [25/Aug/2015:11:09:57 -0300] [Client 337] Installing config file 
"/etc/cups/cupsd.conf"...
D [25/Aug/2015:11:09:57 -0300] [Client 337] cupsdSendHeader: code=201, 
type="(null)", auth_type=0
D [25/Aug/2015:11:09:57 -0300] cupsdSetBusyState: newbusy="Not busy", 
busy="Active clients"
D [25/Aug/2015:11:09:57 -0300] [Client 7] Closing connection.




More information about the cups mailing list