You are not logged in.

#1 2017-09-21 01:30:42

ewab
Member
From: Japan
Registered: 2017-04-28
Posts: 9

[SOLVED]Canon printer stopped printing after re-installation of Arch

Somebody please help me.

I re-installed arch linux last week, since then my Canon irC2550F printer connected via network have stopped printing.

I installed cups and ghostscript, started cups service and installed cndrvcups-lb-bin package from AUR. I restarted cups service and added the printer as I did before. But the printer doesn't print anything. The printer worked flawlessly before re-installation.

CUPS web interface shows "processing since..." all the time.

Here's cups error log.

D [21/Sep/2017:09:54:41 +0900] [Client 235] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:54:41 +0900] [Client 235] Accepted from localhost (Domain)
D [21/Sep/2017:09:54:41 +0900] [Client 235] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] [Client 235] POST / HTTP/1.1
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 235] Read: status=200, state=6
D [21/Sep/2017:09:54:41 +0900] [Client 235] No authentication data provided.
D [21/Sep/2017:09:54:41 +0900] [Client 235] 2.0 Get-Printer-Attributes 1
D [21/Sep/2017:09:54:41 +0900] Get-Printer-Attributes ipp://localhost:631/printers/Canon_iR_C2550
D [21/Sep/2017:09:54:41 +0900] [Client 235] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:09:54:41 +0900] [Client 235] Content-Length: 1487
D [21/Sep/2017:09:54:41 +0900] [Client 235] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:54:41 +0900] [Client 235] con->http=0x561ef9ffe810
D [21/Sep/2017:09:54:41 +0900] [Client 235] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x561efa0079a0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:54:41 +0900] [Client 235] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:54:41 +0900] [Client 235] bytes=0, http_state=0, data_remaining=1487
D [21/Sep/2017:09:54:41 +0900] [Client 235] Flushing write buffer.
D [21/Sep/2017:09:54:41 +0900] [Client 235] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:54:41 +0900] [Client 235] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 235] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:54:41 +0900] [Client 235] Closing connection.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 236] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:54:41 +0900] [Client 236] Accepted from localhost (Domain)
D [21/Sep/2017:09:54:41 +0900] [Client 236] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] [Client 236] POST / HTTP/1.1
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 236] Read: status=200, state=6
D [21/Sep/2017:09:54:41 +0900] [Client 236] No authentication data provided.
D [21/Sep/2017:09:54:41 +0900] [Client 236] 2.0 CUPS-Get-Printers 2
D [21/Sep/2017:09:54:41 +0900] CUPS-Get-Printers
D [21/Sep/2017:09:54:41 +0900] [Client 236] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [21/Sep/2017:09:54:41 +0900] [Client 236] Content-Length: 1487
D [21/Sep/2017:09:54:41 +0900] [Client 236] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:54:41 +0900] [Client 236] con->http=0x561ef9ffe810
D [21/Sep/2017:09:54:41 +0900] [Client 236] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x561efa0079a0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:54:41 +0900] [Client 236] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:54:41 +0900] [Client 236] bytes=0, http_state=0, data_remaining=1487
D [21/Sep/2017:09:54:41 +0900] [Client 236] Flushing write buffer.
D [21/Sep/2017:09:54:41 +0900] [Client 236] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:54:41 +0900] [Client 236] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 236] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:54:41 +0900] [Client 236] Closing connection.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 237] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:54:41 +0900] [Client 237] Accepted from localhost (Domain)
D [21/Sep/2017:09:54:41 +0900] [Client 237] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] [Client 237] POST / HTTP/1.1
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 237] Read: status=200, state=6
D [21/Sep/2017:09:54:41 +0900] [Client 237] No authentication data provided.
D [21/Sep/2017:09:54:41 +0900] [Client 237] 2.0 CUPS-Get-Default 3
D [21/Sep/2017:09:54:41 +0900] CUPS-Get-Default
D [21/Sep/2017:09:54:41 +0900] CUPS-Get-Default client-error-not-found: デフォルトのプリンターはありません。
D [21/Sep/2017:09:54:41 +0900] [Client 237] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [21/Sep/2017:09:54:41 +0900] [Client 237] Content-Length: 148
D [21/Sep/2017:09:54:41 +0900] [Client 237] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:54:41 +0900] [Client 237] con->http=0x561ef9ffe810
D [21/Sep/2017:09:54:41 +0900] [Client 237] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=148, response=0x561efa005fd0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:54:41 +0900] [Client 237] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:54:41 +0900] [Client 237] bytes=0, http_state=0, data_remaining=148
D [21/Sep/2017:09:54:41 +0900] [Client 237] Flushing write buffer.
D [21/Sep/2017:09:54:41 +0900] [Client 237] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:54:41 +0900] [Client 237] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 237] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:54:41 +0900] [Client 237] Closing connection.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 238] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:54:41 +0900] [Client 238] Accepted from localhost (Domain)
D [21/Sep/2017:09:54:41 +0900] [Client 238] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] [Client 238] POST /printers/Canon_iR_C2550 HTTP/1.1
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 238] Read: status=200, state=6
D [21/Sep/2017:09:54:41 +0900] [Client 238] No authentication data provided.
D [21/Sep/2017:09:54:41 +0900] [Client 238] 2.0 Get-Printer-Attributes 4
D [21/Sep/2017:09:54:41 +0900] Get-Printer-Attributes ipp://localhost/printers/Canon_iR_C2550
D [21/Sep/2017:09:54:41 +0900] [Client 238] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:09:54:41 +0900] [Client 238] Content-Length: 169373
D [21/Sep/2017:09:54:41 +0900] [Client 238] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:54:41 +0900] [Client 238] con->http=0x561ef9ffe810
D [21/Sep/2017:09:54:41 +0900] [Client 238] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=169373, response=0x561efa014b30(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:54:41 +0900] [Client 238] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:54:41 +0900] [Client 238] bytes=0, http_state=0, data_remaining=169373
D [21/Sep/2017:09:54:41 +0900] [Client 238] Flushing write buffer.
D [21/Sep/2017:09:54:41 +0900] [Client 238] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:54:41 +0900] [Client 238] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 238] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:54:41 +0900] [Client 238] Closing connection.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 239] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:54:41 +0900] [Client 239] Accepted from localhost (Domain)
D [21/Sep/2017:09:54:41 +0900] [Client 239] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] [Client 239] POST /printers/Canon_iR_C2550 HTTP/1.1
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 239] Read: status=200, state=6
D [21/Sep/2017:09:54:41 +0900] [Client 239] No authentication data provided.
D [21/Sep/2017:09:54:41 +0900] [Client 239] 2.0 Create-Job 5
D [21/Sep/2017:09:54:41 +0900] Create-Job ipp://localhost/printers/Canon_iR_C2550
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] add_job: requesting-user-name="fukuokasoichiro"
I [21/Sep/2017:09:54:41 +0900] [Job 13] Adding start banner page "none".
D [21/Sep/2017:09:54:41 +0900] Discarding unused job-created event...
I [21/Sep/2017:09:54:41 +0900] [Job 13] Queued on "Canon_iR_C2550" by "ewab".
D [21/Sep/2017:09:54:41 +0900] [Client 239] Returning IPP successful-ok for Create-Job (ipp://localhost/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:09:54:41 +0900] [Client 239] Content-Length: 200
D [21/Sep/2017:09:54:41 +0900] [Client 239] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:54:41 +0900] [Client 239] con->http=0x561ef9ffe810
D [21/Sep/2017:09:54:41 +0900] [Client 239] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=200, response=0x561efa005fd0(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [21/Sep/2017:09:54:41 +0900] [Client 239] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:54:41 +0900] [Client 239] bytes=0, http_state=0, data_remaining=200
D [21/Sep/2017:09:54:41 +0900] [Client 239] Flushing write buffer.
D [21/Sep/2017:09:54:41 +0900] [Client 239] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:54:41 +0900] [Client 239] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 239] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:54:41 +0900] [Client 239] Closing connection.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 240] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:54:41 +0900] [Client 240] Accepted from localhost (Domain)
D [21/Sep/2017:09:54:41 +0900] [Client 240] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] [Client 240] POST /printers/Canon_iR_C2550 HTTP/1.1
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Client 240] Read: status=200, state=6
D [21/Sep/2017:09:54:41 +0900] [Client 240] No authentication data provided.
D [21/Sep/2017:09:54:41 +0900] [Client 240] 2.0 Send-Document 6
D [21/Sep/2017:09:54:41 +0900] Send-Document ipp://localhost:631/printers/Canon_iR_C2550
D [21/Sep/2017:09:54:41 +0900] cupsdIsAuthorized: requesting-user-name="ewab"
D [21/Sep/2017:09:54:41 +0900] [Job 13] Auto-typing file...
D [21/Sep/2017:09:54:41 +0900] [Job 13] Request file type is text/plain.
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [21/Sep/2017:09:54:41 +0900] [Job 13] File of type text/plain queued by "ewab".
I [21/Sep/2017:09:54:41 +0900] [Job 13] Adding end banner page "none".
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Job 13] time-at-processing=1505955281
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:54:41 +0900] [Job 13] 4 filters for job:
D [21/Sep/2017:09:54:41 +0900] [Job 13] texttopdf (text/plain to application/pdf, cost 32)
D [21/Sep/2017:09:54:41 +0900] [Job 13] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [21/Sep/2017:09:54:41 +0900] [Job 13] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100)
D [21/Sep/2017:09:54:41 +0900] [Job 13] pstoufr2cpca (application/vnd.cups-postscript to printer/Canon_iR_C2550, cost 0)
D [21/Sep/2017:09:54:41 +0900] [Job 13] job-sheets=none,none
D [21/Sep/2017:09:54:41 +0900] [Job 13] argv[0]="Canon_iR_C2550"
D [21/Sep/2017:09:54:41 +0900] [Job 13] argv[1]="13"
D [21/Sep/2017:09:54:41 +0900] [Job 13] argv[2]="ewab"
D [21/Sep/2017:09:54:41 +0900] [Job 13] argv[3]="test.txt"
D [21/Sep/2017:09:54:41 +0900] [Job 13] argv[4]="1"
D [21/Sep/2017:09:54:41 +0900] [Job 13] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:08372dd5-571d-3012-65a4-a684fea30b85 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1505955281 time-at-processing=1505955281 document-name-supplied=test.txt"
D [21/Sep/2017:09:54:41 +0900] [Job 13] argv[6]="/var/spool/cups/d00013-001"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[7]="CUPS_STATEDIR=/run/cups"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[8]="HOME=/var/spool/cups/tmp"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[10]="SERVER_ADMIN=root@archlinux"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[11]="SOFTWARE=CUPS/2.2.4"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[13]="USER=root"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[14]="CUPS_MAX_MESSAGE=2047"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[17]="IPP_PORT=631"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[18]="CHARSET=utf-8"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[19]="LANG=ja_JP.UTF-8"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[20]="PPD=/etc/cups/ppd/Canon_iR_C2550.ppd"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[21]="RIP_MAX_CACHE=128m"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[22]="CONTENT_TYPE=text/plain"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[23]="DEVICE_URI=socket://192.168.1.50"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[24]="PRINTER_INFO=Canon iR C2550 (LIPSLX)"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[25]="PRINTER_LOCATION="
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[26]="PRINTER=Canon_iR_C2550"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[27]="PRINTER_STATE_REASONS=none"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[28]="CUPS_FILETYPE=document"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
D [21/Sep/2017:09:54:41 +0900] [Job 13] envp[30]="AUTH_I****"
I [21/Sep/2017:09:54:41 +0900] [Job 13] Started filter /usr/lib/cups/filter/texttopdf (PID 14165)
I [21/Sep/2017:09:54:41 +0900] [Job 13] Started filter /usr/lib/cups/filter/pdftopdf (PID 14166)
I [21/Sep/2017:09:54:41 +0900] [Job 13] Started filter /usr/lib/cups/filter/pdftops (PID 14167)
I [21/Sep/2017:09:54:41 +0900] [Job 13] Started filter /usr/lib/cups/filter/pstoufr2cpca (PID 14168)
I [21/Sep/2017:09:54:41 +0900] [Job 13] Started backend /usr/lib/cups/backend/socket (PID 14169)
D [21/Sep/2017:09:54:41 +0900] Discarding unused job-state-changed event...
D [21/Sep/2017:09:54:41 +0900] [Client 240] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:09:54:41 +0900] [Client 240] Content-Length: 170
D [21/Sep/2017:09:54:41 +0900] [Client 240] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:54:41 +0900] [Client 240] con->http=0x561ef9ffe810
D [21/Sep/2017:09:54:41 +0900] [Client 240] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=170, response=0x561efa005450(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:54:41 +0900] [Client 240] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:54:41 +0900] [Client 240] bytes=0, http_state=0, data_remaining=170
D [21/Sep/2017:09:54:41 +0900] [Client 240] Flushing write buffer.
D [21/Sep/2017:09:54:41 +0900] [Client 240] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:54:41 +0900] [Client 240] Waiting for request.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Job 13] pstoufr2cpca start.
D [21/Sep/2017:09:54:41 +0900] [Job 13] pdftops - copying to temp print file \"/var/spool/cups/tmp/0375759cc0ede\"
D [21/Sep/2017:09:54:41 +0900] [Client 240] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:54:41 +0900] [Client 240] Closing connection.
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Job 13] pdftopdf: Last filter determined by the PPD: pstoufr2cpca; FINAL_CONTENT_TYPE: application/vnd.cups-postscript => pdftopdf will not log pages in page_log.
D [21/Sep/2017:09:54:41 +0900] [Job 13] Page = 595x842; 14,14 to 581,828
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: +connecting-to-device
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Job 13] Looking up \"192.168.1.50\"...
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -connecting-to-device
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [21/Sep/2017:09:54:41 +0900] [Job 13] 192.168.1.50=192.168.1.50
D [21/Sep/2017:09:54:41 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:54:41 +0900] [Job 13] PID 14165 (/usr/lib/cups/filter/texttopdf) exited with no errors.
D [21/Sep/2017:09:54:41 +0900] [Job 13] PID 14166 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [21/Sep/2017:09:54:41 +0900] [Job 13] Printer make and model: Canon ir c2550
D [21/Sep/2017:09:54:41 +0900] [Job 13] Running command line for pstops: pstops 13 ewab test.txt 1 \'finishings=3 job-uuid=urn:uuid:08372dd5-571d-3012-65a4-a684fea30b85 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1505955281 time-at-processing=1505955281 document-name-supplied=test.txt\'
D [21/Sep/2017:09:54:41 +0900] [Job 13] Using image rendering resolution 600 dpi
D [21/Sep/2017:09:54:41 +0900] [Job 13] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r600 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c \'save pop\' -f /var/spool/cups/tmp/0375759cc0ede
D [21/Sep/2017:09:54:41 +0900] [Job 13] Started filter gs (PID 14170)
D [21/Sep/2017:09:54:41 +0900] [Job 13] Started filter pstops (PID 14171)
D [21/Sep/2017:09:54:41 +0900] [Job 13] ATTR: marker-colors=#000000,#00FFFF,#FF00FF,#FFFF00,none
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Job 13] ATTR: marker-names=\'\"NPG-35 Black Toner\"\',\'\"NPG-35 Cyan Toner\"\',\'\"NPG-35 Magenta Toner\"\',\'\"NPG-35 Yellow Toner\"\',\'\"Waste Toner\"\'
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Job 13] ATTR: marker-types=toner,toner,toner,toner,waste-toner
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:54:41 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:54:41 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:41 +0900] [Job 13] new_supply_state=0, change_state=ffff
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -developer-low-report
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -developer-empty-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -marker-supply-low-report
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -marker-supply-empty-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -opc-near-eol-report
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -opc-life-over-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -toner-low-report
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -toner-empty-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -waste-receptacle-almost-full-report
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -waste-receptacle-full-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -cleaner-life-almost-over-report
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -cleaner-life-over-warning
D [21/Sep/2017:09:54:41 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:54:41 +0900] [Job 13] new_state=0, change_state=ffff
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -media-empty-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -door-open-report
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -media-jam-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -input-tray-missing-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -output-tray-missing-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -marker-supply-missing-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -output-area-almost-full-report
D [21/Sep/2017:09:54:41 +0900] [Job 13] STATE: -output-area-full-warning
D [21/Sep/2017:09:54:41 +0900] [Job 13] backendWaitLoop(snmp_fd=5, addr=0x5592bc897a58, side_cb=0x5592bbaa7350)
D [21/Sep/2017:09:54:41 +0900] [Job 13] Page = 595x842; 14,14 to 581,828
D [21/Sep/2017:09:54:41 +0900] [Job 13] slow_collate=0, slow_duplex=0, slow_order=0
D [21/Sep/2017:09:54:41 +0900] [Job 13] Before copy_comments - %!PS-Adobe-3.0
D [21/Sep/2017:09:54:41 +0900] [Job 13] %!PS-Adobe-3.0
D [21/Sep/2017:09:54:41 +0900] [Job 13] %%BoundingBox: 0 0 595 842
D [21/Sep/2017:09:54:41 +0900] [Job 13] %%HiResBoundingBox: 0 0 595.00 842.00
D [21/Sep/2017:09:54:41 +0900] [Job 13] %%Creator: GPL Ghostscript 921 (ps2write)
D [21/Sep/2017:09:54:41 +0900] [Job 13] %%LanguageLevel: 2
D [21/Sep/2017:09:54:41 +0900] [Job 13] %%CreationDate: D:20170921095441+09\'00\'
D [21/Sep/2017:09:54:41 +0900] [Job 13] %%Pages: 1
D [21/Sep/2017:09:54:41 +0900] [Job 13] %%EndComments
D [21/Sep/2017:09:54:41 +0900] [Job 13] Before copy_prolog - %%BeginProlog
D [21/Sep/2017:09:54:41 +0900] [Job 13] Before copy_setup - %%Page: 1 1
D [21/Sep/2017:09:54:41 +0900] [Job 13] Before page loop - %%Page: 1 1
D [21/Sep/2017:09:54:41 +0900] [Job 13] Copying page 1...
D [21/Sep/2017:09:54:41 +0900] [Job 13] pagew = 566.9, pagel = 813.5
D [21/Sep/2017:09:54:41 +0900] [Job 13] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [21/Sep/2017:09:54:41 +0900] [Job 13] PageLeft = 14.2, PageRight = 581.1
D [21/Sep/2017:09:54:41 +0900] [Job 13] PageTop = 827.8, PageBottom = 14.3
D [21/Sep/2017:09:54:41 +0900] [Job 13] PageWidth = 595.0, PageLength = 842.0
D [21/Sep/2017:09:54:41 +0900] [Job 13] Wrote 1 pages...
D [21/Sep/2017:09:54:41 +0900] [Job 13] PID 14171 (pstops) exited with no errors.
D [21/Sep/2017:09:54:41 +0900] [Job 13] PID 14170 (gs) exited with no errors.
D [21/Sep/2017:09:54:41 +0900] [Job 13] PID 14167 (/usr/lib/cups/filter/pdftops) exited with no errors.
D [21/Sep/2017:09:54:41 +0900] [Job 13] opvpOpenPrinter(410)
D [21/Sep/2017:09:54:41 +0900] [Job 13] CStubOpenPrinter(349)
D [21/Sep/2017:09:54:41 +0900] [Job 13] opvpOpenPrinter(410)
D [21/Sep/2017:09:54:41 +0900] [Job 13] CStubOpenPrinter(349)
D [21/Sep/2017:09:54:46 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:54:46 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:54:46 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:46 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:54:46 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:54:46 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:54:51 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:54:51 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:54:51 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:51 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:54:51 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:54:51 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:54:54 +0900] Closing client 36 after 300 seconds of inactivity.
D [21/Sep/2017:09:54:54 +0900] [Client 36] Closing connection.
D [21/Sep/2017:09:54:54 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [21/Sep/2017:09:54:55 +0900] Saving printers.conf...
I [21/Sep/2017:09:54:55 +0900] Saving job.cache...
D [21/Sep/2017:09:54:55 +0900] cupsdSetBusyState: newbusy="Printing jobs", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:54:56 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:54:56 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:54:56 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs"
D [21/Sep/2017:09:54:56 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:54:56 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:54:56 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:55:01 +0900] [Client 241] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:55:01 +0900] [Client 241] Accepted from localhost (Domain)
D [21/Sep/2017:09:55:01 +0900] [Client 241] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] [Client 241] POST / HTTP/1.1
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 241] Read: status=200, state=6
D [21/Sep/2017:09:55:01 +0900] [Client 241] No authentication data provided.
D [21/Sep/2017:09:55:01 +0900] [Client 241] 2.0 Get-Printer-Attributes 1
D [21/Sep/2017:09:55:01 +0900] Get-Printer-Attributes ipp://localhost:631/printers/Canon_iR_C2550
D [21/Sep/2017:09:55:01 +0900] [Client 241] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:09:55:01 +0900] [Client 241] Content-Length: 1487
D [21/Sep/2017:09:55:01 +0900] [Client 241] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:55:01 +0900] [Client 241] con->http=0x561ef9fb1b20
D [21/Sep/2017:09:55:01 +0900] [Client 241] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x561efa042060(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:55:01 +0900] [Client 241] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:55:01 +0900] [Client 241] bytes=0, http_state=0, data_remaining=1487
D [21/Sep/2017:09:55:01 +0900] [Client 241] Flushing write buffer.
D [21/Sep/2017:09:55:01 +0900] [Client 241] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:55:01 +0900] [Client 241] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 241] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:55:01 +0900] [Client 241] Closing connection.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 242] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:55:01 +0900] [Client 242] Accepted from localhost (Domain)
D [21/Sep/2017:09:55:01 +0900] [Client 242] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] [Client 242] POST / HTTP/1.1
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 242] Read: status=200, state=6
D [21/Sep/2017:09:55:01 +0900] [Client 242] No authentication data provided.
D [21/Sep/2017:09:55:01 +0900] [Client 242] 2.0 CUPS-Get-Printers 2
D [21/Sep/2017:09:55:01 +0900] CUPS-Get-Printers
D [21/Sep/2017:09:55:01 +0900] [Client 242] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [21/Sep/2017:09:55:01 +0900] [Client 242] Content-Length: 1487
D [21/Sep/2017:09:55:01 +0900] [Client 242] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:55:01 +0900] [Client 242] con->http=0x561ef9fb1b20
D [21/Sep/2017:09:55:01 +0900] [Client 242] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x561efa026da0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:55:01 +0900] [Client 242] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:55:01 +0900] [Client 242] bytes=0, http_state=0, data_remaining=1487
D [21/Sep/2017:09:55:01 +0900] [Client 242] Flushing write buffer.
D [21/Sep/2017:09:55:01 +0900] [Client 242] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:55:01 +0900] [Client 242] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 242] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:55:01 +0900] [Client 242] Closing connection.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 243] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:55:01 +0900] [Client 243] Accepted from localhost (Domain)
D [21/Sep/2017:09:55:01 +0900] [Client 243] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] [Client 243] POST / HTTP/1.1
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 243] Read: status=200, state=6
D [21/Sep/2017:09:55:01 +0900] [Client 243] No authentication data provided.
D [21/Sep/2017:09:55:01 +0900] [Client 243] 2.0 CUPS-Get-Default 3
D [21/Sep/2017:09:55:01 +0900] CUPS-Get-Default
D [21/Sep/2017:09:55:01 +0900] CUPS-Get-Default client-error-not-found: デフォルトのプリンターはありません。
D [21/Sep/2017:09:55:01 +0900] [Client 243] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [21/Sep/2017:09:55:01 +0900] [Client 243] Content-Length: 148
D [21/Sep/2017:09:55:01 +0900] [Client 243] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:55:01 +0900] [Client 243] con->http=0x561ef9fb1b20
D [21/Sep/2017:09:55:01 +0900] [Client 243] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=148, response=0x561efa03fdd0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:55:01 +0900] [Client 243] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:55:01 +0900] [Client 243] bytes=0, http_state=0, data_remaining=148
D [21/Sep/2017:09:55:01 +0900] [Client 243] Flushing write buffer.
D [21/Sep/2017:09:55:01 +0900] [Client 243] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:55:01 +0900] [Client 243] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 243] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:55:01 +0900] [Client 243] Closing connection.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 244] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:55:01 +0900] [Client 244] Accepted from localhost (Domain)
D [21/Sep/2017:09:55:01 +0900] [Client 244] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] [Client 244] POST /printers/Canon_iR_C2550 HTTP/1.1
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 244] Read: status=200, state=6
D [21/Sep/2017:09:55:01 +0900] [Client 244] No authentication data provided.
D [21/Sep/2017:09:55:01 +0900] [Client 244] 2.0 Get-Printer-Attributes 4
D [21/Sep/2017:09:55:01 +0900] Get-Printer-Attributes ipp://localhost/printers/Canon_iR_C2550
D [21/Sep/2017:09:55:01 +0900] [Client 244] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:09:55:01 +0900] [Client 244] Content-Length: 169509
D [21/Sep/2017:09:55:01 +0900] [Client 244] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:55:01 +0900] [Client 244] con->http=0x561ef9fb1b20
D [21/Sep/2017:09:55:01 +0900] [Client 244] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=169509, response=0x561efa03fdd0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:55:01 +0900] [Client 244] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:55:01 +0900] [Client 244] bytes=0, http_state=0, data_remaining=169509
D [21/Sep/2017:09:55:01 +0900] [Client 244] Flushing write buffer.
D [21/Sep/2017:09:55:01 +0900] [Client 244] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:55:01 +0900] [Client 244] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 244] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:55:01 +0900] [Client 244] Closing connection.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 245] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:55:01 +0900] [Client 245] Accepted from localhost (Domain)
D [21/Sep/2017:09:55:01 +0900] [Client 245] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] [Client 245] POST /printers/Canon_iR_C2550 HTTP/1.1
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 245] Read: status=200, state=6
D [21/Sep/2017:09:55:01 +0900] [Client 245] No authentication data provided.
D [21/Sep/2017:09:55:01 +0900] [Client 245] 2.0 Create-Job 5
D [21/Sep/2017:09:55:01 +0900] Create-Job ipp://localhost/printers/Canon_iR_C2550
D [21/Sep/2017:09:55:01 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [21/Sep/2017:09:55:01 +0900] add_job: requesting-user-name="ewab"
I [21/Sep/2017:09:55:01 +0900] [Job 14] Adding start banner page "none".
D [21/Sep/2017:09:55:01 +0900] Discarding unused job-created event...
I [21/Sep/2017:09:55:01 +0900] [Job 14] Queued on "Canon_iR_C2550" by "ewab".
D [21/Sep/2017:09:55:01 +0900] [Client 245] Returning IPP successful-ok for Create-Job (ipp://localhost/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:09:55:01 +0900] [Client 245] Content-Length: 200
D [21/Sep/2017:09:55:01 +0900] [Client 245] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:55:01 +0900] [Client 245] con->http=0x561ef9fb1b20
D [21/Sep/2017:09:55:01 +0900] [Client 245] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=200, response=0x561efa018bc0(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [21/Sep/2017:09:55:01 +0900] [Client 245] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:55:01 +0900] [Client 245] bytes=0, http_state=0, data_remaining=200
D [21/Sep/2017:09:55:01 +0900] [Client 245] Flushing write buffer.
D [21/Sep/2017:09:55:01 +0900] [Client 245] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:55:01 +0900] [Client 245] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 245] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:55:01 +0900] [Client 245] Closing connection.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 246] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:09:55:01 +0900] [Client 246] Accepted from localhost (Domain)
D [21/Sep/2017:09:55:01 +0900] [Client 246] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] [Client 246] POST /printers/Canon_iR_C2550 HTTP/1.1
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 246] Read: status=200, state=6
D [21/Sep/2017:09:55:01 +0900] [Client 246] No authentication data provided.
D [21/Sep/2017:09:55:01 +0900] [Client 246] 2.0 Send-Document 6
D [21/Sep/2017:09:55:01 +0900] Send-Document ipp://localhost:631/printers/Canon_iR_C2550
D [21/Sep/2017:09:55:01 +0900] cupsdIsAuthorized: requesting-user-name="ewab"
D [21/Sep/2017:09:55:01 +0900] [Job 14] Auto-typing file...
D [21/Sep/2017:09:55:01 +0900] [Job 14] Request file type is text/plain.
D [21/Sep/2017:09:55:01 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
I [21/Sep/2017:09:55:01 +0900] [Job 14] File of type text/plain queued by "ewab".
I [21/Sep/2017:09:55:01 +0900] [Job 14] Adding end banner page "none".
D [21/Sep/2017:09:55:01 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 246] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:09:55:01 +0900] [Client 246] Content-Length: 170
D [21/Sep/2017:09:55:01 +0900] [Client 246] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [21/Sep/2017:09:55:01 +0900] [Client 246] con->http=0x561ef9fb1b20
D [21/Sep/2017:09:55:01 +0900] [Client 246] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=170, response=0x561efa02b980(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:09:55:01 +0900] [Client 246] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:09:55:01 +0900] [Client 246] bytes=0, http_state=0, data_remaining=170
D [21/Sep/2017:09:55:01 +0900] [Client 246] Flushing write buffer.
D [21/Sep/2017:09:55:01 +0900] [Client 246] New state is HTTP_STATE_WAITING
D [21/Sep/2017:09:55:01 +0900] [Client 246] Waiting for request.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Client 246] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:09:55:01 +0900] [Client 246] Closing connection.
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:55:01 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:55:01 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:01 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:55:01 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:55:01 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:55:02 +0900] Report: clients=0
D [21/Sep/2017:09:55:02 +0900] Report: jobs=4
D [21/Sep/2017:09:55:02 +0900] Report: jobs-active=2
D [21/Sep/2017:09:55:02 +0900] Report: printers=1
D [21/Sep/2017:09:55:02 +0900] Report: stringpool-string-count=7307
D [21/Sep/2017:09:55:02 +0900] Report: stringpool-alloc-bytes=9880
D [21/Sep/2017:09:55:02 +0900] Report: stringpool-total-bytes=130680
D [21/Sep/2017:09:55:06 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:55:06 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:55:06 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:06 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:55:06 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:55:06 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:55:11 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:55:11 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:55:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:11 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:55:11 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:55:11 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:55:16 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:55:16 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:55:16 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:16 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:55:16 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:55:16 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:55:21 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:55:21 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:55:21 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:21 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:55:21 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:55:21 +0900] [Job 13] new_state=0, change_state=0
I [21/Sep/2017:09:55:26 +0900] Saving printers.conf...
I [21/Sep/2017:09:55:26 +0900] Saving job.cache...
D [21/Sep/2017:09:55:26 +0900] cupsdSetBusyState: newbusy="Printing jobs", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:26 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:55:26 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:55:26 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs"
D [21/Sep/2017:09:55:26 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:55:26 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:55:26 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:55:31 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:55:31 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:55:31 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:31 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:55:31 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:55:31 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:55:36 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:55:36 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:55:36 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:36 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:55:36 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:55:36 +0900] [Job 13] new_state=0, change_state=0
D [21/Sep/2017:09:55:41 +0900] [Job 13] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:09:55:41 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:09:55:41 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:09:55:41 +0900] [Job 13] new_supply_state=0, change_state=0
D [21/Sep/2017:09:55:41 +0900] Discarding unused printer-state-changed event...
D [21/Sep/2017:09:55:41 +0900] [Job 13] new_state=0, change_state=0
^C

I followed this instruction and saved the data which should go to the printer. The output was just a blank file.
https://wiki.ubuntu.com/DebuggingPrinti … he_printer

What is the cause? Any advice would be greatly appreciated.

Last edited by ewab (2017-09-26 03:42:55)

Offline

#2 2017-09-21 01:57:21

cirkit
Member
From: San Francisco
Registered: 2008-01-29
Posts: 80
Website

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

ewab wrote:

I re-installed arch linux last week, since then my Canon irC2550F printer connected via network have stopped printing.

Before you reinstalled, were there successful print jobs? What file formats have you tried printing? Based on a particular message being reported multiple times in your output:

newbusy="Active clients and dirty files", busy="Printing jobs and dirty files"

I would recommend you cancel any stale print jobs, increase CUPS logging verbosity, then send a new print job. You may also consider reprovisioning the printer entirely before these steps. It's possible you missed something after the reinstall.

Btw - I also don't know why you're referring to a non-supported wiki page. You should be looking at the Official Arch CUPS Wiki.

Last edited by cirkit (2017-09-21 02:17:03)

Offline

#3 2017-09-21 09:47:57

ewab
Member
From: Japan
Registered: 2017-04-28
Posts: 9

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

Thank you for your suggestion, cirkit.

It had been working flawlessly for months before reinstall. "dirty files" messages caught my eye and I googled it but I couln't find out any relevant information. I've tried printing test page, text files and PDFs but it prints nothing.

I reinstalled Arch twice, cups and the canon driver several times. I even tried foomatic drivers and build a driver from source files provided by Canon Japan. But nothing changed. When I tried the foomatic driver, cups web interface showed job completed, but the printer stood still.

Here's debug2 level log.

d [21/Sep/2017:12:02:09 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:09 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:10 +0900] cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1505962930
D [21/Sep/2017:12:02:10 +0900] Report: clients=1
D [21/Sep/2017:12:02:10 +0900] Report: jobs=7
D [21/Sep/2017:12:02:10 +0900] Report: jobs-active=0
D [21/Sep/2017:12:02:10 +0900] Report: printers=1
D [21/Sep/2017:12:02:10 +0900] Report: stringpool-string-count=7224
D [21/Sep/2017:12:02:10 +0900] Report: stringpool-alloc-bytes=8624
D [21/Sep/2017:12:02:10 +0900] Report: stringpool-total-bytes=128984
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:10 +0900] cupsdAcceptClient(lis=0x564bdf91d5c0(3)) Clients=1
D [21/Sep/2017:12:02:10 +0900] [Client 85] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:12:02:10 +0900] [Client 85] Accepted from localhost (Domain)
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 85] Waiting for request.
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 85] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 85] POST / HTTP/1.1
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:12:02:10 +0900] [Client 85] Read: status=200, state=6
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: uri="/", limit=10...
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/log(10) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin(6) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /(1) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: best=/
d [21/Sep/2017:12:02:10 +0900] [Client 85] con->uri="/", con->best=0x564bdf91d6e0(/)
D [21/Sep/2017:12:02:10 +0900] [Client 85] No authentication data provided.
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/", con->best=0x564bdf91d6e0(/)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:10 +0900] [Client 85] 2.0 Get-Printer-Attributes 1
d [21/Sep/2017:12:02:10 +0900] cupsdProcessIPPRequest(0x564bdfa4d310[85]): operation_id = 000b
D [21/Sep/2017:12:02:10 +0900] Get-Printer-Attributes ipp://localhost:631/printers/Canon_iR_C2550
d [21/Sep/2017:12:02:10 +0900] get_printer_attrs(0x564bdfa4d310[85], ipp://localhost:631/printers/Canon_iR_C2550)
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp(p=0x564bdf91dec0, op=b(Get-Printer-Attributes))
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp: Found wildcard match...
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/", con->best=0x564bdf922380((null))
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: op=0(0x0000)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [21/Sep/2017:12:02:10 +0900] add_printer_state_reasons(0x564bdfa4d310[85], 0x564bdf93d830[Canon_iR_C2550])
d [21/Sep/2017:12:02:10 +0900] printer-uri-supported="ipp://localhost/printers/Canon_iR_C2550"
d [21/Sep/2017:12:02:10 +0900] copy_attrs(to=0x564bdfa31410, from=0x564bdf930af0, ra=0x564bdf9c99d0, group=0, quickcopy=0)
d [21/Sep/2017:12:02:10 +0900] copy_attrs(to=0x564bdfa31410, from=0x564bdf9663d0, ra=0x564bdf9c99d0, group=0, quickcopy=0)
d [21/Sep/2017:12:02:10 +0900] copy_attrs(to=0x564bdfa31410, from=0x564bdf93d280, ra=0x564bdf9c99d0, group=0, quickcopy=-2147483648)
D [21/Sep/2017:12:02:10 +0900] [Client 85] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:12:02:10 +0900] [Client 85] Content-Length: 1487
D [21/Sep/2017:12:02:10 +0900] [Client 85] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=0x564bde92d9d0, data=0x564bdfa4d310)
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:10 +0900] [Client 85] con->http=0x564bdfa42cd0
D [21/Sep/2017:12:02:10 +0900] [Client 85] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x564bdfa31410(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 85] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:12:02:10 +0900] [Client 85] bytes=0, http_state=0, data_remaining=1487
D [21/Sep/2017:12:02:10 +0900] [Client 85] Flushing write buffer.
D [21/Sep/2017:12:02:10 +0900] [Client 85] New state is HTTP_STATE_WAITING
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 85] Waiting for request.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 85] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 85] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:12:02:10 +0900] [Client 85] Closing connection.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=13)
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=-1)
d [21/Sep/2017:12:02:10 +0900] cupsdAcceptClient(lis=0x564bdf91d5c0(3)) Clients=1
D [21/Sep/2017:12:02:10 +0900] [Client 86] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:12:02:10 +0900] [Client 86] Accepted from localhost (Domain)
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 86] Waiting for request.
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 86] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 86] POST / HTTP/1.1
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:12:02:10 +0900] [Client 86] Read: status=200, state=6
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: uri="/", limit=10...
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/log(10) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin(6) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /(1) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: best=/
d [21/Sep/2017:12:02:10 +0900] [Client 86] con->uri="/", con->best=0x564bdf91d6e0(/)
D [21/Sep/2017:12:02:10 +0900] [Client 86] No authentication data provided.
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/", con->best=0x564bdf91d6e0(/)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:10 +0900] [Client 86] 2.0 CUPS-Get-Printers 2
d [21/Sep/2017:12:02:10 +0900] cupsdProcessIPPRequest(0x564bdfa4d310[86]): operation_id = 4002
D [21/Sep/2017:12:02:10 +0900] CUPS-Get-Printers
d [21/Sep/2017:12:02:10 +0900] get_printers(0x564bdfa4d310[86], 0)
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp(p=0x564bdf91dec0, op=4002(CUPS-Get-Printers))
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp: Found wildcard match...
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/", con->best=0x564bdf922380((null))
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: op=0(0x0000)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [21/Sep/2017:12:02:10 +0900] add_printer_state_reasons(0x564bdfa4d310[86], 0x564bdf93d830[Canon_iR_C2550])
d [21/Sep/2017:12:02:10 +0900] printer-uri-supported="ipp://localhost/printers/Canon_iR_C2550"
d [21/Sep/2017:12:02:10 +0900] copy_attrs(to=0x564bdfa2f6c0, from=0x564bdf930af0, ra=0x564bdf9c99d0, group=0, quickcopy=0)
d [21/Sep/2017:12:02:10 +0900] copy_attrs(to=0x564bdfa2f6c0, from=0x564bdf9663d0, ra=0x564bdf9c99d0, group=0, quickcopy=0)
d [21/Sep/2017:12:02:10 +0900] copy_attrs(to=0x564bdfa2f6c0, from=0x564bdf93d280, ra=0x564bdf9c99d0, group=0, quickcopy=-2147483648)
D [21/Sep/2017:12:02:10 +0900] [Client 86] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [21/Sep/2017:12:02:10 +0900] [Client 86] Content-Length: 1487
D [21/Sep/2017:12:02:10 +0900] [Client 86] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=0x564bde92d9d0, data=0x564bdfa4d310)
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:10 +0900] [Client 86] con->http=0x564bdfa42cd0
D [21/Sep/2017:12:02:10 +0900] [Client 86] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x564bdfa2f6c0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 86] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:12:02:10 +0900] [Client 86] bytes=0, http_state=0, data_remaining=1487
D [21/Sep/2017:12:02:10 +0900] [Client 86] Flushing write buffer.
D [21/Sep/2017:12:02:10 +0900] [Client 86] New state is HTTP_STATE_WAITING
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 86] Waiting for request.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 86] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 86] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:12:02:10 +0900] [Client 86] Closing connection.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=13)
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=-1)
d [21/Sep/2017:12:02:10 +0900] cupsdAcceptClient(lis=0x564bdf91d5c0(3)) Clients=1
D [21/Sep/2017:12:02:10 +0900] [Client 87] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:12:02:10 +0900] [Client 87] Accepted from localhost (Domain)
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 87] Waiting for request.
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 87] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 87] POST / HTTP/1.1
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:12:02:10 +0900] [Client 87] Read: status=200, state=6
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: uri="/", limit=10...
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/log(10) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin(6) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /(1) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: best=/
d [21/Sep/2017:12:02:10 +0900] [Client 87] con->uri="/", con->best=0x564bdf91d6e0(/)
D [21/Sep/2017:12:02:10 +0900] [Client 87] No authentication data provided.
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/", con->best=0x564bdf91d6e0(/)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:10 +0900] [Client 87] 2.0 CUPS-Get-Default 3
d [21/Sep/2017:12:02:10 +0900] cupsdProcessIPPRequest(0x564bdfa4d310[87]): operation_id = 4001
D [21/Sep/2017:12:02:10 +0900] CUPS-Get-Default
d [21/Sep/2017:12:02:10 +0900] get_default(0x564bdfa4d310[87])
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp(p=0x564bdf91dec0, op=4001(CUPS-Get-Default))
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp: Found wildcard match...
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/", con->best=0x564bdf922380((null))
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: op=0(0x0000)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:10 +0900] CUPS-Get-Default client-error-not-found: デフォルトのプリンターはありません。
D [21/Sep/2017:12:02:10 +0900] [Client 87] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [21/Sep/2017:12:02:10 +0900] [Client 87] Content-Length: 148
D [21/Sep/2017:12:02:10 +0900] [Client 87] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=0x564bde92d9d0, data=0x564bdfa4d310)
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:10 +0900] [Client 87] con->http=0x564bdfa42cd0
D [21/Sep/2017:12:02:10 +0900] [Client 87] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=148, response=0x564bdfa280d0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 87] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:12:02:10 +0900] [Client 87] bytes=0, http_state=0, data_remaining=148
D [21/Sep/2017:12:02:10 +0900] [Client 87] Flushing write buffer.
D [21/Sep/2017:12:02:10 +0900] [Client 87] New state is HTTP_STATE_WAITING
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 87] Waiting for request.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 87] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 87] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:12:02:10 +0900] [Client 87] Closing connection.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=13)
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=-1)
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] cupsdAcceptClient(lis=0x564bdf91d5c0(3)) Clients=1
D [21/Sep/2017:12:02:10 +0900] [Client 88] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:12:02:10 +0900] [Client 88] Accepted from localhost (Domain)
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 88] Waiting for request.
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 88] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 88] POST /printers/Canon_iR_C2550 HTTP/1.1
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:12:02:10 +0900] [Client 88] Read: status=200, state=6
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: uri="/printers/Canon_iR_C2550", limit=10...
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/log(10) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin(6) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /(1) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: best=/
d [21/Sep/2017:12:02:10 +0900] [Client 88] con->uri="/printers/Canon_iR_C2550", con->best=0x564bdf91d6e0(/)
D [21/Sep/2017:12:02:10 +0900] [Client 88] No authentication data provided.
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/printers/Canon_iR_C2550", con->best=0x564bdf91d6e0(/)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:10 +0900] [Client 88] 2.0 Get-Printer-Attributes 4
d [21/Sep/2017:12:02:10 +0900] cupsdProcessIPPRequest(0x564bdfa4d310[88]): operation_id = 000b
D [21/Sep/2017:12:02:10 +0900] Get-Printer-Attributes ipp://localhost/printers/Canon_iR_C2550
d [21/Sep/2017:12:02:10 +0900] get_printer_attrs(0x564bdfa4d310[88], ipp://localhost/printers/Canon_iR_C2550)
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp(p=0x564bdf91dec0, op=b(Get-Printer-Attributes))
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp: Found wildcard match...
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/printers/Canon_iR_C2550", con->best=0x564bdf922380((null))
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: op=0(0x0000)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [21/Sep/2017:12:02:10 +0900] printer-icons="http://localhost/icons/Canon_iR_C2550.png"
d [21/Sep/2017:12:02:10 +0900] add_printer_state_reasons(0x564bdfa4d310[88], 0x564bdf93d830[Canon_iR_C2550])
d [21/Sep/2017:12:02:10 +0900] printer-uri-supported="ipp://localhost/printers/Canon_iR_C2550"
d [21/Sep/2017:12:02:10 +0900] add_queued_job_count(0x564bdfa4d310[88], 0x564bdf93d830[Canon_iR_C2550])
d [21/Sep/2017:12:02:10 +0900] copy_attrs(to=0x564bdfa32990, from=0x564bdf930af0, ra=0x564bdf9c99d0, group=0, quickcopy=0)
d [21/Sep/2017:12:02:10 +0900] copy_attrs(to=0x564bdfa32990, from=0x564bdf9663d0, ra=0x564bdf9c99d0, group=0, quickcopy=0)
d [21/Sep/2017:12:02:10 +0900] copy_attrs(to=0x564bdfa32990, from=0x564bdf93d280, ra=0x564bdf9c99d0, group=0, quickcopy=-2147483648)
D [21/Sep/2017:12:02:10 +0900] [Client 88] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:12:02:10 +0900] [Client 88] Content-Length: 169781
D [21/Sep/2017:12:02:10 +0900] [Client 88] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=0x564bde92d9d0, data=0x564bdfa4d310)
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:10 +0900] [Client 88] con->http=0x564bdfa42cd0
D [21/Sep/2017:12:02:10 +0900] [Client 88] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=169781, response=0x564bdfa32990(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 88] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:12:02:10 +0900] [Client 88] bytes=0, http_state=0, data_remaining=169781
D [21/Sep/2017:12:02:10 +0900] [Client 88] Flushing write buffer.
D [21/Sep/2017:12:02:10 +0900] [Client 88] New state is HTTP_STATE_WAITING
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 88] Waiting for request.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 88] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 88] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:12:02:10 +0900] [Client 88] Closing connection.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=13)
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=-1)
d [21/Sep/2017:12:02:10 +0900] cupsdAcceptClient(lis=0x564bdf91d5c0(3)) Clients=1
D [21/Sep/2017:12:02:10 +0900] [Client 89] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:12:02:10 +0900] [Client 89] Accepted from localhost (Domain)
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 89] Waiting for request.
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 89] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 89] POST /printers/Canon_iR_C2550 HTTP/1.1
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:12:02:10 +0900] [Client 89] Read: status=200, state=6
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: uri="/printers/Canon_iR_C2550", limit=10...
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/log(10) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin(6) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /(1) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: best=/
d [21/Sep/2017:12:02:10 +0900] [Client 89] con->uri="/printers/Canon_iR_C2550", con->best=0x564bdf91d6e0(/)
D [21/Sep/2017:12:02:10 +0900] [Client 89] No authentication data provided.
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/printers/Canon_iR_C2550", con->best=0x564bdf91d6e0(/)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:10 +0900] [Client 89] 2.0 Create-Job 5
d [21/Sep/2017:12:02:10 +0900] cupsdProcessIPPRequest(0x564bdfa4d310[89]): operation_id = 0005
D [21/Sep/2017:12:02:10 +0900] Create-Job ipp://localhost/printers/Canon_iR_C2550
d [21/Sep/2017:12:02:10 +0900] create_job(0x564bdfa4d310[89], ipp://localhost/printers/Canon_iR_C2550)
d [21/Sep/2017:12:02:10 +0900] add_job(0x564bdfa4d310[89], 0x564bdf93d830(Canon_iR_C2550), (nil)(none/none))
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp(p=0x564bdf91dec0, op=5(Create-Job))
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp: Found exact match...
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/printers/Canon_iR_C2550", con->best=0x564bdf91e8a0((null))
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: op=5(Create-Job)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [21/Sep/2017:12:02:10 +0900] check_quotas(0x564bdfa4d310[89], 0x564bdf93d830[Canon_iR_C2550])
D [21/Sep/2017:12:02:10 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:12:02:10 +0900] add_job: requesting-user-name="fukuokasoichiro"
I [21/Sep/2017:12:02:10 +0900] [Job 18] Adding start banner page "none".
d [21/Sep/2017:12:02:10 +0900] copy_banner(con=0x564bdfa4d310[89], job=0x564bdfa3f9a0[18], name="none")
d [21/Sep/2017:12:02:10 +0900] cupsdAddEvent(event=job-created, dest=0x564bdf93d830(Canon_iR_C2550), job=0x564bdfa3f9a0(18), text="Job created.", ...)
D [21/Sep/2017:12:02:10 +0900] Discarding unused job-created event...
I [21/Sep/2017:12:02:10 +0900] [Job 18] Queued on "Canon_iR_C2550" by "fukuokasoichiro".
D [21/Sep/2017:12:02:10 +0900] [Client 89] Returning IPP successful-ok for Create-Job (ipp://localhost/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:12:02:10 +0900] [Client 89] Content-Length: 200
D [21/Sep/2017:12:02:10 +0900] [Client 89] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=0x564bde92d9d0, data=0x564bdfa4d310)
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:10 +0900] [Client 89] con->http=0x564bdfa42cd0
D [21/Sep/2017:12:02:10 +0900] [Client 89] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=200, response=0x564bdfa280d0(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 89] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:12:02:10 +0900] [Client 89] bytes=0, http_state=0, data_remaining=200
D [21/Sep/2017:12:02:10 +0900] [Client 89] Flushing write buffer.
D [21/Sep/2017:12:02:10 +0900] [Client 89] New state is HTTP_STATE_WAITING
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 89] Waiting for request.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 89] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 89] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:12:02:10 +0900] [Client 89] Closing connection.
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=13)
d [21/Sep/2017:12:02:10 +0900] cupsdRemoveSelect(fd=-1)
d [21/Sep/2017:12:02:10 +0900] cupsdAcceptClient(lis=0x564bdf91d5c0(3)) Clients=1
D [21/Sep/2017:12:02:10 +0900] [Client 90] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:12:02:10 +0900] [Client 90] Accepted from localhost (Domain)
d [21/Sep/2017:12:02:10 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:10 +0900] [Client 90] Waiting for request.
d [21/Sep/2017:12:02:10 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:10 +0900] [Client 90] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:10 +0900] [Client 90] POST /printers/Canon_iR_C2550 HTTP/1.1
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [21/Sep/2017:12:02:10 +0900] [Client 90] Read: status=200, state=6
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: uri="/printers/Canon_iR_C2550", limit=10...
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/log(10) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /admin(6) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: Location /(1) Limit 7f
d [21/Sep/2017:12:02:10 +0900] cupsdFindBest: best=/
d [21/Sep/2017:12:02:10 +0900] [Client 90] con->uri="/printers/Canon_iR_C2550", con->best=0x564bdf91d6e0(/)
D [21/Sep/2017:12:02:10 +0900] [Client 90] No authentication data provided.
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/printers/Canon_iR_C2550", con->best=0x564bdf91d6e0(/)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:10 +0900] [Client 90] 2.0 Send-Document 6
d [21/Sep/2017:12:02:10 +0900] cupsdProcessIPPRequest(0x564bdfa4d310[90]): operation_id = 0006
D [21/Sep/2017:12:02:10 +0900] Send-Document ipp://localhost:631/printers/Canon_iR_C2550
d [21/Sep/2017:12:02:10 +0900] send_document(0x564bdfa4d310[90], ipp://localhost:631/printers/Canon_iR_C2550)
d [21/Sep/2017:12:02:10 +0900] validate_user(job=18, con=90, owner="fukuokasoichiro", username=0x7ffda9be2810, userlen=1024)
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp(p=0x564bdf91dec0, op=6(Send-Document))
d [21/Sep/2017:12:02:10 +0900] cupsdFindPolicyOp: Found exact match...
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: con->uri="/printers/Canon_iR_C2550", con->best=0x564bdf91ea70((null))
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: owner="fukuokasoichiro"
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_USER, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=2
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: op=6(Send-Document)
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: requesting-user-name="fukuokasoichiro"
d [21/Sep/2017:12:02:10 +0900] cupsdIsAuthorized: Checking user membership...
D [21/Sep/2017:12:02:10 +0900] [Job 18] Auto-typing file...
D [21/Sep/2017:12:02:10 +0900] [Job 18] Request file type is text/plain.
d [21/Sep/2017:12:02:10 +0900] add_file(con=0x564bdfa4d310[90], job=18, filetype=text/plain, compression=0)
D [21/Sep/2017:12:02:10 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [21/Sep/2017:12:02:10 +0900] [Job 18] File of type text/plain queued by "fukuokasoichiro".
I [21/Sep/2017:12:02:10 +0900] [Job 18] Adding end banner page "none".
d [21/Sep/2017:12:02:10 +0900] copy_banner(con=(nil)[-1], job=0x564bdfa3f9a0[18], name="none")
D [21/Sep/2017:12:02:10 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
d [21/Sep/2017:12:02:10 +0900] cupsdCheckJobs: 1 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1505962930
d [21/Sep/2017:12:02:10 +0900] cupsdCheckJobs: Job 18 - dest="Canon_iR_C2550", printer=(nil), state=3, cancel_time=0, hold_until=1505963230, kill_time=0, pending_cost=0, pending_timeout=0
d [21/Sep/2017:12:02:10 +0900] start_job(job=0x564bdfa3f9a0(18), printer=0x564bdf93d830(Canon_iR_C2550))
d [21/Sep/2017:12:02:10 +0900] cupsdSetJobState(job=0x564bdfa3f9a0(18), state=3, newstate=5, action=0, message="(null)")
D [21/Sep/2017:12:02:10 +0900] [Job 18] time-at-processing=1505962930
D [21/Sep/2017:12:02:10 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:12:02:10 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
d [21/Sep/2017:12:02:10 +0900] cupsdAddEvent(event=printer-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=(nil)(0), text="%s \"%s\" state changed to %s.", ...)
D [21/Sep/2017:12:02:10 +0900] Discarding unused printer-state-changed event...
d [21/Sep/2017:12:02:10 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-paused"
d [21/Sep/2017:12:02:10 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-cups-remote-pending,cups-remote-pending-held,cups-remote-processing,cups-remote-stopped,cups-remote-canceled,cups-remote-aborted,cups-remote-completed"
d [21/Sep/2017:12:02:10 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-cups-missing-filter-warning,cups-insecure-filter-warning"
d [21/Sep/2017:12:02:10 +0900] cupsdCreateProfile(job_id=18, allow_networking=0) = NULL
d [21/Sep/2017:12:02:10 +0900] cupsdCreateProfile(job_id=18, allow_networking=1) = NULL
d [21/Sep/2017:12:02:10 +0900] cupsdContinueJob(job=0x564bdfa3f9a0(18)): current_file=0, num_files=1
D [21/Sep/2017:12:02:10 +0900] [Job 18] 4 filters for job:
D [21/Sep/2017:12:02:10 +0900] [Job 18] texttopdf (text/plain to application/pdf, cost 32)
D [21/Sep/2017:12:02:10 +0900] [Job 18] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [21/Sep/2017:12:02:10 +0900] [Job 18] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100)
D [21/Sep/2017:12:02:10 +0900] [Job 18] pstoufr2cpca (application/vnd.cups-postscript to printer/Canon_iR_C2550, cost 0)
D [21/Sep/2017:12:02:10 +0900] [Job 18] job-sheets=none,none
D [21/Sep/2017:12:02:10 +0900] [Job 18] argv[0]="Canon_iR_C2550"
D [21/Sep/2017:12:02:10 +0900] [Job 18] argv[1]="18"
D [21/Sep/2017:12:02:10 +0900] [Job 18] argv[2]="fukuokasoichiro"
D [21/Sep/2017:12:02:10 +0900] [Job 18] argv[3]="test.txt"
D [21/Sep/2017:12:02:10 +0900] [Job 18] argv[4]="1"
D [21/Sep/2017:12:02:10 +0900] [Job 18] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:19f576d5-c48e-3acc-5cdc-14a924a832ea job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1505962930 time-at-processing=1505962930 document-name-supplied=test.txt"
D [21/Sep/2017:12:02:10 +0900] [Job 18] argv[6]="/var/spool/cups/d00018-001"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[7]="CUPS_STATEDIR=/run/cups"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[8]="HOME=/var/spool/cups/tmp"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[10]="SERVER_ADMIN=root@archlinux"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[11]="SOFTWARE=CUPS/2.2.4"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[13]="USER=root"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[14]="CUPS_MAX_MESSAGE=2047"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[17]="IPP_PORT=631"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[18]="CHARSET=utf-8"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[19]="LANG=ja_JP.UTF-8"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[20]="PPD=/etc/cups/ppd/Canon_iR_C2550.ppd"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[21]="RIP_MAX_CACHE=128m"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[22]="CONTENT_TYPE=text/plain"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[23]="DEVICE_URI=socket://192.168.1.50"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[24]="PRINTER_INFO=Canon iR C2550 (LIPSLX)"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[25]="PRINTER_LOCATION="
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[26]="PRINTER=Canon_iR_C2550"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[27]="PRINTER_STATE_REASONS=none"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[28]="CUPS_FILETYPE=document"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
D [21/Sep/2017:12:02:10 +0900] [Job 18] envp[30]="AUTH_I****"
d [21/Sep/2017:12:02:10 +0900] Canon_iR_C2550: ファイル \"/usr/lib/cups/filter/texttopdf\" のパーミッションは問題ありません (040755/uid=0/gid=0)。
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/texttopdf", arguments:
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[1] = "-g"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[2] = "7"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[3] = "-n"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[4] = "0"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[5] = "-u"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[6] = "2"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[7] = "none"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[8] = "/usr/lib/cups/filter/texttopdf"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[9] = "Canon_iR_C2550"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[10] = "18"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[11] = "fukuokasoichiro"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[12] = "test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[13] = "1"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:19f576d5-c48e-3acc-5cdc-14a924a832ea job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1505962930 time-at-processing=1505962930 document-name-supplied=test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[15] = "/var/spool/cups/d00018-001"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting spawn attributes.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting file actions.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Calling posix_spawn.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: pid=2080
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess(command="/usr/lib/cups/filter/texttopdf", argv=0x7ffda9bde5b0, envp=0x7ffda9bdf0a0, infd=-1, outfd=22, errfd=15, backfd=17, sidefd=19, root=0, profile=(nil), job=0x564bdfa3f9a0(18), pid=0x564bdfa3fab4) = 2080
I [21/Sep/2017:12:02:10 +0900] [Job 18] Started filter /usr/lib/cups/filter/texttopdf (PID 2080)
d [21/Sep/2017:12:02:10 +0900] Canon_iR_C2550: ファイル \"/usr/lib/cups/filter/pdftopdf\" のパーミッションは問題ありません (040755/uid=0/gid=0)。
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/pdftopdf", arguments:
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[1] = "-g"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[2] = "7"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[3] = "-n"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[4] = "0"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[5] = "-u"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[6] = "2"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[7] = "none"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[8] = "/usr/lib/cups/filter/pdftopdf"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[9] = "Canon_iR_C2550"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[10] = "18"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[11] = "fukuokasoichiro"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[12] = "test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[13] = "1"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:19f576d5-c48e-3acc-5cdc-14a924a832ea job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1505962930 time-at-processing=1505962930 document-name-supplied=test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting spawn attributes.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting file actions.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Calling posix_spawn.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: pid=2081
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess(command="/usr/lib/cups/filter/pdftopdf", argv=0x7ffda9bde5b0, envp=0x7ffda9bdf0a0, infd=21, outfd=24, errfd=15, backfd=17, sidefd=19, root=0, profile=(nil), job=0x564bdfa3f9a0(18), pid=0x564bdfa3fab8) = 2081
I [21/Sep/2017:12:02:10 +0900] [Job 18] Started filter /usr/lib/cups/filter/pdftopdf (PID 2081)
d [21/Sep/2017:12:02:10 +0900] Canon_iR_C2550: ファイル \"/usr/lib/cups/filter/pdftops\" のパーミッションは問題ありません (040755/uid=0/gid=0)。
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/pdftops", arguments:
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[1] = "-g"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[2] = "7"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[3] = "-n"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[4] = "0"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[5] = "-u"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[6] = "2"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[7] = "none"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[8] = "/usr/lib/cups/filter/pdftops"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[9] = "Canon_iR_C2550"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[10] = "18"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[11] = "fukuokasoichiro"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[12] = "test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[13] = "1"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:19f576d5-c48e-3acc-5cdc-14a924a832ea job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1505962930 time-at-processing=1505962930 document-name-supplied=test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting spawn attributes.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting file actions.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Calling posix_spawn.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: pid=2082
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess(command="/usr/lib/cups/filter/pdftops", argv=0x7ffda9bde5b0, envp=0x7ffda9bdf0a0, infd=23, outfd=22, errfd=15, backfd=17, sidefd=19, root=0, profile=(nil), job=0x564bdfa3f9a0(18), pid=0x564bdfa3fabc) = 2082
I [21/Sep/2017:12:02:10 +0900] [Job 18] Started filter /usr/lib/cups/filter/pdftops (PID 2082)
d [21/Sep/2017:12:02:10 +0900] Canon_iR_C2550: ファイル \"/usr/lib/cups/filter/pstoufr2cpca\" のパーミッションは問題ありません (040755/uid=0/gid=0)。
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Preparing to start "/usr/lib/cups/filter/pstoufr2cpca", arguments:
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[1] = "-g"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[2] = "7"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[3] = "-n"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[4] = "0"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[5] = "-u"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[6] = "2"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[7] = "none"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[8] = "/usr/lib/cups/filter/pstoufr2cpca"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[9] = "Canon_iR_C2550"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[10] = "18"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[11] = "fukuokasoichiro"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[12] = "test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[13] = "1"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:19f576d5-c48e-3acc-5cdc-14a924a832ea job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1505962930 time-at-processing=1505962930 document-name-supplied=test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting spawn attributes.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting file actions.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Calling posix_spawn.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: pid=2083
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess(command="/usr/lib/cups/filter/pstoufr2cpca", argv=0x7ffda9bde5b0, envp=0x7ffda9bdf0a0, infd=21, outfd=24, errfd=15, backfd=17, sidefd=19, root=0, profile=(nil), job=0x564bdfa3f9a0(18), pid=0x564bdfa3fac0) = 2083
I [21/Sep/2017:12:02:10 +0900] [Job 18] Started filter /usr/lib/cups/filter/pstoufr2cpca (PID 2083)
d [21/Sep/2017:12:02:10 +0900] Canon_iR_C2550: ファイル \"/usr/lib/cups/backend/socket\" のパーミッションは問題ありません (040755/uid=0/gid=0)。
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Preparing to start "/usr/lib/cups/backend/socket", arguments:
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[0] = "/usr/lib/cups/daemon/cups-exec"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[1] = "-g"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[2] = "7"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[3] = "-n"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[4] = "0"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[5] = "-u"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[6] = "2"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[7] = "none"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[8] = "/usr/lib/cups/backend/socket"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[9] = "socket://192.168.1.50"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[10] = "18"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[11] = "fukuokasoichiro"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[12] = "test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[13] = "1"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: argv[14] = "finishings=3 number-up=1 job-uuid=urn:uuid:19f576d5-c48e-3acc-5cdc-14a924a832ea job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1505962930 time-at-processing=1505962930 document-name-supplied=test.txt"
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting spawn attributes.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Setting file actions.
d [21/Sep/2017:12:02:10 +0900] cupsdStartProcess: Calling posix_spawn.
d [21/Sep/2017:12:02:11 +0900] cupsdStartProcess: pid=2084
d [21/Sep/2017:12:02:11 +0900] cupsdStartProcess(command="/usr/lib/cups/backend/socket", argv=0x7ffda9bde5b0, envp=0x7ffda9bdf0a0, infd=23, outfd=-1, errfd=15, backfd=18, sidefd=20, root=0, profile=(nil), job=0x564bdfa3f9a0(18), pid=0x564bdfa3fb08) = 2084
I [21/Sep/2017:12:02:11 +0900] [Job 18] Started backend /usr/lib/cups/backend/socket (PID 2084)
d [21/Sep/2017:12:02:11 +0900] cupsdAddSelect(fd=14, read_cb=0x564bde947d10, write_cb=(nil), data=0x564bdfa3f9a0)
d [21/Sep/2017:12:02:11 +0900] cupsdAddEvent(event=job-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=0x564bdfa3f9a0(18), text="Job #%d started.", ...)
D [21/Sep/2017:12:02:11 +0900] Discarding unused job-state-changed event...
D [21/Sep/2017:12:02:11 +0900] [Client 90] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:12:02:11 +0900] [Client 90] Content-Length: 170
D [21/Sep/2017:12:02:11 +0900] [Client 90] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [21/Sep/2017:12:02:11 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=0x564bde92d9d0, data=0x564bdfa4d310)
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Client 90] con->http=0x564bdfa42cd0
D [21/Sep/2017:12:02:11 +0900] [Client 90] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=170, response=0x564bdfa3b760(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:12:02:11 +0900] [Client 90] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:12:02:11 +0900] [Client 90] bytes=0, http_state=0, data_remaining=170
D [21/Sep/2017:12:02:11 +0900] [Client 90] Flushing write buffer.
D [21/Sep/2017:12:02:11 +0900] [Client 90] New state is HTTP_STATE_WAITING
d [21/Sep/2017:12:02:11 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:11 +0900] [Client 90] Waiting for request.
D [21/Sep/2017:12:02:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [21/Sep/2017:12:02:11 +0900] [Job 18] Page = 595x842; 14,14 to 581,828
D [21/Sep/2017:12:02:11 +0900] [Job 18] pstoufr2cpca start.
D [21/Sep/2017:12:02:11 +0900] [Job 18] pdftopdf: Last filter determined by the PPD: pstoufr2cpca; FINAL_CONTENT_TYPE: application/vnd.cups-postscript => pdftopdf will not log pages in page_log.
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] [Client 90] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:11 +0900] [Client 90] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:12:02:11 +0900] [Client 90] Closing connection.
D [21/Sep/2017:12:02:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [21/Sep/2017:12:02:11 +0900] cupsdRemoveSelect(fd=13)
d [21/Sep/2017:12:02:11 +0900] cupsdRemoveSelect(fd=-1)
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] pdftops - copying to temp print file \"/var/spool/cups/tmp/0082259c34a74\"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: +connecting-to-device
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="+connecting-to-device"
D [21/Sep/2017:12:02:11 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:12:02:11 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
d [21/Sep/2017:12:02:11 +0900] cupsdAddEvent(event=printer-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=(nil)(0), text="Printer \"%s\" state changed.", ...)
D [21/Sep/2017:12:02:11 +0900] Discarding unused printer-state-changed event...
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Looking up \"192.168.1.50\"...
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -connecting-to-device
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-connecting-to-device"
D [21/Sep/2017:12:02:11 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:12:02:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
d [21/Sep/2017:12:02:11 +0900] cupsdAddEvent(event=printer-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=(nil)(0), text="Printer \"%s\" state changed.", ...)
D [21/Sep/2017:12:02:11 +0900] Discarding unused printer-state-changed event...
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] 192.168.1.50=192.168.1.50
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] process_children()
d [21/Sep/2017:12:02:11 +0900] cupsdFinishProcess(pid=2080, name=0x7ffda9bf0d20, namelen=1024, job_id=0x7ffda9bf0c08(18)) = "/usr/lib/cups/filter/texttopdf"
D [21/Sep/2017:12:02:11 +0900] [Job 18] PID 2080 (/usr/lib/cups/filter/texttopdf) exited with no errors.
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] select_timeout(-1): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:11 +0900] process_children()
d [21/Sep/2017:12:02:11 +0900] cupsdFinishProcess(pid=2081, name=0x7ffda9bf0d20, namelen=1024, job_id=0x7ffda9bf0c08(18)) = "/usr/lib/cups/filter/pdftopdf"
D [21/Sep/2017:12:02:11 +0900] [Job 18] PID 2081 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] select_timeout(-1): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:11 +0900] [Job 18] hrDeviceDesc=\"Canon iR C2550 94.01\"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Printer make and model: Canon ir c2550
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Running command line for pstops: pstops 18 fukuokasoichiro test.txt 1 \'finishings=3 job-uuid=urn:uuid:19f576d5-c48e-3acc-5cdc-14a924a832ea job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1505962930 time-at-processing=1505962930 document-name-supplied=test.txt\'
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Using image rendering resolution 600 dpi
D [21/Sep/2017:12:02:11 +0900] [Job 18] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r600 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c \'save pop\' -f /var/spool/cups/tmp/0082259c34a74
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Started filter gs (PID 2085)
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Started filter pstops (PID 2086)
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] [Job 18] prtMarkerColorantValue.1.1 = \"black\"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] [Job 18] prtMarkerColorantValue.1.2 = \"cyan\"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] [Job 18] prtMarkerColorantValue.1.3 = \"magenta\"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] [Job 18] prtMarkerColorantValue.1.4 = \"yellow\"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] ATTR: marker-colors=#000000,#00FFFF,#FF00FF,#FFFF00,none
D [21/Sep/2017:12:02:11 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:12:02:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [21/Sep/2017:12:02:11 +0900] cupsdAddEvent(event=printer-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=(nil)(0), text="Printer \"%s\" state changed.", ...)
D [21/Sep/2017:12:02:11 +0900] Discarding unused printer-state-changed event...
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] ATTR: marker-names=\'\"NPG-35 Black Toner\"\',\'\"NPG-35 Cyan Toner\"\',\'\"NPG-35 Magenta Toner\"\',\'\"NPG-35 Yellow Toner\"\',\'\"Waste Toner\"\'
D [21/Sep/2017:12:02:11 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:12:02:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [21/Sep/2017:12:02:11 +0900] cupsdAddEvent(event=printer-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=(nil)(0), text="Printer \"%s\" state changed.", ...)
D [21/Sep/2017:12:02:11 +0900] Discarding unused printer-state-changed event...
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] ATTR: marker-types=toner,toner,toner,toner,waste-toner
D [21/Sep/2017:12:02:11 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:12:02:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [21/Sep/2017:12:02:11 +0900] cupsdAddEvent(event=printer-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=(nil)(0), text="Printer \"%s\" state changed.", ...)
D [21/Sep/2017:12:02:11 +0900] Discarding unused printer-state-changed event...
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:12:02:11 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:12:02:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [21/Sep/2017:12:02:11 +0900] cupsdAddEvent(event=printer-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=(nil)(0), text="Printer \"%s\" state changed.", ...)
D [21/Sep/2017:12:02:11 +0900] Discarding unused printer-state-changed event...
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] new_supply_state=0, change_state=ffff
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -developer-low-report
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-developer-low-report"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -developer-empty-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-developer-empty-warning"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -marker-supply-low-report
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-marker-supply-low-report"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -marker-supply-empty-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-marker-supply-empty-warning"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -opc-near-eol-report
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-opc-near-eol-report"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -opc-life-over-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-opc-life-over-warning"
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -toner-low-report
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-toner-low-report"
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -toner-empty-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-toner-empty-warning"
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -waste-receptacle-almost-full-report
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-waste-receptacle-almost-full-report"
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -waste-receptacle-full-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-waste-receptacle-full-warning"
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -cleaner-life-almost-over-report
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-cleaner-life-almost-over-report"
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -cleaner-life-over-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-cleaner-life-over-warning"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] new_state=0, change_state=ffff
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -media-empty-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-media-empty-warning"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -door-open-report
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-door-open-report"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -media-jam-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-media-jam-warning"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -input-tray-missing-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-input-tray-missing-warning"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -output-tray-missing-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-output-tray-missing-warning"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -marker-supply-missing-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-marker-supply-missing-warning"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -output-area-almost-full-report
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-output-area-almost-full-report"
D [21/Sep/2017:12:02:11 +0900] [Job 18] STATE: -output-area-full-warning
d [21/Sep/2017:12:02:11 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-output-area-full-warning"
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] backendWaitLoop(snmp_fd=6, addr=0x55ebdd7e2a58, side_cb=0x55ebdb642350)
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Page = 595x842; 14,14 to 581,828
D [21/Sep/2017:12:02:11 +0900] [Job 18] slow_collate=0, slow_duplex=0, slow_order=0
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Before copy_comments - %!PS-Adobe-3.0
D [21/Sep/2017:12:02:11 +0900] [Job 18] %!PS-Adobe-3.0
D [21/Sep/2017:12:02:11 +0900] [Job 18] %%BoundingBox: 0 0 595 842
D [21/Sep/2017:12:02:11 +0900] [Job 18] %%HiResBoundingBox: 0 0 595.00 842.00
D [21/Sep/2017:12:02:11 +0900] [Job 18] %%Creator: GPL Ghostscript 921 (ps2write)
D [21/Sep/2017:12:02:11 +0900] [Job 18] %%LanguageLevel: 2
D [21/Sep/2017:12:02:11 +0900] [Job 18] %%CreationDate: D:20170921120211+09\'00\'
D [21/Sep/2017:12:02:11 +0900] [Job 18] %%Pages: 1
D [21/Sep/2017:12:02:11 +0900] [Job 18] %%EndComments
D [21/Sep/2017:12:02:11 +0900] [Job 18] Before copy_prolog - %%BeginProlog
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Before copy_setup - %%Page: 1 1
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Before page loop - %%Page: 1 1
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] Copying page 1...
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] pagew = 566.9, pagel = 813.5
D [21/Sep/2017:12:02:11 +0900] [Job 18] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [21/Sep/2017:12:02:11 +0900] [Job 18] PageLeft = 14.2, PageRight = 581.1
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] PageTop = 827.8, PageBottom = 14.3
D [21/Sep/2017:12:02:11 +0900] [Job 18] PageWidth = 595.0, PageLength = 842.0
D [21/Sep/2017:12:02:11 +0900] [Job 18] Wrote 1 pages...
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] PID 2085 (gs) exited with no errors.
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] PID 2086 (pstops) exited with no errors.
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] process_children()
d [21/Sep/2017:12:02:11 +0900] cupsdFinishProcess(pid=2082, name=0x7ffda9bf0d20, namelen=1024, job_id=0x7ffda9bf0c08(18)) = "/usr/lib/cups/filter/pdftops"
D [21/Sep/2017:12:02:11 +0900] [Job 18] PID 2082 (/usr/lib/cups/filter/pdftops) exited with no errors.
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:11 +0900] select_timeout(-1): 1 seconds to delete stale local printers
D [21/Sep/2017:12:02:11 +0900] [Job 18] opvpOpenPrinter(410)
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] CStubOpenPrinter(349)
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] opvpOpenPrinter(410)
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:11 +0900] [Job 18] CStubOpenPrinter(349)
d [21/Sep/2017:12:02:11 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:12 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:12 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:13 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:13 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:14 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:14 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:15 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:15 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:16 +0900] [Job 18] prtMarkerSuppliesLevel.1.1 = 3888
d [21/Sep/2017:12:02:16 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:16 +0900] [Job 18] prtMarkerSuppliesLevel.1.2 = 1088
d [21/Sep/2017:12:02:16 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:16 +0900] [Job 18] prtMarkerSuppliesLevel.1.3 = 1088
d [21/Sep/2017:12:02:16 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:16 +0900] [Job 18] prtMarkerSuppliesLevel.1.4 = 680
d [21/Sep/2017:12:02:16 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:16 +0900] [Job 18] prtMarkerSuppliesLevel.1.5 = -2
d [21/Sep/2017:12:02:16 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:16 +0900] [Job 18] ATTR: marker-levels=72,64,64,40,-1
D [21/Sep/2017:12:02:16 +0900] cupsdMarkDirty(P----)
D [21/Sep/2017:12:02:16 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:12:02:16 +0900] [Job 18] new_supply_state=0, change_state=0
d [21/Sep/2017:12:02:16 +0900] cupsdAddEvent(event=printer-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=(nil)(0), text="Printer \"%s\" state changed.", ...)
D [21/Sep/2017:12:02:16 +0900] Discarding unused printer-state-changed event...
d [21/Sep/2017:12:02:16 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:16 +0900] [Job 18] new_state=0, change_state=0
d [21/Sep/2017:12:02:16 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:17 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:17 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:18 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:18 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:19 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:19 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:20 +0900] cupsdCheckJobs: 1 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1505962940
d [21/Sep/2017:12:02:20 +0900] cupsdCheckJobs: Job 18 - dest="Canon_iR_C2550", printer=0x564bdf93d830, state=5, cancel_time=1505973731, hold_until=1505963230, kill_time=0, pending_cost=0, pending_timeout=0
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:20 +0900] select_timeout(0): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:20 +0900] cupsdAcceptClient(lis=0x564bdf91d5c0(3)) Clients=1
D [21/Sep/2017:12:02:20 +0900] [Client 91] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:12:02:20 +0900] [Client 91] Accepted from localhost (Domain)
d [21/Sep/2017:12:02:20 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:20 +0900] [Client 91] Waiting for request.
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:20 +0900] [Client 91] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:20 +0900] [Client 91] POST / HTTP/1.1
D [21/Sep/2017:12:02:20 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:12:02:20 +0900] [Client 91] Read: status=200, state=6
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: uri="/", limit=10...
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: Location /admin/log(10) Limit 7f
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: Location /admin(6) Limit 7f
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: Location /(1) Limit 7f
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: best=/
d [21/Sep/2017:12:02:20 +0900] [Client 91] con->uri="/", con->best=0x564bdf91d6e0(/)
D [21/Sep/2017:12:02:20 +0900] [Client 91] No authentication data provided.
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: con->uri="/", con->best=0x564bdf91d6e0(/)
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:20 +0900] [Client 91] 2.0 Get-Printer-Attributes 1
d [21/Sep/2017:12:02:20 +0900] cupsdProcessIPPRequest(0x564bdfa4d310[91]): operation_id = 000b
D [21/Sep/2017:12:02:20 +0900] Get-Printer-Attributes ipp://localhost:631/printers/Canon_iR_C2550
d [21/Sep/2017:12:02:20 +0900] get_printer_attrs(0x564bdfa4d310[91], ipp://localhost:631/printers/Canon_iR_C2550)
d [21/Sep/2017:12:02:20 +0900] cupsdFindPolicyOp(p=0x564bdf91dec0, op=b(Get-Printer-Attributes))
d [21/Sep/2017:12:02:20 +0900] cupsdFindPolicyOp: Found wildcard match...
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: con->uri="/", con->best=0x564bdf922380((null))
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: op=0(0x0000)
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
d [21/Sep/2017:12:02:20 +0900] add_printer_state_reasons(0x564bdfa4d310[91], 0x564bdf93d830[Canon_iR_C2550])
d [21/Sep/2017:12:02:20 +0900] printer-uri-supported="ipp://localhost/printers/Canon_iR_C2550"
d [21/Sep/2017:12:02:20 +0900] copy_attrs(to=0x564bdfa3cba0, from=0x564bdf930af0, ra=0x564bdfa2c280, group=0, quickcopy=0)
d [21/Sep/2017:12:02:20 +0900] copy_attrs(to=0x564bdfa3cba0, from=0x564bdf9663d0, ra=0x564bdfa2c280, group=0, quickcopy=0)
d [21/Sep/2017:12:02:20 +0900] copy_attrs(to=0x564bdfa3cba0, from=0x564bdf93d280, ra=0x564bdfa2c280, group=0, quickcopy=-2147483648)
D [21/Sep/2017:12:02:20 +0900] [Client 91] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:12:02:20 +0900] [Client 91] Content-Length: 1487
D [21/Sep/2017:12:02:20 +0900] [Client 91] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [21/Sep/2017:12:02:20 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=0x564bde92d9d0, data=0x564bdfa4d310)
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:20 +0900] [Client 91] con->http=0x564bdfa42cd0
D [21/Sep/2017:12:02:20 +0900] [Client 91] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x564bdfa3cba0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:12:02:20 +0900] [Client 91] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:12:02:20 +0900] [Client 91] bytes=0, http_state=0, data_remaining=1487
D [21/Sep/2017:12:02:20 +0900] [Client 91] Flushing write buffer.
D [21/Sep/2017:12:02:20 +0900] [Client 91] New state is HTTP_STATE_WAITING
d [21/Sep/2017:12:02:20 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:20 +0900] [Client 91] Waiting for request.
D [21/Sep/2017:12:02:20 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:20 +0900] [Client 91] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:20 +0900] [Client 91] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:12:02:20 +0900] [Client 91] Closing connection.
D [21/Sep/2017:12:02:20 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [21/Sep/2017:12:02:20 +0900] cupsdRemoveSelect(fd=13)
d [21/Sep/2017:12:02:20 +0900] cupsdRemoveSelect(fd=-1)
d [21/Sep/2017:12:02:20 +0900] cupsdAcceptClient(lis=0x564bdf91d5c0(3)) Clients=1
D [21/Sep/2017:12:02:20 +0900] [Client 92] Server address is "/run/cups/cups.sock".
D [21/Sep/2017:12:02:20 +0900] [Client 92] Accepted from localhost (Domain)
d [21/Sep/2017:12:02:20 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:20 +0900] [Client 92] Waiting for request.
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:20 +0900] [Client 92] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:20 +0900] [Client 92] POST /jobs/ HTTP/1.1
D [21/Sep/2017:12:02:20 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [21/Sep/2017:12:02:20 +0900] [Client 92] Read: status=200, state=6
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: uri="/jobs", limit=10...
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: Location /admin/log(10) Limit 7f
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: Location /admin/conf(11) Limit 7f
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: Location /admin(6) Limit 7f
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: Location /(1) Limit 7f
d [21/Sep/2017:12:02:20 +0900] cupsdFindBest: best=/
d [21/Sep/2017:12:02:20 +0900] [Client 92] con->uri="/jobs/", con->best=0x564bdf91d6e0(/)
D [21/Sep/2017:12:02:20 +0900] [Client 92] No authentication data provided.
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: con->uri="/jobs/", con->best=0x564bdf91d6e0(/)
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_ANON, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=0
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:20 +0900] [Client 92] 2.0 Cancel-Job 2
d [21/Sep/2017:12:02:20 +0900] cupsdProcessIPPRequest(0x564bdfa4d310[92]): operation_id = 0008
D [21/Sep/2017:12:02:20 +0900] Cancel-Job ipp://localhost:631/printers/Canon_iR_C2550
d [21/Sep/2017:12:02:20 +0900] cancel_job(0x564bdfa4d310[92], ipp://localhost:631/printers/Canon_iR_C2550)
d [21/Sep/2017:12:02:20 +0900] validate_user(job=18, con=92, owner="fukuokasoichiro", username=0x7ffda9be2c20, userlen=1024)
d [21/Sep/2017:12:02:20 +0900] cupsdFindPolicyOp(p=0x564bdf91dec0, op=8(Cancel-Job))
d [21/Sep/2017:12:02:20 +0900] cupsdFindPolicyOp: Found exact match...
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: con->uri="/jobs/", con->best=0x564bdf922090((null))
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: owner="fukuokasoichiro"
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: level=CUPSD_AUTH_USER, type=None, satisfy=CUPSD_AUTH_SATISFY_ALL, num_names=2
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: op=8(Cancel-Job)
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: auth=CUPSD_AUTH_ALLOW...
D [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: requesting-user-name="fukuokasoichiro"
d [21/Sep/2017:12:02:20 +0900] cupsdIsAuthorized: Checking user membership...
d [21/Sep/2017:12:02:20 +0900] cupsdSetJobState(job=0x564bdfa3f9a0(18), state=5, newstate=7, action=0, message="Job canceled by \"%s\"")
d [21/Sep/2017:12:02:20 +0900] stop_job(job=0x564bdfa3f9a0(18), action=0)
d [21/Sep/2017:12:02:20 +0900] cupsdEndProcess(pid=2083, force=0)
d [21/Sep/2017:12:02:20 +0900] cupsdEndProcess(pid=2084, force=0)
D [21/Sep/2017:12:02:20 +0900] [Job 18] time-at-completed=1505962940
d [21/Sep/2017:12:02:20 +0900] set_time: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:20 +0900] cupsdAddEvent(event=job-completed, dest=0x564bdf93d830(Canon_iR_C2550), job=0x564bdfa3f9a0(18), text="%s", ...)
D [21/Sep/2017:12:02:20 +0900] Discarding unused job-completed event...
I [21/Sep/2017:12:02:20 +0900] [Job 18] Job canceled by \"fukuokasoichiro\"
I [21/Sep/2017:12:02:20 +0900] Expiring subscriptions...
D [21/Sep/2017:12:02:20 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:12:02:20 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [21/Sep/2017:12:02:20 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
d [21/Sep/2017:12:02:20 +0900] cupsdCheckJobs: 1 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1505962940
d [21/Sep/2017:12:02:20 +0900] cupsdCheckJobs: Job 18 - dest="Canon_iR_C2550", printer=0x564bdf93d830, state=7, cancel_time=1505973731, hold_until=1505963230, kill_time=1505963240, pending_cost=0, pending_timeout=0
I [21/Sep/2017:12:02:20 +0900] [Job 18] Canceled by "fukuokasoichiro".
D [21/Sep/2017:12:02:20 +0900] [Client 92] Returning IPP successful-ok for Cancel-Job (ipp://localhost:631/printers/Canon_iR_C2550) from localhost
D [21/Sep/2017:12:02:20 +0900] [Client 92] Content-Length: 75
D [21/Sep/2017:12:02:20 +0900] [Client 92] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
d [21/Sep/2017:12:02:20 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=0x564bde92d9d0, data=0x564bdfa4d310)
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
D [21/Sep/2017:12:02:20 +0900] [Client 92] con->http=0x564bdfa42cd0
D [21/Sep/2017:12:02:20 +0900] [Client 92] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x564bdf92e8c0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [21/Sep/2017:12:02:20 +0900] [Client 92] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [21/Sep/2017:12:02:20 +0900] [Client 92] bytes=0, http_state=0, data_remaining=75
D [21/Sep/2017:12:02:20 +0900] [Client 92] Flushing write buffer.
D [21/Sep/2017:12:02:20 +0900] [Client 92] New state is HTTP_STATE_WAITING
d [21/Sep/2017:12:02:20 +0900] cupsdAddSelect(fd=13, read_cb=0x564bde92e370, write_cb=(nil), data=0x564bdfa4d310)
D [21/Sep/2017:12:02:20 +0900] [Client 92] Waiting for request.
D [21/Sep/2017:12:02:20 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:20 +0900] process_children()
d [21/Sep/2017:12:02:20 +0900] cupsdFinishProcess(pid=2083, name=0x7ffda9bf0d20, namelen=1024, job_id=0x7ffda9bf0c08(18)) = "/usr/lib/cups/filter/pstoufr2cpca"
D [21/Sep/2017:12:02:20 +0900] [Job 18] PID 2083 (/usr/lib/cups/filter/pstoufr2cpca) exited with no errors.
d [21/Sep/2017:12:02:20 +0900] cupsdFinishProcess(pid=2084, name=0x7ffda9bf0d20, namelen=1024, job_id=0x7ffda9bf0c08(18)) = "/usr/lib/cups/backend/socket"
D [21/Sep/2017:12:02:20 +0900] [Job 18] PID 2084 (/usr/lib/cups/backend/socket) was terminated normally with signal 15.
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:20 +0900] select_timeout(-1): 1 seconds to delete stale local printers
d [21/Sep/2017:12:02:20 +0900] [Client 92] cupsdReadClient: error=0, used=0, state=HTTP_STATE_WAITING, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=0, request=(nil)(), file=-1
D [21/Sep/2017:12:02:20 +0900] [Client 92] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [21/Sep/2017:12:02:20 +0900] [Client 92] Closing connection.
D [21/Sep/2017:12:02:20 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [21/Sep/2017:12:02:20 +0900] cupsdRemoveSelect(fd=13)
d [21/Sep/2017:12:02:20 +0900] cupsdRemoveSelect(fd=-1)
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:20 +0900] finalize_job(job=0x564bdfa3f9a0(18))
d [21/Sep/2017:12:02:20 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-connecting-to-device,cups-waiting-for-job-completed,cups-remote-pending,cups-remote-pending-held,cups-remote-processing,cups-remote-stopped,cups-remote-canceled,cups-remote-aborted,cups-remote-completed"
d [21/Sep/2017:12:02:20 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-offline-report"
d [21/Sep/2017:12:02:20 +0900] cupsdDeleteProfile(profile="(null)")
d [21/Sep/2017:12:02:20 +0900] cupsdDeleteProfile(profile="(null)")
d [21/Sep/2017:12:02:20 +0900] cupsdRemoveSelect(fd=14)
d [21/Sep/2017:12:02:20 +0900] cupsdAddEvent(event=printer-state-changed, dest=0x564bdf93d830(Canon_iR_C2550), job=(nil)(0), text="%s \"%s\" state changed to %s.", ...)
D [21/Sep/2017:12:02:20 +0900] Discarding unused printer-state-changed event...
d [21/Sep/2017:12:02:20 +0900] cupsdSetPrinterReasons(p=0x564bdf93d830(Canon_iR_C2550),s="-paused"
D [21/Sep/2017:12:02:20 +0900] cupsdMarkDirty(---J-)
D [21/Sep/2017:12:02:20 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
d [21/Sep/2017:12:02:20 +0900] cupsdCheckJobs: 0 active jobs, sleeping=0, ac-power=-1, reload=0, curtime=1505962940
d [21/Sep/2017:12:02:20 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:21 +0900] cupsdSaveJob(job=0x564bdfa3f9a0(18)): job->attrs=0x564bdfa2f6c0
D [21/Sep/2017:12:02:21 +0900] [Job 18] Unloading...
d [21/Sep/2017:12:02:21 +0900] select_timeout: JobHistoryUpdate=1506048964
d [21/Sep/2017:12:02:21 +0900] select_timeout(0): 1 seconds to delete stale local printers

I wonder "HTTP_STATE_WAITING Closing for error 32 (Broken pipe)" might be related to the issue.

When it comes to the Ubuntu page, I just followed it hoping I could find out something. No particular reason. I've refered to Official Arch CUPS Wiki too.

Offline

#4 2017-09-21 10:12:27

Lone_Wolf
Member
From: Netherlands, Europe
Registered: 2005-10-04
Posts: 11,848

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

ewab,

the cndrvcups-lb-bin package is currently oprhaned and doesn't list the libjpeg6-turbo dependency that was recently found to be needed for certain printers.
Please try with my cndrvcups-common-lb / cndrvcups-lb packages (you need both of them).


Disliking systemd intensely, but not satisfied with alternatives so focusing on taming systemd.


(A works at time B)  && (time C > time B ) ≠  (A works at time C)

Offline

#5 2017-09-22 01:32:56

ewab
Member
From: Japan
Registered: 2017-04-28
Posts: 9

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

Lone_Wolf, thank you for your advice.

It's unbelievable to receive an advice from you yourself.

Actually, I have  tried the cndrvcups-common-lb and the cndrvcups-lb packages. My printer had been working perfectly with your packages before. So I installed your packages first when I reinstalled Arch 2 weeks ago. But it didn't work. This morning I uninstalled the cndrvcups-lb-bin and installed your packages again, but the result was same...

I added libjpeg6-turbo or/and lib32-libjpeg6-turbo, or installed them before your packages, but I can't see any changes.

Offline

#6 2017-09-22 16:54:17

Lone_Wolf
Member
From: Netherlands, Europe
Registered: 2005-10-04
Posts: 11,848

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

Keep in mind i'm just another arch linux user.
While i'm fortunate enough to no longer have to use canon printers under linux, they are a challenge to get to work.

Could you try clearing / moving the error.log file, then issue 1 command to print something and share that log ?

Are you using the printer over network or usb ?


Disliking systemd intensely, but not satisfied with alternatives so focusing on taming systemd.


(A works at time B)  && (time C > time B ) ≠  (A works at time C)

Offline

#7 2017-09-23 09:26:01

ewab
Member
From: Japan
Registered: 2017-04-28
Posts: 9

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

Lone_Wolf,

Thanks. The PC is in my office. I'm gonna try it Monday.

Offline

#8 2017-09-25 01:10:58

ewab
Member
From: Japan
Registered: 2017-04-28
Posts: 9

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

Lone_Wolf,

I've done it. I moved the error_log file, restarted cups service, printed a text file from terminal, and cancelled the job.

I'm using the printer over network.

I noticed that "PID xxxxx (/usr/lib/cups/filter/pstoufr2cpca) exited with no errors." message doesn't appear until I cancell a print job. It means the printing process stalls in applying the pstoufr2cpca filter?

Thank you for your help.

D [25/Sep/2017:09:36:46 +0900] Creating keep-alive file "/var/cache/cups/org.cups.cupsd".
I [25/Sep/2017:09:36:46 +0900] Saving job.cache...
D [25/Sep/2017:09:36:46 +0900] cupsdStopSelect()
I [25/Sep/2017:09:36:46 +0900] Listening to [v1.::1]:631 (IPv6)
I [25/Sep/2017:09:36:46 +0900] Listening to 127.0.0.1:631 (IPv4)
I [25/Sep/2017:09:36:46 +0900] Listening to /run/cups/cups.sock (Domain)
I [25/Sep/2017:09:36:46 +0900] Remote access is disabled.
D [25/Sep/2017:09:36:46 +0900] Added auto ServerAlias archlinux
I [25/Sep/2017:09:36:46 +0900] Loaded configuration file "/etc/cups/cupsd.conf"
D [25/Sep/2017:09:36:46 +0900] Using keychain "/etc/cups/ssl" for server name "archlinux".
I [25/Sep/2017:09:36:46 +0900] Using default TempDir of /var/spool/cups/tmp...
I [25/Sep/2017:09:36:46 +0900] Configured for up to 100 clients.
I [25/Sep/2017:09:36:46 +0900] Allowing up to 100 client connections per host.
I [25/Sep/2017:09:36:46 +0900] Using policy "default" as the default.
I [25/Sep/2017:09:36:46 +0900] Full reload is required.
I [25/Sep/2017:09:36:46 +0900] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 44 types, 81 filters...
D [25/Sep/2017:09:36:46 +0900] Loading printer Canon_iR_C2550...
D [25/Sep/2017:09:36:46 +0900] load_ppd: Loading /var/cache/cups/Canon_iR_C2550.data...
D [25/Sep/2017:09:36:46 +0900] cupsdRegisterPrinter(p=0x560dfce367f0(Canon_iR_C2550))
D [25/Sep/2017:09:36:46 +0900] load_ppd: Loading /var/cache/cups/Canon_iR_C2550.data...
D [25/Sep/2017:09:36:46 +0900] cupsdRegisterPrinter(p=0x560dfce367f0(Canon_iR_C2550))
I [25/Sep/2017:09:36:46 +0900] Loading job cache file "/var/cache/cups/job.cache"...
D [25/Sep/2017:09:36:46 +0900] [Job 15] Loading from cache...
D [25/Sep/2017:09:36:46 +0900] [Job 16] Loading from cache...
D [25/Sep/2017:09:36:46 +0900] [Job 16] Loading attributes...
D [25/Sep/2017:09:36:46 +0900] [Job 16] Unloading...
I [25/Sep/2017:09:36:46 +0900] Full reload complete.
D [25/Sep/2017:09:36:46 +0900] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)")
I [25/Sep/2017:09:36:46 +0900] Cleaning out old files in "/var/spool/cups/tmp".
D [25/Sep/2017:09:36:46 +0900] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp")
I [25/Sep/2017:09:36:46 +0900] Cleaning out old files in "/var/cache/cups".
D [25/Sep/2017:09:36:46 +0900] service_checkin: pid=30762
D [25/Sep/2017:09:36:46 +0900] service_checkin: 0 listeners.
D [25/Sep/2017:09:36:46 +0900] Creating keep-alive file "/var/cache/cups/org.cups.cupsd".
D [25/Sep/2017:09:36:46 +0900] Calling FindDeviceById(cups-Canon_iR_C2550)
D [25/Sep/2017:09:36:46 +0900] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-Canon_iR_C2550\' does not exist
D [25/Sep/2017:09:36:46 +0900] Using profile ID "Canon_iR_C2550-Gray..".
D [25/Sep/2017:09:36:46 +0900] Calling CreateProfile(Canon_iR_C2550-Gray..,temp)
D [25/Sep/2017:09:36:46 +0900] Created profile "/org/freedesktop/ColorManager/profiles/Canon_iR_C2550_Gray__".
D [25/Sep/2017:09:36:46 +0900] Using profile ID "Canon_iR_C2550-RGB..".
D [25/Sep/2017:09:36:46 +0900] Calling CreateProfile(Canon_iR_C2550-RGB..,temp)
D [25/Sep/2017:09:36:46 +0900] Created profile "/org/freedesktop/ColorManager/profiles/Canon_iR_C2550_RGB__".
I [25/Sep/2017:09:36:46 +0900] Registering ICC color profiles for "Canon_iR_C2550".
D [25/Sep/2017:09:36:46 +0900] Calling CreateDevice(cups-Canon_iR_C2550,temp)
D [25/Sep/2017:09:36:46 +0900] Created device "/org/freedesktop/ColorManager/devices/cups_Canon_iR_C2550".
D [25/Sep/2017:09:36:46 +0900] Calling /org/freedesktop/ColorManager/devices/cups_Canon_iR_C2550:AddProfile(/org/freedesktop/ColorManager/profiles/Canon_iR_C2550_Gray__) [soft]
D [25/Sep/2017:09:36:46 +0900] Calling /org/freedesktop/ColorManager/devices/cups_Canon_iR_C2550:AddProfile(/org/freedesktop/ColorManager/profiles/Canon_iR_C2550_RGB__) [soft]
I [25/Sep/2017:09:36:46 +0900] Listening to [v1.::1]:631 on fd 7...
I [25/Sep/2017:09:36:46 +0900] Listening to 127.0.0.1:631 on fd 8...
I [25/Sep/2017:09:36:46 +0900] Listening to /run/cups/cups.sock on fd 9...
I [25/Sep/2017:09:36:46 +0900] Resuming new connection processing...
D [25/Sep/2017:09:36:46 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [25/Sep/2017:09:36:46 +0900] cupsdAddCert: Adding certificate for PID 0
D [25/Sep/2017:09:36:46 +0900] Discarding unused server-started event...
D [25/Sep/2017:09:36:47 +0900] Report: clients=0
D [25/Sep/2017:09:36:47 +0900] Report: jobs=2
D [25/Sep/2017:09:36:47 +0900] Report: jobs-active=0
D [25/Sep/2017:09:36:47 +0900] Report: printers=1
D [25/Sep/2017:09:36:47 +0900] Report: stringpool-string-count=7190
D [25/Sep/2017:09:36:47 +0900] Report: stringpool-alloc-bytes=8440
D [25/Sep/2017:09:36:47 +0900] Report: stringpool-total-bytes=128152
D [25/Sep/2017:09:37:02 +0900] [Client 1] Server address is "/run/cups/cups.sock".
D [25/Sep/2017:09:37:02 +0900] [Client 1] Accepted from localhost (Domain)
D [25/Sep/2017:09:37:02 +0900] [Client 1] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] [Client 1] POST / HTTP/1.1
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [25/Sep/2017:09:37:02 +0900] [Client 1] Read: status=200, state=6
D [25/Sep/2017:09:37:02 +0900] [Client 1] No authentication data provided.
D [25/Sep/2017:09:37:02 +0900] [Client 1] 2.0 Get-Printer-Attributes 1
D [25/Sep/2017:09:37:02 +0900] Get-Printer-Attributes ipp://localhost:631/printers/Canon_ir_C2550
D [25/Sep/2017:09:37:02 +0900] [Client 1] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/Canon_ir_C2550) from localhost
D [25/Sep/2017:09:37:02 +0900] [Client 1] Content-Length: 1487
D [25/Sep/2017:09:37:02 +0900] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [25/Sep/2017:09:37:02 +0900] [Client 1] con->http=0x560dfcef52b0
D [25/Sep/2017:09:37:02 +0900] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x560dfcee89f0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [25/Sep/2017:09:37:02 +0900] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Sep/2017:09:37:02 +0900] [Client 1] bytes=0, http_state=0, data_remaining=1487
D [25/Sep/2017:09:37:02 +0900] [Client 1] Flushing write buffer.
D [25/Sep/2017:09:37:02 +0900] [Client 1] New state is HTTP_STATE_WAITING
D [25/Sep/2017:09:37:02 +0900] [Client 1] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [25/Sep/2017:09:37:02 +0900] [Client 1] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Sep/2017:09:37:02 +0900] [Client 1] Closing connection.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [25/Sep/2017:09:37:02 +0900] [Client 2] Server address is "/run/cups/cups.sock".
D [25/Sep/2017:09:37:02 +0900] [Client 2] Accepted from localhost (Domain)
D [25/Sep/2017:09:37:02 +0900] [Client 2] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] [Client 2] POST / HTTP/1.1
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [25/Sep/2017:09:37:02 +0900] [Client 2] Read: status=200, state=6
D [25/Sep/2017:09:37:02 +0900] [Client 2] No authentication data provided.
D [25/Sep/2017:09:37:02 +0900] [Client 2] 2.0 CUPS-Get-Printers 2
D [25/Sep/2017:09:37:02 +0900] CUPS-Get-Printers
D [25/Sep/2017:09:37:02 +0900] [Client 2] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [25/Sep/2017:09:37:02 +0900] [Client 2] Content-Length: 1487
D [25/Sep/2017:09:37:02 +0900] [Client 2] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [25/Sep/2017:09:37:02 +0900] [Client 2] con->http=0x560dfcef52b0
D [25/Sep/2017:09:37:02 +0900] [Client 2] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x560dfcee6070(IPP_STATE_DATA), pipe_pid=0, file=-1
D [25/Sep/2017:09:37:02 +0900] [Client 2] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Sep/2017:09:37:02 +0900] [Client 2] bytes=0, http_state=0, data_remaining=1487
D [25/Sep/2017:09:37:02 +0900] [Client 2] Flushing write buffer.
D [25/Sep/2017:09:37:02 +0900] [Client 2] New state is HTTP_STATE_WAITING
D [25/Sep/2017:09:37:02 +0900] [Client 2] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [25/Sep/2017:09:37:02 +0900] [Client 2] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Sep/2017:09:37:02 +0900] [Client 2] Closing connection.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [25/Sep/2017:09:37:02 +0900] [Client 3] Server address is "/run/cups/cups.sock".
D [25/Sep/2017:09:37:02 +0900] [Client 3] Accepted from localhost (Domain)
D [25/Sep/2017:09:37:02 +0900] [Client 3] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] [Client 3] POST / HTTP/1.1
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [25/Sep/2017:09:37:02 +0900] [Client 3] Read: status=200, state=6
D [25/Sep/2017:09:37:02 +0900] [Client 3] No authentication data provided.
D [25/Sep/2017:09:37:02 +0900] [Client 3] 2.0 CUPS-Get-Default 3
D [25/Sep/2017:09:37:02 +0900] CUPS-Get-Default
D [25/Sep/2017:09:37:02 +0900] CUPS-Get-Default client-error-not-found: No default printer.
D [25/Sep/2017:09:37:02 +0900] [Client 3] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [25/Sep/2017:09:37:02 +0900] [Client 3] Content-Length: 113
D [25/Sep/2017:09:37:02 +0900] [Client 3] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [25/Sep/2017:09:37:02 +0900] [Client 3] con->http=0x560dfcef52b0
D [25/Sep/2017:09:37:02 +0900] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x560dfce4ddf0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [25/Sep/2017:09:37:02 +0900] [Client 3] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Sep/2017:09:37:02 +0900] [Client 3] bytes=0, http_state=0, data_remaining=113
D [25/Sep/2017:09:37:02 +0900] [Client 3] Flushing write buffer.
D [25/Sep/2017:09:37:02 +0900] [Client 3] New state is HTTP_STATE_WAITING
D [25/Sep/2017:09:37:02 +0900] [Client 3] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [25/Sep/2017:09:37:02 +0900] [Client 3] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Sep/2017:09:37:02 +0900] [Client 3] Closing connection.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [25/Sep/2017:09:37:02 +0900] [Client 4] Server address is "/run/cups/cups.sock".
D [25/Sep/2017:09:37:02 +0900] [Client 4] Accepted from localhost (Domain)
D [25/Sep/2017:09:37:02 +0900] [Client 4] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] [Client 4] POST /printers/Canon_iR_C2550 HTTP/1.1
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [25/Sep/2017:09:37:02 +0900] [Client 4] Read: status=200, state=6
D [25/Sep/2017:09:37:02 +0900] [Client 4] No authentication data provided.
D [25/Sep/2017:09:37:02 +0900] [Client 4] 2.0 Get-Printer-Attributes 4
D [25/Sep/2017:09:37:02 +0900] Get-Printer-Attributes ipp://localhost/printers/Canon_iR_C2550
D [25/Sep/2017:09:37:02 +0900] [Client 4] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/Canon_iR_C2550) from localhost
D [25/Sep/2017:09:37:02 +0900] [Client 4] Content-Length: 168533
D [25/Sep/2017:09:37:02 +0900] [Client 4] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [25/Sep/2017:09:37:02 +0900] [Client 4] con->http=0x560dfcef52b0
D [25/Sep/2017:09:37:02 +0900] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=168533, response=0x560dfcee4120(IPP_STATE_DATA), pipe_pid=0, file=-1
D [25/Sep/2017:09:37:02 +0900] [Client 4] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Sep/2017:09:37:02 +0900] [Client 4] bytes=0, http_state=0, data_remaining=168533
D [25/Sep/2017:09:37:02 +0900] [Client 4] Flushing write buffer.
D [25/Sep/2017:09:37:02 +0900] [Client 4] New state is HTTP_STATE_WAITING
D [25/Sep/2017:09:37:02 +0900] [Client 4] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [25/Sep/2017:09:37:02 +0900] [Client 4] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Sep/2017:09:37:02 +0900] [Client 4] Closing connection.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [25/Sep/2017:09:37:02 +0900] [Client 5] Server address is "/run/cups/cups.sock".
D [25/Sep/2017:09:37:02 +0900] [Client 5] Accepted from localhost (Domain)
D [25/Sep/2017:09:37:02 +0900] [Client 5] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] [Client 5] POST /printers/Canon_iR_C2550 HTTP/1.1
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [25/Sep/2017:09:37:02 +0900] [Client 5] Read: status=200, state=6
D [25/Sep/2017:09:37:02 +0900] [Client 5] No authentication data provided.
D [25/Sep/2017:09:37:02 +0900] [Client 5] 2.0 Create-Job 5
D [25/Sep/2017:09:37:02 +0900] Create-Job ipp://localhost/printers/Canon_iR_C2550
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(---J-)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [25/Sep/2017:09:37:02 +0900] add_job: requesting-user-name="ewab"
I [25/Sep/2017:09:37:02 +0900] [Job 17] Adding start banner page "none".
D [25/Sep/2017:09:37:02 +0900] Discarding unused job-created event...
I [25/Sep/2017:09:37:02 +0900] [Job 17] Queued on "Canon_iR_C2550" by "ewab".
D [25/Sep/2017:09:37:02 +0900] [Client 5] Returning IPP successful-ok for Create-Job (ipp://localhost/printers/Canon_iR_C2550) from localhost
D [25/Sep/2017:09:37:02 +0900] [Client 5] Content-Length: 200
D [25/Sep/2017:09:37:02 +0900] [Client 5] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [25/Sep/2017:09:37:02 +0900] [Client 5] con->http=0x560dfcef52b0
D [25/Sep/2017:09:37:02 +0900] [Client 5] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=200, response=0x560dfceeb9b0(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [25/Sep/2017:09:37:02 +0900] [Client 5] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Sep/2017:09:37:02 +0900] [Client 5] bytes=0, http_state=0, data_remaining=200
D [25/Sep/2017:09:37:02 +0900] [Client 5] Flushing write buffer.
D [25/Sep/2017:09:37:02 +0900] [Client 5] New state is HTTP_STATE_WAITING
D [25/Sep/2017:09:37:02 +0900] [Client 5] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [25/Sep/2017:09:37:02 +0900] [Client 5] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Sep/2017:09:37:02 +0900] [Client 5] Closing connection.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [25/Sep/2017:09:37:02 +0900] [Client 6] Server address is "/run/cups/cups.sock".
D [25/Sep/2017:09:37:02 +0900] [Client 6] Accepted from localhost (Domain)
D [25/Sep/2017:09:37:02 +0900] [Client 6] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] [Client 6] POST /printers/Canon_ir_C2550 HTTP/1.1
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [25/Sep/2017:09:37:02 +0900] [Client 6] Read: status=200, state=6
D [25/Sep/2017:09:37:02 +0900] [Client 6] No authentication data provided.
D [25/Sep/2017:09:37:02 +0900] [Client 6] 2.0 Send-Document 6
D [25/Sep/2017:09:37:02 +0900] Send-Document ipp://localhost:631/printers/Canon_ir_C2550
D [25/Sep/2017:09:37:02 +0900] cupsdIsAuthorized: requesting-user-name="ewab"
D [25/Sep/2017:09:37:02 +0900] [Job 17] Auto-typing file...
D [25/Sep/2017:09:37:02 +0900] [Job 17] Request file type is text/plain.
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(---J-)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [25/Sep/2017:09:37:02 +0900] [Job 17] File of type text/plain queued by "ewab".
I [25/Sep/2017:09:37:02 +0900] [Job 17] Adding end banner page "none".
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(---J-)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [25/Sep/2017:09:37:02 +0900] [Job 17] time-at-processing=1506299822
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(---J-)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [25/Sep/2017:09:37:02 +0900] Discarding unused printer-state-changed event...
D [25/Sep/2017:09:37:02 +0900] [Job 17] 4 filters for job:
D [25/Sep/2017:09:37:02 +0900] [Job 17] texttopdf (text/plain to application/pdf, cost 32)
D [25/Sep/2017:09:37:02 +0900] [Job 17] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [25/Sep/2017:09:37:02 +0900] [Job 17] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100)
D [25/Sep/2017:09:37:02 +0900] [Job 17] pstoufr2cpca (application/vnd.cups-postscript to printer/Canon_iR_C2550, cost 0)
D [25/Sep/2017:09:37:02 +0900] [Job 17] job-sheets=none,none
D [25/Sep/2017:09:37:02 +0900] [Job 17] argv[0]="Canon_iR_C2550"
D [25/Sep/2017:09:37:02 +0900] [Job 17] argv[1]="17"
D [25/Sep/2017:09:37:02 +0900] [Job 17] argv[2]="ewab"
D [25/Sep/2017:09:37:02 +0900] [Job 17] argv[3]="test.txt"
D [25/Sep/2017:09:37:02 +0900] [Job 17] argv[4]="1"
D [25/Sep/2017:09:37:02 +0900] [Job 17] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:41647a7e-2173-31a4-5952-6613c017a7f1 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1506299822 time-at-processing=1506299822 document-name-supplied=test.txt"
D [25/Sep/2017:09:37:02 +0900] [Job 17] argv[6]="/var/spool/cups/d00017-001"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[7]="CUPS_STATEDIR=/run/cups"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[8]="HOME=/var/spool/cups/tmp"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[10]="SERVER_ADMIN=root@archlinux"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[11]="SOFTWARE=CUPS/2.2.4"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[13]="USER=root"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[14]="CUPS_MAX_MESSAGE=2047"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[17]="IPP_PORT=631"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[18]="CHARSET=utf-8"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[19]="LANG=en_US.UTF-8"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[20]="PPD=/etc/cups/ppd/Canon_iR_C2550.ppd"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[21]="RIP_MAX_CACHE=128m"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[22]="CONTENT_TYPE=text/plain"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[23]="DEVICE_URI=socket://192.168.1.50"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[24]="PRINTER_INFO=Canon iR C2550 (LIPSLX)"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[25]="PRINTER_LOCATION="
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[26]="PRINTER=Canon_iR_C2550"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[27]="PRINTER_STATE_REASONS=none"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[28]="CUPS_FILETYPE=document"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
D [25/Sep/2017:09:37:02 +0900] [Job 17] envp[30]="AUTH_I****"
I [25/Sep/2017:09:37:02 +0900] [Job 17] Started filter /usr/lib/cups/filter/texttopdf (PID 30765)
I [25/Sep/2017:09:37:02 +0900] [Job 17] Started filter /usr/lib/cups/filter/pdftopdf (PID 30766)
I [25/Sep/2017:09:37:02 +0900] [Job 17] Started filter /usr/lib/cups/filter/pdftops (PID 30767)
I [25/Sep/2017:09:37:02 +0900] [Job 17] Started filter /usr/lib/cups/filter/pstoufr2cpca (PID 30768)
I [25/Sep/2017:09:37:02 +0900] [Job 17] Started backend /usr/lib/cups/backend/socket (PID 30769)
D [25/Sep/2017:09:37:02 +0900] Discarding unused job-state-changed event...
D [25/Sep/2017:09:37:02 +0900] [Client 6] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/Canon_ir_C2550) from localhost
D [25/Sep/2017:09:37:02 +0900] [Client 6] Content-Length: 170
D [25/Sep/2017:09:37:02 +0900] [Client 6] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [25/Sep/2017:09:37:02 +0900] [Client 6] con->http=0x560dfcef52b0
D [25/Sep/2017:09:37:02 +0900] [Client 6] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=170, response=0x560dfcf20020(IPP_STATE_DATA), pipe_pid=0, file=-1
D [25/Sep/2017:09:37:02 +0900] [Client 6] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Sep/2017:09:37:02 +0900] [Client 6] bytes=0, http_state=0, data_remaining=170
D [25/Sep/2017:09:37:02 +0900] [Client 6] Flushing write buffer.
D [25/Sep/2017:09:37:02 +0900] [Client 6] New state is HTTP_STATE_WAITING
D [25/Sep/2017:09:37:02 +0900] [Client 6] Waiting for request.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [25/Sep/2017:09:37:02 +0900] [Job 17] pstoufr2cpca start.
D [25/Sep/2017:09:37:02 +0900] [Job 17] pdftops - copying to temp print file \"/var/spool/cups/tmp/0782f59d34a8e\"
D [25/Sep/2017:09:37:02 +0900] [Job 17] pdftopdf: Last filter determined by the PPD: pstoufr2cpca; FINAL_CONTENT_TYPE: application/vnd.cups-postscript => pdftopdf will not log pages in page_log.
D [25/Sep/2017:09:37:02 +0900] [Client 6] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Sep/2017:09:37:02 +0900] [Client 6] Closing connection.
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:02 +0900] [Job 17] Page = 595x842; 14,14 to 581,828
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: +connecting-to-device
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(---J-)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:02 +0900] [Job 17] Looking up \"192.168.1.50\"...
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -connecting-to-device
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(---J-)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [25/Sep/2017:09:37:02 +0900] [Job 17] 192.168.1.50=192.168.1.50
D [25/Sep/2017:09:37:02 +0900] Discarding unused printer-state-changed event...
D [25/Sep/2017:09:37:02 +0900] [Job 17] PID 30765 (/usr/lib/cups/filter/texttopdf) exited with no errors.
D [25/Sep/2017:09:37:02 +0900] [Job 17] PID 30766 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [25/Sep/2017:09:37:02 +0900] [Job 17] Printer make and model: Canon ir c2550
D [25/Sep/2017:09:37:02 +0900] [Job 17] Running command line for pstops: pstops 17 ewab test.txt 1 \'finishings=3 job-uuid=urn:uuid:41647a7e-2173-31a4-5952-6613c017a7f1 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1506299822 time-at-processing=1506299822 document-name-supplied=test.txt\'
D [25/Sep/2017:09:37:02 +0900] [Job 17] Using image rendering resolution 600 dpi
D [25/Sep/2017:09:37:02 +0900] [Job 17] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r600 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c \'save pop\' -f /var/spool/cups/tmp/0782f59d34a8e
D [25/Sep/2017:09:37:02 +0900] [Job 17] Started filter gs (PID 30770)
D [25/Sep/2017:09:37:02 +0900] [Job 17] Started filter pstops (PID 30771)
D [25/Sep/2017:09:37:02 +0900] [Job 17] ATTR: marker-colors=#000000,#00FFFF,#FF00FF,#FFFF00,none
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(P----)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:02 +0900] [Job 17] ATTR: marker-names=\'\"NPG-35 Black Toner\"\',\'\"NPG-35 Cyan Toner\"\',\'\"NPG-35 Magenta Toner\"\',\'\"NPG-35 Yellow Toner\"\',\'\"Waste Toner\"\'
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(P----)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:02 +0900] [Job 17] ATTR: marker-types=toner,toner,toner,toner,waste-toner
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(P----)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:02 +0900] [Job 17] ATTR: marker-levels=72,64,64,40,-1
D [25/Sep/2017:09:37:02 +0900] cupsdMarkDirty(P----)
D [25/Sep/2017:09:37:02 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:02 +0900] [Job 17] new_supply_state=0, change_state=ffff
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -developer-low-report
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -developer-empty-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -marker-supply-low-report
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -marker-supply-empty-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -opc-near-eol-report
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -opc-life-over-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -toner-low-report
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -toner-empty-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -waste-receptacle-almost-full-report
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -waste-receptacle-full-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -cleaner-life-almost-over-report
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -cleaner-life-over-warning
D [25/Sep/2017:09:37:02 +0900] Discarding unused printer-state-changed event...
D [25/Sep/2017:09:37:02 +0900] [Job 17] new_state=0, change_state=ffff
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -media-empty-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -door-open-report
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -media-jam-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -input-tray-missing-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -output-tray-missing-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -marker-supply-missing-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -output-area-almost-full-report
D [25/Sep/2017:09:37:02 +0900] [Job 17] STATE: -output-area-full-warning
D [25/Sep/2017:09:37:02 +0900] [Job 17] backendWaitLoop(snmp_fd=5, addr=0x55b415f00a58, side_cb=0x55b413f48350)
D [25/Sep/2017:09:37:02 +0900] [Job 17] Page = 595x842; 14,14 to 581,828
D [25/Sep/2017:09:37:02 +0900] [Job 17] slow_collate=0, slow_duplex=0, slow_order=0
D [25/Sep/2017:09:37:02 +0900] [Job 17] Before copy_comments - %!PS-Adobe-3.0
D [25/Sep/2017:09:37:02 +0900] [Job 17] %!PS-Adobe-3.0
D [25/Sep/2017:09:37:02 +0900] [Job 17] %%BoundingBox: 0 0 595 842
D [25/Sep/2017:09:37:02 +0900] [Job 17] %%HiResBoundingBox: 0 0 595.00 842.00
D [25/Sep/2017:09:37:02 +0900] [Job 17] %%Creator: GPL Ghostscript 921 (ps2write)
D [25/Sep/2017:09:37:02 +0900] [Job 17] %%LanguageLevel: 2
D [25/Sep/2017:09:37:02 +0900] [Job 17] %%CreationDate: D:20170925093702+09\'00\'
D [25/Sep/2017:09:37:02 +0900] [Job 17] %%Pages: 1
D [25/Sep/2017:09:37:02 +0900] [Job 17] %%EndComments
D [25/Sep/2017:09:37:02 +0900] [Job 17] Before copy_prolog - %%BeginProlog
D [25/Sep/2017:09:37:02 +0900] [Job 17] Before copy_setup - %%Page: 1 1
D [25/Sep/2017:09:37:02 +0900] [Job 17] Before page loop - %%Page: 1 1
D [25/Sep/2017:09:37:02 +0900] [Job 17] Copying page 1...
D [25/Sep/2017:09:37:02 +0900] [Job 17] pagew = 566.9, pagel = 813.5
D [25/Sep/2017:09:37:02 +0900] [Job 17] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [25/Sep/2017:09:37:02 +0900] [Job 17] PageLeft = 14.2, PageRight = 581.1
D [25/Sep/2017:09:37:02 +0900] [Job 17] PageTop = 827.8, PageBottom = 14.3
D [25/Sep/2017:09:37:02 +0900] [Job 17] PageWidth = 595.0, PageLength = 842.0
D [25/Sep/2017:09:37:02 +0900] [Job 17] Wrote 1 pages...
D [25/Sep/2017:09:37:02 +0900] [Job 17] PID 30771 (pstops) exited with no errors.
D [25/Sep/2017:09:37:02 +0900] [Job 17] PID 30770 (gs) exited with no errors.
D [25/Sep/2017:09:37:02 +0900] [Job 17] PID 30767 (/usr/lib/cups/filter/pdftops) exited with no errors.
D [25/Sep/2017:09:37:02 +0900] [Job 17] opvpOpenPrinter(410)
D [25/Sep/2017:09:37:02 +0900] [Job 17] CStubOpenPrinter(349)
D [25/Sep/2017:09:37:02 +0900] [Job 17] opvpOpenPrinter(410)
D [25/Sep/2017:09:37:03 +0900] [Job 17] CStubOpenPrinter(349)
D [25/Sep/2017:09:37:07 +0900] [Job 17] ATTR: marker-levels=71,64,64,40,-1
D [25/Sep/2017:09:37:07 +0900] cupsdMarkDirty(P----)
D [25/Sep/2017:09:37:07 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:07 +0900] [Job 17] new_supply_state=0, change_state=0
D [25/Sep/2017:09:37:07 +0900] Discarding unused printer-state-changed event...
D [25/Sep/2017:09:37:07 +0900] [Job 17] new_state=0, change_state=0
D [25/Sep/2017:09:37:11 +0900] [Client 7] Server address is "/run/cups/cups.sock".
D [25/Sep/2017:09:37:11 +0900] [Client 7] Accepted from localhost (Domain)
D [25/Sep/2017:09:37:11 +0900] [Client 7] Waiting for request.
D [25/Sep/2017:09:37:11 +0900] [Client 7] POST / HTTP/1.1
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:11 +0900] [Client 7] Read: status=200, state=6
D [25/Sep/2017:09:37:11 +0900] [Client 7] No authentication data provided.
D [25/Sep/2017:09:37:11 +0900] [Client 7] 2.0 CUPS-Get-Default 1
D [25/Sep/2017:09:37:11 +0900] CUPS-Get-Default
D [25/Sep/2017:09:37:11 +0900] CUPS-Get-Default client-error-not-found: No default printer.
D [25/Sep/2017:09:37:11 +0900] [Client 7] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [25/Sep/2017:09:37:11 +0900] [Client 7] Content-Length: 113
D [25/Sep/2017:09:37:11 +0900] [Client 7] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [25/Sep/2017:09:37:11 +0900] [Client 7] con->http=0x560dfcef52b0
D [25/Sep/2017:09:37:11 +0900] [Client 7] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x560dfcef3360(IPP_STATE_DATA), pipe_pid=0, file=-1
D [25/Sep/2017:09:37:11 +0900] [Client 7] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Sep/2017:09:37:11 +0900] [Client 7] bytes=0, http_state=0, data_remaining=113
D [25/Sep/2017:09:37:11 +0900] [Client 7] Flushing write buffer.
D [25/Sep/2017:09:37:11 +0900] [Client 7] New state is HTTP_STATE_WAITING
D [25/Sep/2017:09:37:11 +0900] [Client 7] Waiting for request.
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [25/Sep/2017:09:37:11 +0900] [Client 7] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Sep/2017:09:37:11 +0900] [Client 7] Closing connection.
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:11 +0900] [Client 8] Server address is "/run/cups/cups.sock".
D [25/Sep/2017:09:37:11 +0900] [Client 8] Accepted from localhost (Domain)
D [25/Sep/2017:09:37:11 +0900] [Client 8] Waiting for request.
D [25/Sep/2017:09:37:11 +0900] [Client 8] POST / HTTP/1.1
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:11 +0900] [Client 8] Read: status=200, state=6
D [25/Sep/2017:09:37:11 +0900] [Client 8] No authentication data provided.
D [25/Sep/2017:09:37:11 +0900] [Client 8] 2.0 Get-Printer-Attributes 2
D [25/Sep/2017:09:37:11 +0900] Get-Printer-Attributes ipp://localhost:631/printers/Canon_ir_C2550
D [25/Sep/2017:09:37:11 +0900] [Client 8] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/Canon_ir_C2550) from localhost
D [25/Sep/2017:09:37:11 +0900] [Client 8] Content-Length: 1487
D [25/Sep/2017:09:37:11 +0900] [Client 8] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [25/Sep/2017:09:37:11 +0900] [Client 8] con->http=0x560dfcef52b0
D [25/Sep/2017:09:37:11 +0900] [Client 8] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1487, response=0x560dfce29080(IPP_STATE_DATA), pipe_pid=0, file=-1
D [25/Sep/2017:09:37:11 +0900] [Client 8] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Sep/2017:09:37:11 +0900] [Client 8] bytes=0, http_state=0, data_remaining=1487
D [25/Sep/2017:09:37:11 +0900] [Client 8] Flushing write buffer.
D [25/Sep/2017:09:37:11 +0900] [Client 8] New state is HTTP_STATE_WAITING
D [25/Sep/2017:09:37:11 +0900] [Client 8] Waiting for request.
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [25/Sep/2017:09:37:11 +0900] [Client 8] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Sep/2017:09:37:11 +0900] [Client 8] Closing connection.
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:11 +0900] [Client 9] Server address is "/run/cups/cups.sock".
D [25/Sep/2017:09:37:11 +0900] [Client 9] Accepted from localhost (Domain)
D [25/Sep/2017:09:37:11 +0900] [Client 9] Waiting for request.
D [25/Sep/2017:09:37:11 +0900] [Client 9] POST /jobs/ HTTP/1.1
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:11 +0900] [Client 9] Read: status=200, state=6
D [25/Sep/2017:09:37:11 +0900] [Client 9] No authentication data provided.
D [25/Sep/2017:09:37:11 +0900] [Client 9] 2.0 Cancel-Job 3
D [25/Sep/2017:09:37:11 +0900] Cancel-Job ipp://localhost:631/printers/Canon_ir_C2550
D [25/Sep/2017:09:37:11 +0900] cupsdIsAuthorized: requesting-user-name="ewab"
D [25/Sep/2017:09:37:11 +0900] [Job 17] time-at-completed=1506299831
D [25/Sep/2017:09:37:11 +0900] Discarding unused job-completed event...
I [25/Sep/2017:09:37:11 +0900] [Job 17] Job canceled by \"ewab\"
I [25/Sep/2017:09:37:11 +0900] Expiring subscriptions...
D [25/Sep/2017:09:37:11 +0900] cupsdMarkDirty(---J-)
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
I [25/Sep/2017:09:37:11 +0900] [Job 17] Canceled by "ewab".
D [25/Sep/2017:09:37:11 +0900] [Client 9] Returning IPP successful-ok for Cancel-Job (ipp://localhost:631/printers/Canon_ir_C2550) from localhost
D [25/Sep/2017:09:37:11 +0900] [Client 9] Content-Length: 75
D [25/Sep/2017:09:37:11 +0900] [Client 9] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [25/Sep/2017:09:37:11 +0900] [Client 9] con->http=0x560dfcef52b0
D [25/Sep/2017:09:37:11 +0900] [Client 9] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x560dfcef3300(IPP_STATE_DATA), pipe_pid=0, file=-1
D [25/Sep/2017:09:37:11 +0900] [Client 9] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [25/Sep/2017:09:37:11 +0900] [Client 9] bytes=0, http_state=0, data_remaining=75
D [25/Sep/2017:09:37:11 +0900] [Client 9] Flushing write buffer.
D [25/Sep/2017:09:37:11 +0900] [Client 9] New state is HTTP_STATE_WAITING
D [25/Sep/2017:09:37:11 +0900] [Client 9] Waiting for request.
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [25/Sep/2017:09:37:11 +0900] [Client 9] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [25/Sep/2017:09:37:11 +0900] [Client 9] Closing connection.
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:11 +0900] [Job 17] PID 30768 (/usr/lib/cups/filter/pstoufr2cpca) exited with no errors.
D [25/Sep/2017:09:37:11 +0900] [Job 17] PID 30769 (/usr/lib/cups/backend/socket) was terminated normally with signal 15.
D [25/Sep/2017:09:37:11 +0900] Discarding unused printer-state-changed event...
D [25/Sep/2017:09:37:11 +0900] cupsdMarkDirty(---J-)
D [25/Sep/2017:09:37:11 +0900] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:12 +0900] [Job 17] Unloading...
I [25/Sep/2017:09:37:33 +0900] Saving printers.conf...
I [25/Sep/2017:09:37:33 +0900] Saving job.cache...
D [25/Sep/2017:09:37:33 +0900] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files"
D [25/Sep/2017:09:37:47 +0900] Report: clients=0
D [25/Sep/2017:09:37:47 +0900] Report: jobs=3
D [25/Sep/2017:09:37:47 +0900] Report: jobs-active=0
D [25/Sep/2017:09:37:47 +0900] Report: printers=1
D [25/Sep/2017:09:37:47 +0900] Report: stringpool-string-count=7198
D [25/Sep/2017:09:37:47 +0900] Report: stringpool-alloc-bytes=8544
D [25/Sep/2017:09:37:47 +0900] Report: stringpool-total-bytes=128344
D [25/Sep/2017:09:38:47 +0900] Report: clients=0
D [25/Sep/2017:09:38:47 +0900] Report: jobs=3
D [25/Sep/2017:09:38:47 +0900] Report: jobs-active=0
D [25/Sep/2017:09:38:47 +0900] Report: printers=1
D [25/Sep/2017:09:38:47 +0900] Report: stringpool-string-count=7198
D [25/Sep/2017:09:38:47 +0900] Report: stringpool-alloc-bytes=8544
D [25/Sep/2017:09:38:47 +0900] Report: stringpool-total-bytes=128344

Last edited by ewab (2017-09-25 02:43:42)

Offline

#9 2017-09-25 12:09:08

Lone_Wolf
Member
From: Netherlands, Europe
Registered: 2005-10-04
Posts: 11,848

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

It does look like the problem is in pstoufr2cpca , fortunately that's not proprietary code.
Maybe we can figure out what has changed, any chance you can figure out when the older version was built ?


please post

ldd --verbose /usr/lib/cups/filter/pstoufr2cpca

   .


Disliking systemd intensely, but not satisfied with alternatives so focusing on taming systemd.


(A works at time B)  && (time C > time B ) ≠  (A works at time C)

Offline

#10 2017-09-26 01:23:27

ewab
Member
From: Japan
Registered: 2017-04-28
Posts: 9

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

I apparently installed archlinux on Aug 1 last time looking into the creation time of my home folder and some other folders, so the driver that was running normally before was the latest version...

To tell the whole story, as I was going to build a medical image viewer, mirrors answered there was no such file when installing dependencies. I remembered I hadn't upgraded the system for a while, I did pacman -Syu. I noticed I couldn't print files after installation of the viewer. I uninstalled the viewer but I still couldn't print. So I decided to re-install archlinux itself.

The culprit may not be the driver.

anyway, this is the output of "ldd --verbose /usr/lib/cups/filter/pstoufr2cpca"

	linux-vdso.so.1 (0x00007fffe6f92000)
	libcups.so.2 => /usr/lib/libcups.so.2 (0x00007f62d54b7000)
	libc.so.6 => /usr/lib/libc.so.6 (0x00007f62d5100000)
	libgssapi_krb5.so.2 => /usr/lib/libgssapi_krb5.so.2 (0x00007f62d4eb2000)
	libkrb5.so.3 => /usr/lib/libkrb5.so.3 (0x00007f62d4bca000)
	libk5crypto.so.3 => /usr/lib/libk5crypto.so.3 (0x00007f62d4996000)
	libcom_err.so.2 => /usr/lib/libcom_err.so.2 (0x00007f62d4792000)
	libgnutls.so.30 => /usr/lib/libgnutls.so.30 (0x00007f62d4427000)
	libavahi-common.so.3 => /usr/lib/libavahi-common.so.3 (0x00007f62d421a000)
	libavahi-client.so.3 => /usr/lib/libavahi-client.so.3 (0x00007f62d4009000)
	libpthread.so.0 => /usr/lib/libpthread.so.0 (0x00007f62d3deb000)
	libm.so.6 => /usr/lib/libm.so.6 (0x00007f62d3a9f000)
	libcrypt.so.1 => /usr/lib/libcrypt.so.1 (0x00007f62d3867000)
	libz.so.1 => /usr/lib/libz.so.1 (0x00007f62d3650000)
	/lib64/ld-linux-x86-64.so.2 => /usr/lib64/ld-linux-x86-64.so.2 (0x00007f62d5992000)
	libkrb5support.so.0 => /usr/lib/libkrb5support.so.0 (0x00007f62d3443000)
	libdl.so.2 => /usr/lib/libdl.so.2 (0x00007f62d323f000)
	libkeyutils.so.1 => /usr/lib/libkeyutils.so.1 (0x00007f62d303b000)
	libresolv.so.2 => /usr/lib/libresolv.so.2 (0x00007f62d2e24000)
	libp11-kit.so.0 => /usr/lib/libp11-kit.so.0 (0x00007f62d2af4000)
	libunistring.so.2 => /usr/lib/libunistring.so.2 (0x00007f62d2783000)
	libtasn1.so.6 => /usr/lib/libtasn1.so.6 (0x00007f62d2570000)
	libnettle.so.6 => /usr/lib/libnettle.so.6 (0x00007f62d2338000)
	libhogweed.so.4 => /usr/lib/libhogweed.so.4 (0x00007f62d2103000)
	libgmp.so.10 => /usr/lib/libgmp.so.10 (0x00007f62d1e70000)
	libdbus-1.so.3 => /usr/lib/libdbus-1.so.3 (0x00007f62d1c21000)
	libffi.so.6 => /usr/lib/libffi.so.6 (0x00007f62d1a18000)
	libsystemd.so.0 => /usr/lib/libsystemd.so.0 (0x00007f62d1791000)
	libgcrypt.so.20 => /usr/lib/libgcrypt.so.20 (0x00007f62d1475000)
	librt.so.1 => /usr/lib/librt.so.1 (0x00007f62d126d000)
	liblzma.so.5 => /usr/lib/liblzma.so.5 (0x00007f62d1047000)
	liblz4.so.1 => /usr/lib/liblz4.so.1 (0x00007f62d0e32000)
	libgpg-error.so.0 => /usr/lib/libgpg-error.so.0 (0x00007f62d0c1d000)

	Version information:
	/usr/lib/cups/filter/pstoufr2cpca:
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libcups.so.2:
		libz.so.1 (ZLIB_1.2.0) => /usr/lib/libz.so.1
		libm.so.6 (GLIBC_2.2.5) => /usr/lib/libm.so.6
		libgssapi_krb5.so.2 (gssapi_krb5_2_MIT) => /usr/lib/libgssapi_krb5.so.2
		libpthread.so.0 (GLIBC_2.3.2) => /usr/lib/libpthread.so.0
		libpthread.so.0 (GLIBC_2.2.5) => /usr/lib/libpthread.so.0
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.16) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libgnutls.so.30 (GNUTLS_3_4) => /usr/lib/libgnutls.so.30
	/usr/lib/libc.so.6:
		ld-linux-x86-64.so.2 (GLIBC_2.3) => /usr/lib64/ld-linux-x86-64.so.2
		ld-linux-x86-64.so.2 (GLIBC_PRIVATE) => /usr/lib64/ld-linux-x86-64.so.2
	/usr/lib/libgssapi_krb5.so.2:
		libk5crypto.so.3 (k5crypto_3_MIT) => /usr/lib/libk5crypto.so.3
		libkrb5support.so.0 (krb5support_0_MIT) => /usr/lib/libkrb5support.so.0
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.8) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libkrb5.so.3 (krb5_3_MIT) => /usr/lib/libkrb5.so.3
	/usr/lib/libkrb5.so.3:
		libresolv.so.2 (GLIBC_2.2.5) => /usr/lib/libresolv.so.2
		libresolv.so.2 (GLIBC_2.9) => /usr/lib/libresolv.so.2
		libk5crypto.so.3 (k5crypto_3_MIT) => /usr/lib/libk5crypto.so.3
		libkrb5support.so.0 (krb5support_0_MIT) => /usr/lib/libkrb5support.so.0
		libkeyutils.so.1 (KEYUTILS_1.0) => /usr/lib/libkeyutils.so.1
		libkeyutils.so.1 (KEYUTILS_1.5) => /usr/lib/libkeyutils.so.1
		libkeyutils.so.1 (KEYUTILS_0.3) => /usr/lib/libkeyutils.so.1
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.8) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.16) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
	/usr/lib/libk5crypto.so.3:
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libkrb5support.so.0 (krb5support_0_MIT) => /usr/lib/libkrb5support.so.0
	/usr/lib/libcom_err.so.2:
		ld-linux-x86-64.so.2 (GLIBC_2.3) => /usr/lib64/ld-linux-x86-64.so.2
		libpthread.so.0 (GLIBC_2.2.5) => /usr/lib/libpthread.so.0
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.17) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libgnutls.so.30:
		libc.so.6 (GLIBC_2.8) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.25) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.2) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.17) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.22) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libtasn1.so.6 (LIBTASN1_0_3) => /usr/lib/libtasn1.so.6
		libnettle.so.6 (NETTLE_6) => /usr/lib/libnettle.so.6
		libhogweed.so.4 (HOGWEED_4) => /usr/lib/libhogweed.so.4
	/usr/lib/libavahi-common.so.3:
		libpthread.so.0 (GLIBC_2.2.5) => /usr/lib/libpthread.so.0
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libavahi-client.so.3:
		libdl.so.2 (GLIBC_2.2.5) => /usr/lib/libdl.so.2
		libpthread.so.0 (GLIBC_2.2.5) => /usr/lib/libpthread.so.0
		libdbus-1.so.3 (LIBDBUS_1_3) => /usr/lib/libdbus-1.so.3
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libpthread.so.0:
		ld-linux-x86-64.so.2 (GLIBC_2.2.5) => /usr/lib64/ld-linux-x86-64.so.2
		ld-linux-x86-64.so.2 (GLIBC_PRIVATE) => /usr/lib64/ld-linux-x86-64.so.2
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.2) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_PRIVATE) => /usr/lib/libc.so.6
	/usr/lib/libm.so.6:
		ld-linux-x86-64.so.2 (GLIBC_PRIVATE) => /usr/lib64/ld-linux-x86-64.so.2
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_PRIVATE) => /usr/lib/libc.so.6
	/usr/lib/libcrypt.so.1:
		libc.so.6 (GLIBC_2.25) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_PRIVATE) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libz.so.1:
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libkrb5support.so.0:
		libdl.so.2 (GLIBC_2.2.5) => /usr/lib/libdl.so.2
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.8) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
	/usr/lib/libdl.so.2:
		ld-linux-x86-64.so.2 (GLIBC_PRIVATE) => /usr/lib64/ld-linux-x86-64.so.2
		libc.so.6 (GLIBC_PRIVATE) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libkeyutils.so.1:
		libc.so.6 (GLIBC_2.7) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libresolv.so.2:
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_PRIVATE) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
	/usr/lib/libp11-kit.so.0:
		libdl.so.2 (GLIBC_2.2.5) => /usr/lib/libdl.so.2
		libpthread.so.0 (GLIBC_2.2.5) => /usr/lib/libpthread.so.0
		libc.so.6 (GLIBC_2.16) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.6) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.8) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.2) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.15) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
	/usr/lib/libunistring.so.2:
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libtasn1.so.6:
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
	/usr/lib/libnettle.so.6:
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libhogweed.so.4:
		libnettle.so.6 (NETTLE_6) => /usr/lib/libnettle.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libgmp.so.10:
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.7) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
	/usr/lib/libdbus-1.so.3:
		libpthread.so.0 (GLIBC_2.3.3) => /usr/lib/libpthread.so.0
		libpthread.so.0 (GLIBC_2.3.2) => /usr/lib/libpthread.so.0
		libpthread.so.0 (GLIBC_2.2.5) => /usr/lib/libpthread.so.0
		libsystemd.so.0 (LIBSYSTEMD_209) => /usr/lib/libsystemd.so.0
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.10) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.17) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libffi.so.6:
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.7) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libsystemd.so.0:
		ld-linux-x86-64.so.2 (GLIBC_2.3) => /usr/lib64/ld-linux-x86-64.so.2
		librt.so.1 (GLIBC_2.3.4) => /usr/lib/librt.so.1
		liblzma.so.5 (XZ_5.0) => /usr/lib/liblzma.so.5
		libgcrypt.so.20 (GCRYPT_1.6) => /usr/lib/libgcrypt.so.20
		libpthread.so.0 (GLIBC_2.2.5) => /usr/lib/libpthread.so.0
		libc.so.6 (GLIBC_2.25) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.8) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.2) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.7) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.10) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.9) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.17) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.16) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libgcrypt.so.20:
		libgpg-error.so.0 (GPG_ERROR_1.0) => /usr/lib/libgpg-error.so.0
		libc.so.6 (GLIBC_2.3) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.15) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/librt.so.1:
		libpthread.so.0 (GLIBC_2.3.2) => /usr/lib/libpthread.so.0
		libpthread.so.0 (GLIBC_PRIVATE) => /usr/lib/libpthread.so.0
		libpthread.so.0 (GLIBC_2.2.5) => /usr/lib/libpthread.so.0
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.2) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_PRIVATE) => /usr/lib/libc.so.6
	/usr/lib/liblzma.so.5:
		libpthread.so.0 (GLIBC_2.3.3) => /usr/lib/libpthread.so.0
		libpthread.so.0 (GLIBC_2.3.2) => /usr/lib/libpthread.so.0
		libpthread.so.0 (GLIBC_2.2.5) => /usr/lib/libpthread.so.0
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.6) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.17) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/liblz4.so.1:
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6
	/usr/lib/libgpg-error.so.0:
		libc.so.6 (GLIBC_2.14) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.15) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.3.4) => /usr/lib/libc.so.6
		libc.so.6 (GLIBC_2.2.5) => /usr/lib/libc.so.6

I really appreciate your help.

Offline

#11 2017-09-26 02:23:26

ewab
Member
From: Japan
Registered: 2017-04-28
Posts: 9

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

The printer has come back! I restored all packages in the system to their version at Aug 1st, it came back.

The cndrvcups-lb seems to depend on

lib32-libxml2
  ├─lib32-zlib
  │ ├─lib32-glibc
  │ └─zlib
  ├─lib32-readline
  │ ├─lib32-glibc
  │ ├─lib32-ncurses
  │ │ ├─lib32-glibc
  │ │ └─ncurses
  │ └─readline
  ├─lib32-ncurses
  ├─lib32-icu
  │ ├─lib32-gcc-libs
  │ └─icu
  └─libxml2

I upgraded the whole system again. The printer stopped working again.
After that, I was downgrading these packages one by one. When I downgraded lib32-glibc to the version 2.25-5, the printer restored. Once I upgraded it to the version 2-26.1, it stalls again. The cause was lib32-glibc-2.26-1. The latest version is 2.26-2.

Do I need to report this to somebody? Canon?

Anyway, thank you so much for your advice, Lone_Wolf.

Last edited by ewab (2017-09-26 03:42:15)

Offline

#12 2017-09-26 10:55:35

Lone_Wolf
Member
From: Netherlands, Europe
Registered: 2005-10-04
Posts: 11,848

Re: [SOLVED]Canon printer stopped printing after re-installation of Arch

The changelog of glibc 2.26 is full of deprecated and removed features, so it's not surprising it breaks this package.

It would be great if canon became aware of this, but they have a very strict policy wrt linux support tickets :
Unless the problem occurs on a distribution they support, the ticket gets closed.

We may need a lib32-glibc2.25 package that can be installed alongside latest lib32-glibc, not sure how to do that.
I'll probably start a thread about this in AUR sub-board.



<side note>

Approx 3 -4 years ago there was an archlinux user from a company running several 20+ canon printers on various systems, including ubuntu ones.
At that time both ubuntu and arch linux gave the same error, canon accepted the ticket for ubuntu .
They did find a very generic solution for ubuntu : installing the ia32-libs, a catch all package for multilib which afaik never has had an AL counterpart .
After that the ticket was closed.
Nine months later canon released a new driver version that solved the problem.
The AL user tested again, the reported problem was gone but 2 other errors had appeared.
In order to use the canon printers from AL, the user installed an ubuntu VM.

Last edited by Lone_Wolf (2017-09-26 10:57:17)


Disliking systemd intensely, but not satisfied with alternatives so focusing on taming systemd.


(A works at time B)  && (time C > time B ) ≠  (A works at time C)

Offline

Board footer

Powered by FluxBB