[cups] Printing problems

[E.Time]

Dear members,
I've installed an Epson Laser Printer AL-C1100 on my Linux 64 bit 
system. The problem is the printer only prints grayscale no color.

Information about my system:

wilhelm at Blacky:~$ uname -a
Linux Blacky 4.15.0-43-generic #46-Ubuntu SMP Thu Dec 6 14:45:28 UTC 
2018 x86_64 x86_64 x86_64 GNU/Linux


When I set the system language to "english US" and try to print out a 
document with the printer setting "color" it only prints grayscale. I 
can't find the reason for this behavouir because the printer default 
option Color is set to "color". The printer itself has been installed 
without any error.

If I set the system language to "german" which is my default, the 
printer fails with the following error and prints the document in grayscale:

FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-EPSON_AL-C1100\' does not exist
Using profile ID "EPSON_AL-C1100-Gray..".

The CUPS test page is always being printed in color regardless of the 
language settings.


I've attached the following files for further information:

  * parts of the error_log (LogLevel is set to "debug")
  * screenshot from colormgr get-devices
  * screenshot fom colormgr get-profiles

Any help will be greatly appreciated.


Thanks in advance

Wilhelm

-------------- next part --------------
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Jan/2019:15:49:02 +0100] [Client 122] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 122] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 122] Waiting for request.
I [23/Jan/2019:15:49:02 +0100] Expiring subscriptions...
D [23/Jan/2019:15:49:02 +0100] Report: clients=1
D [23/Jan/2019:15:49:02 +0100] Report: jobs=7
D [23/Jan/2019:15:49:02 +0100] Report: jobs-active=0
D [23/Jan/2019:15:49:02 +0100] Report: printers=1
D [23/Jan/2019:15:49:02 +0100] Report: stringpool-string-count=7507
D [23/Jan/2019:15:49:02 +0100] Report: stringpool-alloc-bytes=10752
D [23/Jan/2019:15:49:02 +0100] Report: stringpool-total-bytes=150344
D [23/Jan/2019:15:49:02 +0100] [Client 122] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 122] 2.0 CUPS-Get-Printers 40
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Printers
D [23/Jan/2019:15:49:02 +0100] [Client 122] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 122] Content-Length: 1311
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] con->http=0x555d0ceca140
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1311, response=0x555d0ced5a40(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 122] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] bytes=0, http_state=0, data_remaining=1311
D [23/Jan/2019:15:49:02 +0100] [Client 122] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 122] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 122] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Jan/2019:15:49:02 +0100] [Client 122] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 122] 2.0 CUPS-Get-Default 41
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [23/Jan/2019:15:49:02 +0100] [Client 122] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 122] Content-Length: 113
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] con->http=0x555d0ceca140
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0ce98140(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 122] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:02 +0100] [Client 122] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 122] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 122] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Jan/2019:15:49:02 +0100] [Client 122] POST /printers/EPSON_AL-C1100 HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 122] 2.0 Get-Printer-Attributes 42
D [23/Jan/2019:15:49:02 +0100] Get-Printer-Attributes ipp://localhost/printers/EPSON_AL-C1100
D [23/Jan/2019:15:49:02 +0100] [Client 122] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/EPSON_AL-C1100) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 122] Content-Length: 66391
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] con->http=0x555d0ceca140
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=66391, response=0x555d0ce03a00(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 122] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] bytes=0, http_state=0, data_remaining=66391
D [23/Jan/2019:15:49:02 +0100] [Client 122] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 122] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 122] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Jan/2019:15:49:02 +0100] [Client 122] POST /printers/EPSON_AL-C1100 HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 122] 2.0 Create-Job 43
D [23/Jan/2019:15:49:02 +0100] Create-Job ipp://localhost/printers/EPSON_AL-C1100
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [23/Jan/2019:15:49:02 +0100] [Job 232] Applying default options...
D [23/Jan/2019:15:49:02 +0100] add_job: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] Adding default job-sheets values "none,none"...
I [23/Jan/2019:15:49:02 +0100] [Job 232] Adding start banner page "none".
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [23/Jan/2019:15:49:02 +0100] [Job 232] Queued on "EPSON_AL-C1100" by "wilhelm".
D [23/Jan/2019:15:49:02 +0100] [Client 122] Returning IPP successful-ok for Create-Job (ipp://localhost/printers/EPSON_AL-C1100) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 122] Content-Length: 201
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] con->http=0x555d0ceca140
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=201, response=0x555d0cd9bae0(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 122] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] bytes=0, http_state=0, data_remaining=201
D [23/Jan/2019:15:49:02 +0100] [Client 122] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 122] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 122] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Notifier] JobCreated
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 123] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 Get-Notifications 92
D [23/Jan/2019:15:49:02 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 675
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=675, response=0x555d0ced4850(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=675
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 122] POST /printers/EPSON_AL-C1100 HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 122] 2.0 Send-Document 44
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 124] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 124] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 124] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 124] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 124] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 124] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 124] 2.0 Get-Job-Attributes 93
D [23/Jan/2019:15:49:02 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:02 +0100] [Client 124] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 124] Content-Length: 113
D [23/Jan/2019:15:49:02 +0100] [Client 124] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 124] con->http=0x555d0ce90940
D [23/Jan/2019:15:49:02 +0100] [Client 124] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0cee2400(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 124] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 124] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:02 +0100] [Client 124] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 124] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 124] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 124] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 124] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
...... more of the same stuff ......
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 122] Read: status=100, state=6
D [23/Jan/2019:15:49:02 +0100] Send-Document ipp://localhost:631/printers/EPSON_AL-C1100
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Job 232] Auto-typing file...
D [23/Jan/2019:15:49:02 +0100] [Job 232] Request file type is application/pdf.
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [23/Jan/2019:15:49:02 +0100] [Job 232] File of type application/pdf queued by "wilhelm".
I [23/Jan/2019:15:49:02 +0100] [Job 232] Adding end banner page "none".
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] time-at-processing=1548254942
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] 3 filters for job:
D [23/Jan/2019:15:49:02 +0100] [Job 232] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [23/Jan/2019:15:49:02 +0100] [Job 232] pdftops (application/vnd.cups-pdf to application/vnd.cups-postscript, cost 100)
D [23/Jan/2019:15:49:02 +0100] [Job 232] foomatic-rip (application/vnd.cups-postscript to printer/EPSON_AL-C1100, cost 0)
D [23/Jan/2019:15:49:02 +0100] [Job 232] job-sheets=none,none
D [23/Jan/2019:15:49:02 +0100] [Job 232] argv[0]="EPSON_AL-C1100"
D [23/Jan/2019:15:49:02 +0100] [Job 232] argv[1]="232"
D [23/Jan/2019:15:49:02 +0100] [Job 232] argv[2]="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Job 232] argv[3]="Frauentag - was bewegt Dich.doc"
D [23/Jan/2019:15:49:02 +0100] [Job 232] argv[4]="1"
D [23/Jan/2019:15:49:02 +0100] [Job 232] argv[5]="Duplex=None InputSlot=mptray PageSize=a4 job-uuid=urn:uuid:cc5616b3-ac3e-3e16-6e4b-9a2884aa5ca0 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1548254942 time-at-processing=1548254942 document-name-supplied=etI9wL"
D [23/Jan/2019:15:49:02 +0100] [Job 232] argv[6]="/var/spool/cups/d00232-001"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[7]="CUPS_STATEDIR=/run/cups"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[8]="HOME=/var/spool/cups/tmp"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[10]="SERVER_ADMIN=root at Blacky"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[11]="SOFTWARE=CUPS/2.2.7"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[13]="USER=root"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[14]="CUPS_MAX_MESSAGE=2047"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[17]="IPP_PORT=631"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[18]="CHARSET=utf-8"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[19]="LANG=en_US.UTF-8"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[20]="PPD=/etc/cups/ppd/EPSON_AL-C1100.ppd"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[21]="RIP_MAX_CACHE=128m"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[22]="CONTENT_TYPE=application/pdf"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[23]="DEVICE_URI=usb://EPSON/AL-C1100?serial=31PF2PZ12377841225"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[24]="PRINTER_INFO=EPSON AL-C1100"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[25]="PRINTER_LOCATION=Blacky"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[26]="PRINTER=EPSON_AL-C1100"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[27]="PRINTER_STATE_REASONS=none"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[28]="CUPS_FILETYPE=document"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-postscript"
D [23/Jan/2019:15:49:02 +0100] [Job 232] envp[30]="AUTH_I****"
I [23/Jan/2019:15:49:02 +0100] [Job 232] Started filter /usr/lib/cups/filter/pdftopdf (PID 6088)
I [23/Jan/2019:15:49:02 +0100] [Job 232] Started filter /usr/lib/cups/filter/pdftops (PID 6089)
I [23/Jan/2019:15:49:02 +0100] [Job 232] Started filter /usr/lib/cups/filter/foomatic-rip (PID 6090)
I [23/Jan/2019:15:49:02 +0100] [Job 232] Started backend /usr/lib/cups/backend/usb (PID 6091)
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 122] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/EPSON_AL-C1100) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 122] Content-Length: 171
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] con->http=0x555d0ceca140
D [23/Jan/2019:15:49:02 +0100] [Client 122] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=171, response=0x555d0cee2400(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 122] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 122] bytes=0, http_state=0, data_remaining=171
D [23/Jan/2019:15:49:02 +0100] [Client 122] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 122] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 122] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Notifier] PrinterStateChanged
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Notifier] JobState
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 Get-Notifications 94
D [23/Jan/2019:15:49:02 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 1109
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Job 232] pdftops - copying to temp print file \"/tmp/017c95c4ddc78\"
D [23/Jan/2019:15:49:02 +0100] [Job 232] pdftopdf: Last filter determined by the PPD: foomatic-rip; FINAL_CONTENT_TYPE: application/vnd.cups-postscript => pdftopdf will log pages in page_log.
D [23/Jan/2019:15:49:02 +0100] [Job 232] PAGE: 1 1
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] Calling FindDeviceById(cups-EPSON_AL-C1100)
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Notifier] JobProgress
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1109, response=0x555d0ced4850(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=1109
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] Found device /org/freedesktop/ColorManager/devices/cups_EPSON_AL_C1100
D [23/Jan/2019:15:49:02 +0100] [Job 232] Calling org.freedesktop.ColorManager.Device.Get(ProfilingInhibitors)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 125] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 125] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 125] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Job 232] \'CM Color Calibration\' Mode in SPOOLER-LESS: Off
D [23/Jan/2019:15:49:02 +0100] [Job 232] Getting input from file 
D [23/Jan/2019:15:49:02 +0100] [Job 232] foomatic-rip version 1.20.2 running...
D [23/Jan/2019:15:49:02 +0100] [Job 232] Parsing PPD file ...
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option ColorSpace
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option PageSize
D [23/Jan/2019:15:49:02 +0100] [Client 125] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 125] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 125] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 125] 2.0 Get-Job-Attributes 95
D [23/Jan/2019:15:49:02 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:02 +0100] [Client 125] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 125] Content-Length: 113
D [23/Jan/2019:15:49:02 +0100] [Client 125] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 125] con->http=0x555d0ce90940
D [23/Jan/2019:15:49:02 +0100] [Client 125] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0ceb4e10(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 125] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 125] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:02 +0100] [Client 125] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 125] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 125] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option ImageableArea
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option PaperDimension
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option MediaType
D [23/Jan/2019:15:49:02 +0100] [Client 125] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 125] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 Get-Notifications 96
D [23/Jan/2019:15:49:02 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 127
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=127, response=0x555d0cee2400(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=127
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 Get-Notifications 97
D [23/Jan/2019:15:49:02 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 127
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=127, response=0x555d0ceb4e10(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=127
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] Loading USB quirks from \"/usr/share/cups/usb\".
D [23/Jan/2019:15:49:02 +0100] [Job 232] Loaded 88 quirks.
D [23/Jan/2019:15:49:02 +0100] [Job 232] Printing on printer with URI: usb://EPSON/AL-C1100?serial=31PF2PZ12377841225
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option Color
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option Duplex
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option TonerSave
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option Resolution
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option InputSlot
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option Collate
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option Copies
D [23/Jan/2019:15:49:02 +0100] [Job 232] libusb_get_device_list=5
D [23/Jan/2019:15:49:02 +0100] [Job 232] STATE: +connecting-to-device
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Notifier] PrinterStateChanged
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 Get-Notifications 98
D [23/Jan/2019:15:49:02 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 564
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=564, response=0x555d0cee3c20(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=564
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 CUPS-Get-Printers 99
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Printers
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 1327
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1327, response=0x555d0ced76c0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=1327
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 CUPS-Get-Default 100
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 113
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0cee3c20(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] STATE: -connecting-to-device
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] Added option Font
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Notifier] PrinterStateChanged
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Job 232] Device protocol: 2
D [23/Jan/2019:15:49:02 +0100] [Job 232] Sending data to printer.
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] Set job-printer-state-message to "Sending data to printer.", current level=INFO
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Job 232] Parameter Summary
D [23/Jan/2019:15:49:02 +0100] [Job 232] -----------------
D [23/Jan/2019:15:49:02 +0100] [Job 232] Spooler: cups
D [23/Jan/2019:15:49:02 +0100] [Job 232] Printer: EPSON_AL-C1100
D [23/Jan/2019:15:49:02 +0100] [Job 232] Shell: /bin/sh
D [23/Jan/2019:15:49:02 +0100] [Job 232] PPD file: /etc/cups/ppd/EPSON_AL-C1100.ppd
D [23/Jan/2019:15:49:02 +0100] [Job 232] ATTR file: 
D [23/Jan/2019:15:49:02 +0100] [Job 232] Printer model: EPSON AL-C1100, ESC/PageS Filter
D [23/Jan/2019:15:49:02 +0100] [Job 232] Job title: Frauentag - was bewegt Dich.doc
D [23/Jan/2019:15:49:02 +0100] [Job 232] File(s) to be printed:
D [23/Jan/2019:15:49:02 +0100] [Job 232] <STDIN>
D [23/Jan/2019:15:49:02 +0100] [Job 232] Ghostscript extra search path (\'GS_LIB\'): /usr/share/cups/fonts
D [23/Jan/2019:15:49:02 +0100] [Job 232] Printing system options:
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'job-uuid=urn:uuid:cc5616b3-ac3e-3e16-6e4b-9a2884aa5ca0\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Unknown option job-uuid=urn:uuid:cc5616b3-ac3e-3e16-6e4b-9a2884aa5ca0.
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'job-originating-host-name=localhost\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Unknown option job-originating-host-name=localhost.
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'date-time-at-creation=\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Unknown option date-time-at-creation=.
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'date-time-at-processing=\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Unknown option date-time-at-processing=.
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'time-at-creation=1548254942\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Unknown option time-at-creation=1548254942.
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'time-at-processing=1548254942\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Unknown option time-at-processing=1548254942.
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'document-name-supplied=etI9wL\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Unknown option document-name-supplied=etI9wL.
D [23/Jan/2019:15:49:02 +0100] [Job 232] CM Color Calibration Mode in CUPS: Off
D [23/Jan/2019:15:49:02 +0100] [Job 232] Options from the PPD file:
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'Duplex=None\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'InputSlot=mptray\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Pondering option \'PageSize=a4\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] ================================================
D [23/Jan/2019:15:49:02 +0100] [Job 232] File: <STDIN>
D [23/Jan/2019:15:49:02 +0100] [Job 232] ================================================
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Notifier] JobProgress
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Notifier] PrinterStateChanged
D [23/Jan/2019:15:49:02 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:02 +0100] [Job 232] PID 6088 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [23/Jan/2019:15:49:02 +0100] [Job 232] Printer make and model: Epson ESC/PageS Filter
D [23/Jan/2019:15:49:02 +0100] [Job 232] Running command line for pstops: pstops 232 wilhelm \'Frauentag - was bewegt Dich.doc\' 1 \'Duplex=None InputSlot=mptray PageSize=a4 job-uuid=urn:uuid:cc5616b3-ac3e-3e16-6e4b-9a2884aa5ca0 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1548254942 time-at-processing=1548254942 document-name-supplied=etI9wL\'
D [23/Jan/2019:15:49:02 +0100] [Job 232] Using image rendering resolution 300 dpi
D [23/Jan/2019:15:49:02 +0100] [Job 232] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -dShowAcroForm -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r300 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c \'save pop\' -f /tmp/017c95c4ddc78
D [23/Jan/2019:15:49:02 +0100] [Job 232] Started filter gs (PID 6101)
D [23/Jan/2019:15:49:02 +0100] [Job 232] Started filter pstops (PID 6102)
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 126] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 126] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 126] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 126] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 126] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 126] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 126] 2.0 Get-Notifications 50
D [23/Jan/2019:15:49:02 +0100] Get-Notifications /
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Client 126] Returning IPP successful-ok for Get-Notifications (/) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 126] Content-Length: 4028
D [23/Jan/2019:15:49:02 +0100] [Client 126] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 126] con->http=0x555d0cec4770
D [23/Jan/2019:15:49:02 +0100] [Client 126] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=4028, response=0x555d0ceda260(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 126] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 126] bytes=0, http_state=0, data_remaining=4028
D [23/Jan/2019:15:49:02 +0100] [Client 126] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 126] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 126] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 126] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 126] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 126] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 126] 2.0 Get-Job-Attributes 51
D [23/Jan/2019:15:49:02 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:02 +0100] [Client 126] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 126] Content-Length: 1122
D [23/Jan/2019:15:49:02 +0100] [Client 126] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 126] con->http=0x555d0cec4770
D [23/Jan/2019:15:49:02 +0100] [Client 126] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1122, response=0x555d0ceda820(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 126] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 126] bytes=0, http_state=0, data_remaining=1122
D [23/Jan/2019:15:49:02 +0100] [Client 126] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 126] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 126] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 CUPS-Get-Default 101
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 113
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0ceda260(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 127] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 127] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 127] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 127] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 127] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 127] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 127] 2.0 Get-Printer-Attributes 52
D [23/Jan/2019:15:49:02 +0100] Get-Printer-Attributes 
D [23/Jan/2019:15:49:02 +0100] Get-Printer-Attributes client-error-not-found: The printer or class does not exist.
D [23/Jan/2019:15:49:02 +0100] [Client 127] Returning IPP client-error-not-found for Get-Printer-Attributes () from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 127] Content-Length: 130
D [23/Jan/2019:15:49:02 +0100] [Client 127] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 127] con->http=0x555d0cecdc50
D [23/Jan/2019:15:49:02 +0100] [Client 127] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=130, response=0x555d0ce00770(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 127] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 127] bytes=0, http_state=0, data_remaining=130
D [23/Jan/2019:15:49:02 +0100] [Client 127] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 127] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 127] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 127] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 127] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 128] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 128] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 128] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 128] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 128] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 128] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 128] 2.0 Get-Job-Attributes 53
D [23/Jan/2019:15:49:02 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:02 +0100] [Client 128] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 128] Content-Length: 178
D [23/Jan/2019:15:49:02 +0100] [Client 128] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 128] con->http=0x555d0cecdc50
D [23/Jan/2019:15:49:02 +0100] [Client 128] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=178, response=0x555d0ce00780(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 128] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 128] bytes=0, http_state=0, data_remaining=178
D [23/Jan/2019:15:49:02 +0100] [Client 128] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 128] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 128] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 Get-Notifications 102
D [23/Jan/2019:15:49:02 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 969
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 128] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 128] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=969, response=0x555d0ce007d0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=969
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 129] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 129] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 129] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 129] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 129] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 129] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 129] 2.0 Get-Job-Attributes 54
D [23/Jan/2019:15:49:02 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:02 +0100] [Client 129] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 129] Content-Length: 101
D [23/Jan/2019:15:49:02 +0100] [Client 129] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 129] con->http=0x555d0cecdc50
D [23/Jan/2019:15:49:02 +0100] [Client 129] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=101, response=0x555d0ce007c0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 129] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 129] bytes=0, http_state=0, data_remaining=101
D [23/Jan/2019:15:49:02 +0100] [Client 129] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 129] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 129] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 CUPS-Get-Printers 103
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Printers
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 1311
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1311, response=0x555d0ceda820(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=1311
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 130] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 130] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 130] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 130] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 130] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 130] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 130] 2.0 Get-Printer-Attributes 55
D [23/Jan/2019:15:49:02 +0100] Get-Printer-Attributes ipp://Blacky/printers/EPSON_AL-C1100
D [23/Jan/2019:15:49:02 +0100] [Client 130] Returning IPP successful-ok for Get-Printer-Attributes (ipp://Blacky/printers/EPSON_AL-C1100) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 130] Content-Length: 137
D [23/Jan/2019:15:49:02 +0100] [Client 130] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 130] con->http=0x555d0ceaf8c0
D [23/Jan/2019:15:49:02 +0100] [Client 130] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=137, response=0x555d0ce007c0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 130] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 130] bytes=0, http_state=0, data_remaining=137
D [23/Jan/2019:15:49:02 +0100] [Client 130] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 130] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 130] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 130] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 130] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 130] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 130] 2.0 Get-Job-Attributes 56
D [23/Jan/2019:15:49:02 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:02 +0100] [Client 130] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 130] Content-Length: 179
D [23/Jan/2019:15:49:02 +0100] [Client 130] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 130] con->http=0x555d0ceaf8c0
D [23/Jan/2019:15:49:02 +0100] [Client 130] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=179, response=0x555d0ceda820(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 130] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 130] bytes=0, http_state=0, data_remaining=179
D [23/Jan/2019:15:49:02 +0100] [Client 130] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 130] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 130] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 CUPS-Get-Default 104
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 113
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0cee5060(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 129] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 129] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 131] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 131] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 131] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 131] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 131] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 131] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 131] 2.0 Get-Job-Attributes 57
D [23/Jan/2019:15:49:02 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:02 +0100] [Client 131] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 131] Content-Length: 101
D [23/Jan/2019:15:49:02 +0100] [Client 131] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 131] con->http=0x555d0cecdc50
D [23/Jan/2019:15:49:02 +0100] [Client 131] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=101, response=0x555d0ce007c0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 131] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 131] bytes=0, http_state=0, data_remaining=101
D [23/Jan/2019:15:49:02 +0100] [Client 131] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 131] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 131] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 131] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 131] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 132] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 132] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 132] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 132] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 132] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 132] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 132] 2.0 Get-Job-Attributes 58
D [23/Jan/2019:15:49:02 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:02 +0100] [Client 132] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 132] Content-Length: 101
D [23/Jan/2019:15:49:02 +0100] [Client 132] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 132] con->http=0x555d0cecdc50
D [23/Jan/2019:15:49:02 +0100] [Client 132] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=101, response=0x555d0ce007c0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 132] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 132] bytes=0, http_state=0, data_remaining=101
D [23/Jan/2019:15:49:02 +0100] [Client 132] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 132] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 132] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 CUPS-Get-Default 105
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 113
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 132] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 132] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0ceda820(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 133] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 133] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 133] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 134] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 134] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 134] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 133] POST /printers/EPSON_AL-C1100 HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 133] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 133] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 133] 2.0 Get-Printer-Attributes 59
D [23/Jan/2019:15:49:02 +0100] Get-Printer-Attributes ipp://localhost/printers/EPSON_AL-C1100
D [23/Jan/2019:15:49:02 +0100] [Client 133] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/EPSON_AL-C1100) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 133] Content-Length: 223
D [23/Jan/2019:15:49:02 +0100] [Client 133] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 133] con->http=0x555d0cecdc50
D [23/Jan/2019:15:49:02 +0100] [Client 133] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=223, response=0x555d0cee1b50(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 133] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 133] bytes=0, http_state=0, data_remaining=223
D [23/Jan/2019:15:49:02 +0100] [Client 133] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 133] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 133] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 134] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 134] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 134] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 134] 2.0 Get-Job-Attributes 60
D [23/Jan/2019:15:49:02 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:02 +0100] [Client 134] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 134] Content-Length: 101
D [23/Jan/2019:15:49:02 +0100] [Client 134] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 134] con->http=0x555d0cee5180
D [23/Jan/2019:15:49:02 +0100] [Client 134] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=101, response=0x555d0ce00710(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 134] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 134] bytes=0, http_state=0, data_remaining=101
D [23/Jan/2019:15:49:02 +0100] [Client 134] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 134] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 134] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 135] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:02 +0100] [Client 135] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:02 +0100] [Client 135] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 CUPS-Get-Printers 106
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Printers
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 1311
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 134] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 134] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1311, response=0x555d0ce00770(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=1311
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 135] GET /printers/EPSON_AL-C1100.ppd HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 135] Read: status=200, state=3
D [23/Jan/2019:15:49:02 +0100] [Client 135] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 135] Processing GET /printers/EPSON_AL-C1100.ppd
D [23/Jan/2019:15:49:02 +0100] [Client 135] filename="/etc/cups/ppd/EPSON_AL-C1100.ppd", type=application/vnd.cups-ppd
D [23/Jan/2019:15:49:02 +0100] [Client 135] cupsdSendHeader: code=304, type="(null)", auth_type=0
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 126] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 126] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 135] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:02 +0100] [Client 135] Closing connection.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 CUPS-Get-Default 107
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 113
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0ceb3d00(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 CUPS-Get-Default 108
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default
D [23/Jan/2019:15:49:02 +0100] CUPS-Get-Default client-error-not-found: No default printer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP client-error-not-found for CUPS-Get-Default (no URI) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 113
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0cee5060(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 Get-Notifications 109
D [23/Jan/2019:15:49:02 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 127
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=127, response=0x555d0ceb3d00(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=127
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:02 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:02 +0100] [Client 123] 2.0 Get-Notifications 110
D [23/Jan/2019:15:49:02 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:02 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:02 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:02 +0100] [Client 123] Content-Length: 127
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:02 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=127, response=0x555d0cee5060(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:02 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:02 +0100] [Client 123] bytes=0, http_state=0, data_remaining=127
D [23/Jan/2019:15:49:02 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:02 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:02 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:02 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
I [23/Jan/2019:15:49:03 +0100] Expiring subscriptions...
D [23/Jan/2019:15:49:04 +0100] [Job 232] Page = 595x842; 0,0 to 595,842
D [23/Jan/2019:15:49:04 +0100] [Job 232] slow_collate=0, slow_duplex=0, slow_order=0
D [23/Jan/2019:15:49:04 +0100] [Job 232] Before copy_comments - %!PS-Adobe-3.0
D [23/Jan/2019:15:49:04 +0100] [Job 232] %!PS-Adobe-3.0
I [23/Jan/2019:15:49:04 +0100] Expiring subscriptions...
D [23/Jan/2019:15:49:04 +0100] [Job 232] %%BoundingBox: 0 0 595 842
D [23/Jan/2019:15:49:04 +0100] [Job 232] %%HiResBoundingBox: 0 0 595.00 842.00
D [23/Jan/2019:15:49:04 +0100] [Job 232] %%Creator: GPL Ghostscript 926 (ps2write)
D [23/Jan/2019:15:49:04 +0100] [Job 232] %%LanguageLevel: 2
D [23/Jan/2019:15:49:04 +0100] [Job 232] %%CreationDate: D:20190123154902+01\'00\'
D [23/Jan/2019:15:49:04 +0100] [Job 232] %%Pages: 1
D [23/Jan/2019:15:49:04 +0100] [Job 232] %%EndComments
D [23/Jan/2019:15:49:04 +0100] [Job 232] Before copy_prolog - %%BeginProlog
D [23/Jan/2019:15:49:04 +0100] [Job 232] Filetype: PostScript
D [23/Jan/2019:15:49:04 +0100] [Job 232] Reading PostScript input ...
D [23/Jan/2019:15:49:04 +0100] [Job 232] --> This document is DSC-conforming!
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found %RBINumCopies: 1
D [23/Jan/2019:15:49:04 +0100] [Job 232] -----------
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginProlog
D [23/Jan/2019:15:49:04 +0100] [Job 232] Before copy_setup - %%Page: 1 1
D [23/Jan/2019:15:49:04 +0100] [Job 232] Before page loop - %%Page: 1 1
D [23/Jan/2019:15:49:04 +0100] [Job 232] Copying page 1...
D [23/Jan/2019:15:49:04 +0100] [Job 232] pagew = 595.0, pagel = 842.0
D [23/Jan/2019:15:49:04 +0100] [Job 232] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [23/Jan/2019:15:49:04 +0100] [Job 232] PageLeft = 0.0, PageRight = 595.0
D [23/Jan/2019:15:49:04 +0100] [Job 232] PageTop = 842.0, PageBottom = 0.0
D [23/Jan/2019:15:49:04 +0100] [Job 232] PageWidth = 595.0, PageLength = 842.0
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%EndProlog
D [23/Jan/2019:15:49:04 +0100] [Job 232] -----------
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginSetup
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginFeature: *Collate on
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Collate=on
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %% FoomaticRIPOptionSetting: Collate=on
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Collate=on
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginFeature: *Copies 1
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Copies=1
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %% FoomaticRIPOptionSetting: Copies=1
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Copies=1
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginFeature: *InputSlot mptray
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: InputSlot=mptray
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %% FoomaticRIPOptionSetting: InputSlot=mptray
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: InputSlot=mptray
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginFeature: *MediaType normal
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: MediaType=normal
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %% FoomaticRIPOptionSetting: MediaType=normal
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: MediaType=normal
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginFeature: *PageSize a4
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: PageSize=a4
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %% FoomaticRIPOptionSetting: PageSize=a4
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: PageSize=a4
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginFeature: *TonerSave false
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: TonerSave=false
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %% FoomaticRIPOptionSetting: TonerSave=false
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: TonerSave=false
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginFeature: *Resolution 300dpi
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Resolution=300dpi
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %% FoomaticRIPOptionSetting: Resolution=300dpi
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Resolution=300dpi
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginFeature: *Color color
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Color=color
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %% FoomaticRIPOptionSetting: Color=color
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Color=color
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginFeature: *Duplex None
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Duplex=None
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %% FoomaticRIPOptionSetting: Duplex=None
D [23/Jan/2019:15:49:04 +0100] [Job 232] Option: Duplex=None
D [23/Jan/2019:15:49:04 +0100] [Job 232] Setting option
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%EndSetup
D [23/Jan/2019:15:49:04 +0100] [Job 232] -----------
D [23/Jan/2019:15:49:04 +0100] [Job 232] New page: %%Page: 1 1
D [23/Jan/2019:15:49:04 +0100] [Job 232] \"Setup\" section is missing, inserting it.
D [23/Jan/2019:15:49:04 +0100] [Job 232] Found: %%BeginPageSetup
D [23/Jan/2019:15:49:04 +0100] [Job 232] Inserting option code into \"PageSetup\" section.
D [23/Jan/2019:15:49:04 +0100] [Job 232] Wrote 1 pages...
D [23/Jan/2019:15:49:04 +0100] [Job 232] PID 6101 (gs) exited with no errors.
D [23/Jan/2019:15:49:04 +0100] [Job 232] PID 6102 (pstops) exited with no errors.
D [23/Jan/2019:15:49:04 +0100] [Job 232] Flushing FIFO.
D [23/Jan/2019:15:49:04 +0100] [Job 232] PID 6089 (/usr/lib/cups/filter/pdftops) exited with no errors.
D [23/Jan/2019:15:49:04 +0100] [Job 232] Starting renderer with command: \"pstoalc1100.sh  Copies=1 Collate=on InputSlot=mptray TonerSave=false MediaType=normal PageSize=a4 XY600=4960x7016 Resolution=300dpi Color=color Duplex=None\"
D [23/Jan/2019:15:49:04 +0100] [Job 232] Starting process \"kid3\" (generation 1)
D [23/Jan/2019:15:49:04 +0100] [Job 232] Starting process \"kid4\" (generation 2)
D [23/Jan/2019:15:49:04 +0100] [Job 232] Starting process \"renderer\" (generation 2)
D [23/Jan/2019:15:49:04 +0100] [Job 232] JCL: \033%-12345X at PJL
D [23/Jan/2019:15:49:04 +0100] [Job 232] <job data> 
I [23/Jan/2019:15:49:05 +0100] Expiring subscriptions...
D [23/Jan/2019:15:49:19 +0100] [Job 232] Closing renderer
I [23/Jan/2019:15:49:19 +0100] Expiring subscriptions...
D [23/Jan/2019:15:49:19 +0100] [Job 232] Read 8192 bytes of print data...
D [23/Jan/2019:15:49:19 +0100] [Job 232] Wrote 8192 bytes of print data...
D [23/Jan/2019:15:49:19 +0100] [Job 232] Read 8192 bytes of print data...
D [23/Jan/2019:15:49:19 +0100] [Job 232] Wrote 8192 bytes of print data...
D [23/Jan/2019:15:49:19 +0100] [Job 232] Read 8192 bytes of print data...
...... more of the same stuff ......
D [23/Jan/2019:15:49:20 +0100] [Job 232] Wrote 8192 bytes of print data...
D [23/Jan/2019:15:49:20 +0100] [Job 232] Read 8192 bytes of print data...
D [23/Jan/2019:15:49:20 +0100] [Job 232] Wrote 8192 bytes of print data...
D [23/Jan/2019:15:49:20 +0100] [Job 232] Read 8192 bytes of print data...
D [23/Jan/2019:15:49:20 +0100] [Job 232] Wrote 8192 bytes of print data...
D [23/Jan/2019:15:49:20 +0100] [Job 232] renderer exited with status 0
D [23/Jan/2019:15:49:20 +0100] [Job 232] kid4 exited with status 0
D [23/Jan/2019:15:49:20 +0100] [Job 232] Read 5682 bytes of print data...
D [23/Jan/2019:15:49:20 +0100] [Job 232] kid3 finished
D [23/Jan/2019:15:49:20 +0100] [Job 232] Wrote 5682 bytes of print data...
D [23/Jan/2019:15:49:20 +0100] [Job 232] kid3 exited with status 0
D [23/Jan/2019:15:49:20 +0100] [Job 232] Closing foomatic-rip.
D [23/Jan/2019:15:49:20 +0100] [Job 232] Sent 5125682 bytes...
D [23/Jan/2019:15:49:20 +0100] [Job 232] Waiting for read thread to exit...
D [23/Jan/2019:15:49:20 +0100] [Job 232] PID 6090 (/usr/lib/cups/filter/foomatic-rip) exited with no errors.
D [23/Jan/2019:15:49:20 +0100] [Job 232] PID 6091 (/usr/lib/cups/backend/usb) exited with no errors.
D [23/Jan/2019:15:49:20 +0100] [Job 232] time-at-completed=1548254960
D [23/Jan/2019:15:49:20 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [23/Jan/2019:15:49:20 +0100] [Job 232] Job completed.
I [23/Jan/2019:15:49:20 +0100] Expiring subscriptions...
D [23/Jan/2019:15:49:20 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:20 +0100] cupsdMarkDirty(----S)
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:20 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:20 +0100] [Job 226] Removing document files.
D [23/Jan/2019:15:49:20 +0100] cupsdMarkDirty(---J-)
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [23/Jan/2019:15:49:20 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:20 +0100] [Notifier] JobCompleted
D [23/Jan/2019:15:49:20 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:20 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:20 +0100] [Notifier] PrinterStateChanged
D [23/Jan/2019:15:49:20 +0100] [Notifier] state=3
D [23/Jan/2019:15:49:20 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:20 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:20 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:20 +0100] [Client 123] 2.0 Get-Notifications 111
D [23/Jan/2019:15:49:20 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:20 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:20 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:20 +0100] [Client 123] Content-Length: 1110
D [23/Jan/2019:15:49:20 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:20 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:20 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1110, response=0x555d0ce90df0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:20 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:20 +0100] [Client 123] bytes=0, http_state=0, data_remaining=1110
D [23/Jan/2019:15:49:20 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:20 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:20 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:20 +0100] [Client 136] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:20 +0100] [Client 136] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:20 +0100] [Client 136] Waiting for request.
D [23/Jan/2019:15:49:20 +0100] [Client 136] POST / HTTP/1.1
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:20 +0100] [Client 136] Read: status=200, state=6
D [23/Jan/2019:15:49:20 +0100] [Client 136] No authentication data provided.
D [23/Jan/2019:15:49:20 +0100] [Client 136] 2.0 Get-Job-Attributes 112
D [23/Jan/2019:15:49:20 +0100] Get-Job-Attributes ipp://localhost/jobs/232
D [23/Jan/2019:15:49:20 +0100] [Client 136] Returning IPP successful-ok for Get-Job-Attributes (ipp://localhost/jobs/232) from localhost
D [23/Jan/2019:15:49:20 +0100] [Client 136] Content-Length: 113
D [23/Jan/2019:15:49:20 +0100] [Client 136] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:20 +0100] [Client 136] con->http=0x555d0cec4770
D [23/Jan/2019:15:49:20 +0100] [Client 136] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=113, response=0x555d0ce90df0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:20 +0100] [Client 136] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:20 +0100] [Client 136] bytes=0, http_state=0, data_remaining=113
D [23/Jan/2019:15:49:20 +0100] [Client 136] Flushing write buffer.
D [23/Jan/2019:15:49:20 +0100] [Client 136] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:20 +0100] [Client 136] Waiting for request.
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:20 +0100] [Client 136] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:20 +0100] [Client 136] Closing connection.
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:20 +0100] [Client 123] POST / HTTP/1.1
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:20 +0100] [Client 123] Read: status=200, state=6
D [23/Jan/2019:15:49:20 +0100] [Client 123] No authentication data provided.
D [23/Jan/2019:15:49:20 +0100] [Client 123] 2.0 Get-Notifications 113
D [23/Jan/2019:15:49:20 +0100] Get-Notifications /printers/
D [23/Jan/2019:15:49:20 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:20 +0100] [Client 123] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [23/Jan/2019:15:49:20 +0100] [Client 123] Content-Length: 127
D [23/Jan/2019:15:49:20 +0100] [Client 123] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:20 +0100] [Client 123] con->http=0x555d0cebaa10
D [23/Jan/2019:15:49:20 +0100] [Client 123] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=127, response=0x555d0ceb40d0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:20 +0100] [Client 123] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:20 +0100] [Client 123] bytes=0, http_state=0, data_remaining=127
D [23/Jan/2019:15:49:20 +0100] [Client 123] Flushing write buffer.
D [23/Jan/2019:15:49:20 +0100] [Client 123] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:20 +0100] [Client 123] Waiting for request.
D [23/Jan/2019:15:49:20 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:21 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:21 +0100] [Client 137] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:21 +0100] [Client 137] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:21 +0100] [Client 137] Waiting for request.
I [23/Jan/2019:15:49:21 +0100] Expiring subscriptions...
D [23/Jan/2019:15:49:21 +0100] [Client 137] POST / HTTP/1.1
D [23/Jan/2019:15:49:21 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:21 +0100] [Client 137] Read: status=200, state=6
D [23/Jan/2019:15:49:21 +0100] [Client 137] No authentication data provided.
D [23/Jan/2019:15:49:21 +0100] [Client 137] 2.0 Get-Notifications 61
D [23/Jan/2019:15:49:21 +0100] Get-Notifications /
D [23/Jan/2019:15:49:21 +0100] cupsdIsAuthorized: requesting-user-name="wilhelm"
D [23/Jan/2019:15:49:21 +0100] [Client 137] Returning IPP successful-ok for Get-Notifications (/) from localhost
D [23/Jan/2019:15:49:21 +0100] [Client 137] Content-Length: 1110
D [23/Jan/2019:15:49:21 +0100] [Client 137] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:21 +0100] [Client 137] con->http=0x555d0cec4770
D [23/Jan/2019:15:49:21 +0100] [Client 137] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1110, response=0x555d0ce90e30(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:21 +0100] [Client 137] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:21 +0100] [Client 137] bytes=0, http_state=0, data_remaining=1110
D [23/Jan/2019:15:49:21 +0100] [Client 137] Flushing write buffer.
D [23/Jan/2019:15:49:21 +0100] [Client 137] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:21 +0100] [Client 137] Waiting for request.
D [23/Jan/2019:15:49:21 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:21 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Jan/2019:15:49:21 +0100] [Client 138] Server address is "/run/cups/cups.sock".
D [23/Jan/2019:15:49:21 +0100] [Client 138] Accepted from localhost (Domain)
D [23/Jan/2019:15:49:21 +0100] [Client 138] Waiting for request.
D [23/Jan/2019:15:49:21 +0100] [Client 138] POST / HTTP/1.1
D [23/Jan/2019:15:49:21 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:21 +0100] [Client 138] Read: status=200, state=6
D [23/Jan/2019:15:49:21 +0100] [Client 138] No authentication data provided.
D [23/Jan/2019:15:49:21 +0100] [Client 138] 2.0 Get-Printer-Attributes 62
D [23/Jan/2019:15:49:21 +0100] Get-Printer-Attributes ipp://Blacky/printers/EPSON_AL-C1100
D [23/Jan/2019:15:49:21 +0100] [Client 138] Returning IPP successful-ok for Get-Printer-Attributes (ipp://Blacky/printers/EPSON_AL-C1100) from localhost
D [23/Jan/2019:15:49:21 +0100] [Client 138] Content-Length: 137
D [23/Jan/2019:15:49:21 +0100] [Client 138] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [23/Jan/2019:15:49:21 +0100] [Client 138] con->http=0x555d0cee6340
D [23/Jan/2019:15:49:21 +0100] [Client 138] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=137, response=0x555d0ce90dc0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [23/Jan/2019:15:49:21 +0100] [Client 138] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [23/Jan/2019:15:49:21 +0100] [Client 138] bytes=0, http_state=0, data_remaining=137
D [23/Jan/2019:15:49:21 +0100] [Client 138] Flushing write buffer.
D [23/Jan/2019:15:49:21 +0100] [Client 138] New state is HTTP_STATE_WAITING
D [23/Jan/2019:15:49:21 +0100] [Client 138] Waiting for request.
D [23/Jan/2019:15:49:21 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Jan/2019:15:49:21 +0100] [Client 137] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [23/Jan/2019:15:49:21 +0100] [Client 137] Closing connection.
D [23/Jan/2019:15:49:21 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
I [23/Jan/2019:15:49:22 +0100] Expiring subscriptions...
I [23/Jan/2019:15:49:33 +0100] Saving job.cache...
I [23/Jan/2019:15:49:33 +0100] Saving subscriptions.conf...
D [23/Jan/2019:15:49:33 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
I [23/Jan/2019:15:49:33 +0100] Expiring subscriptions...
D [23/Jan/2019:15:49:46 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Jan/2019:15:49:46 +0100] [Client 139] Server address is "127.0.0.1".
D [23/Jan/2019:15:49:46 +0100] [Client 139] Accepted from localhost:59728 (IPv4)
D [23/Jan/2019:15:49:46 +0100] [Client 139] Waiting for request.
I [23/Jan/2019:15:49:46 +0100] Expiring subscriptions...
D [23/Jan/2019:15:49:46 +0100] [Client 139] GET /admin/log/error_log HTTP/1.1
D [23/Jan/2019:15:49:46 +0100] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [23/Jan/2019:15:49:46 +0100] [Client 139] Read: status=200, state=3
D [23/Jan/2019:15:49:46 +0100] [Client 139] Authorized as "wilhelm" using Basic.
D [23/Jan/2019:15:49:46 +0100] cupsdIsAuthorized: username="wilhelm"
D [23/Jan/2019:15:49:46 +0100] [Client 139] Processing GET /admin/log/error_log