Suddenly can't print anything

plp · 2018-08-29 10:48:55

Hello everyone,

After using Arch on my laptop for over two years, I suddenly cannot print anything.

My printer is a Ricoh MP 2352 and I'm using the openprinting-ppds-pxlmono-ricoh from AUR, together with cups, cups-filters, foomatic, etc.

Whenever I try to print, the printer job stays there forever:

# lpq -a
Rank    Owner   Job     File(s)                         Total Size
active  plp     569     Payment Receipt #22702600       203776 bytes

The printer either doesn't print anything, or it prints the following garbage:

%%[ Error handled by opdfread.ps : undefined; OffendingCommand: currenthal ]%%

When the printer doesn't print anything, a number of print-related processes (pdftops, gs) remain hung until I restart cups.

I enabled debugging for cups and I'm attaching my error_log:

I [29/Aug/2018:13:23:57 +0300] Listening to [v1.::1]:631 (IPv6)
I [29/Aug/2018:13:23:57 +0300] Listening to 127.0.0.1:631 (IPv4)
I [29/Aug/2018:13:23:57 +0300] Listening to /run/cups/cups.sock (Domain)
I [29/Aug/2018:13:23:57 +0300] Remote access is disabled.
D [29/Aug/2018:13:23:57 +0300] Added auto ServerAlias saxonia
I [29/Aug/2018:13:23:57 +0300] Loaded configuration file "/etc/cups/cupsd.conf"
D [29/Aug/2018:13:23:57 +0300] Using keychain "/etc/cups/ssl" for server name "saxonia".
I [29/Aug/2018:13:23:57 +0300] Using default TempDir of /var/spool/cups/tmp...
I [29/Aug/2018:13:23:57 +0300] Configured for up to 100 clients.
I [29/Aug/2018:13:23:57 +0300] Allowing up to 100 client connections per host.
I [29/Aug/2018:13:23:57 +0300] Using policy "default" as the default.
I [29/Aug/2018:13:23:57 +0300] Full reload is required.
I [29/Aug/2018:13:23:57 +0300] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 78 types, 114 filters...
D [29/Aug/2018:13:23:57 +0300] Loading printer ricoh-copier...
D [29/Aug/2018:13:23:57 +0300] load_ppd: Loading /var/cache/cups/ricoh-copier.data...
D [29/Aug/2018:13:23:57 +0300] cupsdRegisterPrinter(p=0x55a06a452110(ricoh-copier))
D [29/Aug/2018:13:23:57 +0300] load_ppd: Loading /var/cache/cups/ricoh-copier.data...
D [29/Aug/2018:13:23:57 +0300] cupsdRegisterPrinter(p=0x55a06a452110(ricoh-copier))
I [29/Aug/2018:13:23:57 +0300] Loading job cache file "/var/cache/cups/job.cache"...
D [29/Aug/2018:13:23:57 +0300] [Job 566] Loading from cache...
D [29/Aug/2018:13:23:57 +0300] [Job 567] Loading from cache...
D [29/Aug/2018:13:23:57 +0300] [Job 568] Loading from cache...
I [29/Aug/2018:13:23:57 +0300] Full reload complete.
D [29/Aug/2018:13:23:57 +0300] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)")
I [29/Aug/2018:13:23:57 +0300] Cleaning out old files in "/var/spool/cups/tmp".
D [29/Aug/2018:13:23:57 +0300] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp")
I [29/Aug/2018:13:23:57 +0300] Cleaning out old files in "/var/cache/cups".
D [29/Aug/2018:13:23:57 +0300] service_checkin: pid=9697
D [29/Aug/2018:13:23:57 +0300] service_checkin: 0 listeners.
D [29/Aug/2018:13:23:57 +0300] Creating KeepAlive/PID file "/var/cache/cups/org.cups.cupsd".
D [29/Aug/2018:13:23:57 +0300] Calling FindDeviceById(cups-ricoh-copier)
D [29/Aug/2018:13:23:57 +0300] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-ricoh-copier\' does not exist
D [29/Aug/2018:13:23:57 +0300] Using profile ID "ricoh-copier-Gray..".
D [29/Aug/2018:13:23:57 +0300] Calling CreateProfile(ricoh-copier-Gray..,temp)
D [29/Aug/2018:13:23:57 +0300] Created profile "/org/freedesktop/ColorManager/profiles/ricoh_copier_Gray__".
I [29/Aug/2018:13:23:57 +0300] Registering ICC color profiles for "ricoh-copier".
D [29/Aug/2018:13:23:57 +0300] Calling CreateDevice(cups-ricoh-copier,temp)
D [29/Aug/2018:13:23:57 +0300] Created device "/org/freedesktop/ColorManager/devices/cups_ricoh_copier".
D [29/Aug/2018:13:23:57 +0300] Calling /org/freedesktop/ColorManager/devices/cups_ricoh_copier:AddProfile(/org/freedesktop/ColorManager/profiles/ricoh_copier_Gray__) [soft]
I [29/Aug/2018:13:23:57 +0300] Listening to [v1.::1]:631 on fd 7...
I [29/Aug/2018:13:23:57 +0300] Listening to 127.0.0.1:631 on fd 8...
I [29/Aug/2018:13:23:57 +0300] Listening to /run/cups/cups.sock on fd 9...
I [29/Aug/2018:13:23:57 +0300] Resuming new connection processing...
D [29/Aug/2018:13:23:57 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:23:57 +0300] cupsdAddCert: Adding certificate for PID 0
D [29/Aug/2018:13:23:57 +0300] Discarding unused server-started event...
D [29/Aug/2018:13:23:57 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:23:58 +0300] Report: clients=0
D [29/Aug/2018:13:23:58 +0300] Report: jobs=3
D [29/Aug/2018:13:23:58 +0300] Report: jobs-active=0
D [29/Aug/2018:13:23:58 +0300] Report: printers=1
D [29/Aug/2018:13:23:58 +0300] Report: stringpool-string-count=18243
D [29/Aug/2018:13:23:58 +0300] Report: stringpool-alloc-bytes=10920
D [29/Aug/2018:13:23:58 +0300] Report: stringpool-total-bytes=331792
D [29/Aug/2018:13:23:59 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:23:59 +0300] [Client 1] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:23:59 +0300] [Client 1] Accepted from localhost (Domain)
D [29/Aug/2018:13:23:59 +0300] [Client 1] Waiting for request.
D [29/Aug/2018:13:23:59 +0300] [Client 1] POST / HTTP/1.1
D [29/Aug/2018:13:23:59 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:23:59 +0300] [Client 1] Read: status=200, state=6
D [29/Aug/2018:13:23:59 +0300] [Client 1] No authentication data provided.
D [29/Aug/2018:13:23:59 +0300] [Client 1] 2.0 Get-Jobs 1
D [29/Aug/2018:13:23:59 +0300] Get-Jobs ipp://localhost/
D [29/Aug/2018:13:23:59 +0300] [Client 1] Returning IPP successful-ok for Get-Jobs (ipp://localhost/) from localhost.
D [29/Aug/2018:13:23:59 +0300] [Client 1] Content-Length: 75
D [29/Aug/2018:13:23:59 +0300] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:23:59 +0300] [Client 1] con->http=0x55a06a5c90e0
D [29/Aug/2018:13:23:59 +0300] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x55a06a47d4a0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:23:59 +0300] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:23:59 +0300] [Client 1] bytes=0, http_state=0, data_remaining=75
D [29/Aug/2018:13:23:59 +0300] [Client 1] Flushing write buffer.
D [29/Aug/2018:13:23:59 +0300] [Client 1] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:23:59 +0300] [Client 1] Waiting for request.
D [29/Aug/2018:13:23:59 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:23:59 +0300] [Client 1] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:23:59 +0300] [Client 1] Closing connection.
D [29/Aug/2018:13:23:59 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
I [29/Aug/2018:13:24:24 +0300] Scheduler shutting down normally.
D [29/Aug/2018:13:24:24 +0300] Discarding unused server-stopped event...
D [29/Aug/2018:13:24:24 +0300] Creating KeepAlive/PID file "/var/cache/cups/org.cups.cupsd".
I [29/Aug/2018:13:24:24 +0300] Saving job.cache...
D [29/Aug/2018:13:24:24 +0300] cupsdStopSelect()
I [29/Aug/2018:13:24:24 +0300] Listening to [v1.::1]:631 (IPv6)
I [29/Aug/2018:13:24:24 +0300] Listening to 127.0.0.1:631 (IPv4)
I [29/Aug/2018:13:24:24 +0300] Listening to /run/cups/cups.sock (Domain)
I [29/Aug/2018:13:24:24 +0300] Remote access is disabled.
D [29/Aug/2018:13:24:24 +0300] Added auto ServerAlias saxonia
I [29/Aug/2018:13:24:24 +0300] Loaded configuration file "/etc/cups/cupsd.conf"
D [29/Aug/2018:13:24:24 +0300] Using keychain "/etc/cups/ssl" for server name "saxonia".
I [29/Aug/2018:13:24:24 +0300] Using default TempDir of /var/spool/cups/tmp...
I [29/Aug/2018:13:24:24 +0300] Configured for up to 100 clients.
I [29/Aug/2018:13:24:24 +0300] Allowing up to 100 client connections per host.
I [29/Aug/2018:13:24:24 +0300] Using policy "default" as the default.
I [29/Aug/2018:13:24:24 +0300] Full reload is required.
I [29/Aug/2018:13:24:24 +0300] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 78 types, 114 filters...
D [29/Aug/2018:13:24:24 +0300] Loading printer ricoh-copier...
D [29/Aug/2018:13:24:24 +0300] load_ppd: Loading /var/cache/cups/ricoh-copier.data...
D [29/Aug/2018:13:24:24 +0300] cupsdRegisterPrinter(p=0x55b68fa9d110(ricoh-copier))
D [29/Aug/2018:13:24:24 +0300] load_ppd: Loading /var/cache/cups/ricoh-copier.data...
D [29/Aug/2018:13:24:24 +0300] cupsdRegisterPrinter(p=0x55b68fa9d110(ricoh-copier))
I [29/Aug/2018:13:24:24 +0300] Loading job cache file "/var/cache/cups/job.cache"...
D [29/Aug/2018:13:24:24 +0300] [Job 566] Loading from cache...
D [29/Aug/2018:13:24:24 +0300] [Job 567] Loading from cache...
D [29/Aug/2018:13:24:24 +0300] [Job 568] Loading from cache...
I [29/Aug/2018:13:24:24 +0300] Full reload complete.
D [29/Aug/2018:13:24:24 +0300] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)")
I [29/Aug/2018:13:24:24 +0300] Cleaning out old files in "/var/spool/cups/tmp".
D [29/Aug/2018:13:24:24 +0300] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp")
I [29/Aug/2018:13:24:24 +0300] Cleaning out old files in "/var/cache/cups".
D [29/Aug/2018:13:24:24 +0300] service_checkin: pid=9762
D [29/Aug/2018:13:24:24 +0300] service_checkin: 0 listeners.
D [29/Aug/2018:13:24:24 +0300] Creating KeepAlive/PID file "/var/cache/cups/org.cups.cupsd".
D [29/Aug/2018:13:24:24 +0300] Calling FindDeviceById(cups-ricoh-copier)
D [29/Aug/2018:13:24:24 +0300] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-ricoh-copier\' does not exist
D [29/Aug/2018:13:24:24 +0300] Using profile ID "ricoh-copier-Gray..".
D [29/Aug/2018:13:24:24 +0300] Calling CreateProfile(ricoh-copier-Gray..,temp)
D [29/Aug/2018:13:24:24 +0300] Created profile "/org/freedesktop/ColorManager/profiles/ricoh_copier_Gray__".
I [29/Aug/2018:13:24:24 +0300] Registering ICC color profiles for "ricoh-copier".
D [29/Aug/2018:13:24:24 +0300] Calling CreateDevice(cups-ricoh-copier,temp)
D [29/Aug/2018:13:24:24 +0300] Created device "/org/freedesktop/ColorManager/devices/cups_ricoh_copier".
D [29/Aug/2018:13:24:24 +0300] Calling /org/freedesktop/ColorManager/devices/cups_ricoh_copier:AddProfile(/org/freedesktop/ColorManager/profiles/ricoh_copier_Gray__) [soft]
I [29/Aug/2018:13:24:24 +0300] Listening to [v1.::1]:631 on fd 7...
I [29/Aug/2018:13:24:24 +0300] Listening to 127.0.0.1:631 on fd 8...
I [29/Aug/2018:13:24:24 +0300] Listening to /run/cups/cups.sock on fd 9...
I [29/Aug/2018:13:24:24 +0300] Resuming new connection processing...
D [29/Aug/2018:13:24:24 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:24 +0300] cupsdAddCert: Adding certificate for PID 0
D [29/Aug/2018:13:24:24 +0300] Discarding unused server-started event...
D [29/Aug/2018:13:24:24 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:25 +0300] Report: clients=0
D [29/Aug/2018:13:24:25 +0300] Report: jobs=3
D [29/Aug/2018:13:24:25 +0300] Report: jobs-active=0
D [29/Aug/2018:13:24:25 +0300] Report: printers=1
D [29/Aug/2018:13:24:25 +0300] Report: stringpool-string-count=18243
D [29/Aug/2018:13:24:25 +0300] Report: stringpool-alloc-bytes=10920
D [29/Aug/2018:13:24:25 +0300] Report: stringpool-total-bytes=331792
D [29/Aug/2018:13:24:29 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:29 +0300] [Client 1] Server address is "[v1.::1]".
D [29/Aug/2018:13:24:29 +0300] [Client 1] Accepted from localhost:40666 (IPv6)
D [29/Aug/2018:13:24:29 +0300] [Client 1] Waiting for request.
D [29/Aug/2018:13:24:29 +0300] [Client 1] GET /admin/log/error_log HTTP/1.1
D [29/Aug/2018:13:24:29 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:29 +0300] [Client 1] Read: status=200, state=3
D [29/Aug/2018:13:24:29 +0300] [Client 1] Authorized as "root" using Basic.
D [29/Aug/2018:13:24:29 +0300] cupsdIsAuthorized: username="root"
D [29/Aug/2018:13:24:29 +0300] [Client 1] Processing GET /admin/log/error_log
D [29/Aug/2018:13:24:29 +0300] [Client 1] filename="/var/log/cups/error_log", type=text/plain
D [29/Aug/2018:13:24:29 +0300] [Client 1] cupsdSendHeader: code=200, type="text/plain", auth_type=0
D [29/Aug/2018:13:24:29 +0300] [Client 1] Sending file.
D [29/Aug/2018:13:24:29 +0300] [Client 1] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:29 +0300] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=14342, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:29 +0300] [Client 1] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:29 +0300] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=14342, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:29 +0300] [Client 1] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:29 +0300] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=14342, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:29 +0300] [Client 1] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:29 +0300] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=14342, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:29 +0300] [Client 1] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:29 +0300] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=14342, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:29 +0300] [Client 1] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:29 +0300] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=14342, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:29 +0300] [Client 1] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:29 +0300] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=14342, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:29 +0300] [Client 1] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:29 +0300] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=14342, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:29 +0300] [Client 1] Flushing write buffer.
D [29/Aug/2018:13:24:29 +0300] [Client 1] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:29 +0300] [Client 1] Waiting for request.
D [29/Aug/2018:13:24:29 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:40 +0300] [Client 1] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:40 +0300] [Client 1] Closing connection.
D [29/Aug/2018:13:24:40 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 2] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 2] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 2] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 3] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 3] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 3] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] [Client 2] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 2] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 3] POST / HTTP/1.1
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=200, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] No authentication data provided.
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 3] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:46 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:46 +0300] [Client 3] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:46 +0300] [Client 3] Content-Length: 874
D [29/Aug/2018:13:24:46 +0300] [Client 3] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:46 +0300] [Client 3] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:46 +0300] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fac84a0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:46 +0300] [Client 3] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:46 +0300] [Client 3] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:46 +0300] [Client 3] Flushing write buffer.
D [29/Aug/2018:13:24:46 +0300] [Client 3] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:46 +0300] [Client 3] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 4] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 4] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 4] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] [Client 3] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 3] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 4] GET /printers/ricoh-copier.ppd HTTP/1.1
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 4] Read: status=200, state=3
D [29/Aug/2018:13:24:46 +0300] [Client 4] No authentication data provided.
D [29/Aug/2018:13:24:46 +0300] [Client 4] Processing GET /printers/ricoh-copier.ppd
D [29/Aug/2018:13:24:46 +0300] [Client 4] filename="/etc/cups/ppd/ricoh-copier.ppd", type=application/vnd.cups-ppd
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdSendHeader: code=200, type="application/vnd.cups-ppd", auth_type=0
D [29/Aug/2018:13:24:46 +0300] [Client 4] Sending file.
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:46 +0300] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=51353, response=(nil)(), pipe_pid=0, file=13
D [29/Aug/2018:13:24:46 +0300] [Client 4] Flushing write buffer.
D [29/Aug/2018:13:24:46 +0300] [Client 4] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:46 +0300] [Client 4] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 4] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 4] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 5] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 5] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 5] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 6] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 6] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 6] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] [Client 5] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 5] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 6] POST / HTTP/1.1
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=200, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] No authentication data provided.
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 6] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:46 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:46 +0300] [Client 6] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:46 +0300] [Client 6] Content-Length: 874
D [29/Aug/2018:13:24:46 +0300] [Client 6] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:46 +0300] [Client 6] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:46 +0300] [Client 6] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fb4fcc0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:46 +0300] [Client 6] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:46 +0300] [Client 6] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:46 +0300] [Client 6] Flushing write buffer.
D [29/Aug/2018:13:24:46 +0300] [Client 6] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:46 +0300] [Client 6] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 6] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 6] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 7] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 7] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 7] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 8] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 8] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 8] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] [Client 7] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 7] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 8] POST / HTTP/1.1
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 8] Read: status=200, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 8] No authentication data provided.
D [29/Aug/2018:13:24:46 +0300] [Client 8] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:46 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:46 +0300] [Client 8] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:46 +0300] [Client 8] Content-Length: 874
D [29/Aug/2018:13:24:46 +0300] [Client 8] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:46 +0300] [Client 8] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:46 +0300] [Client 8] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fac84a0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:46 +0300] [Client 8] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:46 +0300] [Client 8] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:46 +0300] [Client 8] Flushing write buffer.
D [29/Aug/2018:13:24:46 +0300] [Client 8] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:46 +0300] [Client 8] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 8] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 8] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 9] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 9] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 9] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 10] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 10] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 10] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] [Client 9] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 9] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 10] POST / HTTP/1.1
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=200, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] No authentication data provided.
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 10] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:46 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:46 +0300] [Client 10] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:46 +0300] [Client 10] Content-Length: 874
D [29/Aug/2018:13:24:46 +0300] [Client 10] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:46 +0300] [Client 10] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:46 +0300] [Client 10] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fb4fcc0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:46 +0300] [Client 10] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:46 +0300] [Client 10] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:46 +0300] [Client 10] Flushing write buffer.
D [29/Aug/2018:13:24:46 +0300] [Client 10] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:46 +0300] [Client 10] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 10] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 10] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 11] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 11] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 11] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 12] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 12] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 12] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] [Client 11] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 11] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 12] POST / HTTP/1.1
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=200, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] No authentication data provided.
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 12] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:46 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:46 +0300] [Client 12] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:46 +0300] [Client 12] Content-Length: 874
D [29/Aug/2018:13:24:46 +0300] [Client 12] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:46 +0300] [Client 12] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:46 +0300] [Client 12] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fac84a0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:46 +0300] [Client 12] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:46 +0300] [Client 12] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:46 +0300] [Client 12] Flushing write buffer.
D [29/Aug/2018:13:24:46 +0300] [Client 12] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:46 +0300] [Client 12] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 12] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 12] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 13] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 13] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 13] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 14] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:46 +0300] [Client 14] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:46 +0300] [Client 14] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] [Client 13] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 13] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 14] POST / HTTP/1.1
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=200, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] No authentication data provided.
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] Read: status=100, state=6
D [29/Aug/2018:13:24:46 +0300] [Client 14] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:46 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:46 +0300] [Client 14] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:46 +0300] [Client 14] Content-Length: 874
D [29/Aug/2018:13:24:46 +0300] [Client 14] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:46 +0300] [Client 14] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:46 +0300] [Client 14] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fb4fcc0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:46 +0300] [Client 14] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:46 +0300] [Client 14] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:46 +0300] [Client 14] Flushing write buffer.
D [29/Aug/2018:13:24:46 +0300] [Client 14] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:46 +0300] [Client 14] Waiting for request.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:46 +0300] [Client 14] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:46 +0300] [Client 14] Closing connection.
D [29/Aug/2018:13:24:46 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 15] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 15] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 15] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 16] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 16] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 16] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] [Client 15] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 15] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 16] POST / HTTP/1.1
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 16] Read: status=200, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 16] No authentication data provided.
D [29/Aug/2018:13:24:47 +0300] [Client 16] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:47 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:47 +0300] [Client 16] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:47 +0300] [Client 16] Content-Length: 874
D [29/Aug/2018:13:24:47 +0300] [Client 16] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:47 +0300] [Client 16] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:47 +0300] [Client 16] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fac84a0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:47 +0300] [Client 16] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:47 +0300] [Client 16] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:47 +0300] [Client 16] Flushing write buffer.
D [29/Aug/2018:13:24:47 +0300] [Client 16] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:47 +0300] [Client 16] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 16] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 16] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 17] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 17] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 17] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 18] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 18] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 18] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] [Client 17] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 17] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 18] POST / HTTP/1.1
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 18] Read: status=200, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 18] No authentication data provided.
D [29/Aug/2018:13:24:47 +0300] [Client 18] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:47 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:47 +0300] [Client 18] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:47 +0300] [Client 18] Content-Length: 874
D [29/Aug/2018:13:24:47 +0300] [Client 18] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:47 +0300] [Client 18] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:47 +0300] [Client 18] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fb4fcc0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:47 +0300] [Client 18] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:47 +0300] [Client 18] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:47 +0300] [Client 18] Flushing write buffer.
D [29/Aug/2018:13:24:47 +0300] [Client 18] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:47 +0300] [Client 18] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 18] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 18] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 19] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 19] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 19] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 20] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 20] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 20] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] [Client 19] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 19] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 20] POST / HTTP/1.1
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=200, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] No authentication data provided.
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 20] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:47 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:47 +0300] [Client 20] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:47 +0300] [Client 20] Content-Length: 874
D [29/Aug/2018:13:24:47 +0300] [Client 20] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:47 +0300] [Client 20] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:47 +0300] [Client 20] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fac84a0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:47 +0300] [Client 20] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:47 +0300] [Client 20] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:47 +0300] [Client 20] Flushing write buffer.
D [29/Aug/2018:13:24:47 +0300] [Client 20] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:47 +0300] [Client 20] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 20] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 20] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 21] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 21] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 21] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 22] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 22] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 22] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] [Client 21] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 21] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 22] POST / HTTP/1.1
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=200, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] No authentication data provided.
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 22] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:47 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:47 +0300] [Client 22] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:47 +0300] [Client 22] Content-Length: 874
D [29/Aug/2018:13:24:47 +0300] [Client 22] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:47 +0300] [Client 22] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:47 +0300] [Client 22] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fb4fcc0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:47 +0300] [Client 22] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:47 +0300] [Client 22] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:47 +0300] [Client 22] Flushing write buffer.
D [29/Aug/2018:13:24:47 +0300] [Client 22] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:47 +0300] [Client 22] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 22] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 22] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 23] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 23] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 23] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 24] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:47 +0300] [Client 24] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:47 +0300] [Client 24] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] [Client 23] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 23] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 24] POST / HTTP/1.1
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=200, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] No authentication data provided.
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] Read: status=100, state=6
D [29/Aug/2018:13:24:47 +0300] [Client 24] 2.0 CUPS-Get-Printers 1
D [29/Aug/2018:13:24:47 +0300] CUPS-Get-Printers
D [29/Aug/2018:13:24:47 +0300] [Client 24] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost.
D [29/Aug/2018:13:24:47 +0300] [Client 24] Content-Length: 874
D [29/Aug/2018:13:24:47 +0300] [Client 24] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:47 +0300] [Client 24] con->http=0x55b68fc193b0
D [29/Aug/2018:13:24:47 +0300] [Client 24] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=874, response=0x55b68fac84a0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:47 +0300] [Client 24] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:47 +0300] [Client 24] bytes=0, http_state=0, data_remaining=874
D [29/Aug/2018:13:24:47 +0300] [Client 24] Flushing write buffer.
D [29/Aug/2018:13:24:47 +0300] [Client 24] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:47 +0300] [Client 24] Waiting for request.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [29/Aug/2018:13:24:47 +0300] [Client 24] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:47 +0300] [Client 24] Closing connection.
D [29/Aug/2018:13:24:47 +0300] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [29/Aug/2018:13:24:48 +0300] [Client 25] Server address is "/run/cups/cups.sock".
D [29/Aug/2018:13:24:48 +0300] [Client 25] Accepted from localhost (Domain)
D [29/Aug/2018:13:24:48 +0300] [Client 25] Waiting for request.
D [29/Aug/2018:13:24:48 +0300] [Client 25] POST /printers/ricoh-copier HTTP/1.1
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=200, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] No authentication data provided.
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] 2.1 Print-Job 1
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] [Client 25] Read: status=100, state=6
D [29/Aug/2018:13:24:48 +0300] Print-Job ipp://localhost:631/printers/ricoh-copier
D [29/Aug/2018:13:24:48 +0300] [Job ???] Auto-typing file...
I [29/Aug/2018:13:24:48 +0300] [Job ???] Request file type is application/pdf.
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(---J-)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [29/Aug/2018:13:24:48 +0300] [Job 569] Applying default options...
D [29/Aug/2018:13:24:48 +0300] add_job: requesting-user-name="plp"
I [29/Aug/2018:13:24:48 +0300] [Job 569] Adding start banner page "none".
D [29/Aug/2018:13:24:48 +0300] Discarding unused job-created event...
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(---J-)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [29/Aug/2018:13:24:48 +0300] [Job 569] Adding end banner page "none".
I [29/Aug/2018:13:24:48 +0300] [Job 569] File of type application/pdf queued by "plp".
D [29/Aug/2018:13:24:48 +0300] [Job 569] hold_until=0
I [29/Aug/2018:13:24:48 +0300] [Job 569] Queued on "ricoh-copier" by "plp".
D [29/Aug/2018:13:24:48 +0300] [Job 569] time-at-processing=1535538288
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(---J-)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [29/Aug/2018:13:24:48 +0300] Discarding unused printer-state-changed event...
D [29/Aug/2018:13:24:48 +0300] [Job 569] 2 filters for job:
D [29/Aug/2018:13:24:48 +0300] [Job 569] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [29/Aug/2018:13:24:48 +0300] [Job 569] foomatic-rip (application/vnd.cups-pdf to printer/ricoh-copier, cost 0)
D [29/Aug/2018:13:24:48 +0300] [Job 569] job-sheets=none,none
D [29/Aug/2018:13:24:48 +0300] [Job 569] argv[0]="ricoh-copier"
D [29/Aug/2018:13:24:48 +0300] [Job 569] argv[1]="569"
D [29/Aug/2018:13:24:48 +0300] [Job 569] argv[2]="plp"
D [29/Aug/2018:13:24:48 +0300] [Job 569] argv[3]="Payment Receipt #22702600"
D [29/Aug/2018:13:24:48 +0300] [Job 569] argv[4]="1"
D [29/Aug/2018:13:24:48 +0300] [Job 569] argv[5]="OutputBin=Default number-up=1 Password=None noCollate PageSize=A4 InputSlot=Auto Duplex=DuplexNoTumble JobType=Normal UserCode=None MediaType=Plain job-uuid=urn:uuid:4d14de8b-4f88-3551-6184-9952cdda9f49 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1535538288 time-at-processing=1535538288"
D [29/Aug/2018:13:24:48 +0300] [Job 569] argv[6]="/var/spool/cups/d00569-001"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[7]="CUPS_STATEDIR=/run/cups"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[8]="HOME=/var/spool/cups/tmp"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[10]="SERVER_ADMIN=root@saxonia"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[11]="SOFTWARE=CUPS/2.2.8"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[13]="USER=root"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[14]="CUPS_MAX_MESSAGE=2047"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[15]="CUPS_SERVER=/run/cups/cups.sock"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[17]="IPP_PORT=631"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[18]="CHARSET=utf-8"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[19]="LANG=en_GB.UTF-8"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[20]="PPD=/etc/cups/ppd/ricoh-copier.ppd"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[21]="RIP_MAX_CACHE=128m"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[22]="CONTENT_TYPE=application/pdf"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[23]="DEVICE_URI=socket://ricoh-copier"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[24]="PRINTER_INFO=Ricoh copier"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[25]="PRINTER_LOCATION=Office"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[26]="PRINTER=ricoh-copier"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[27]="PRINTER_STATE_REASONS=none"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[28]="CUPS_FILETYPE=document"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-pdf"
D [29/Aug/2018:13:24:48 +0300] [Job 569] envp[30]="AUTH_I****"
I [29/Aug/2018:13:24:48 +0300] [Job 569] Started filter /usr/lib/cups/filter/pdftopdf (PID 9789)
I [29/Aug/2018:13:24:48 +0300] [Job 569] Started filter /usr/lib/cups/filter/foomatic-rip (PID 9790)
I [29/Aug/2018:13:24:48 +0300] [Job 569] Started backend /usr/lib/cups/backend/socket (PID 9791)
D [29/Aug/2018:13:24:48 +0300] Discarding unused job-state-changed event...
D [29/Aug/2018:13:24:48 +0300] [Client 25] Returning IPP successful-ok for Print-Job (ipp://localhost:631/printers/ricoh-copier) from localhost.
D [29/Aug/2018:13:24:48 +0300] [Client 25] Content-Length: 193
D [29/Aug/2018:13:24:48 +0300] [Client 25] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [29/Aug/2018:13:24:48 +0300] [Client 25] con->http=0x55b68fc140e0
D [29/Aug/2018:13:24:48 +0300] [Client 25] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=193, response=0x55b68fc0ed80(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [29/Aug/2018:13:24:48 +0300] [Client 25] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [29/Aug/2018:13:24:48 +0300] [Client 25] bytes=0, http_state=0, data_remaining=193
D [29/Aug/2018:13:24:48 +0300] [Client 25] Flushing write buffer.
D [29/Aug/2018:13:24:48 +0300] [Client 25] New state is HTTP_STATE_WAITING
D [29/Aug/2018:13:24:48 +0300] [Client 25] Waiting for request.
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [29/Aug/2018:13:24:48 +0300] [Client 25] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [29/Aug/2018:13:24:48 +0300] [Client 25] Closing connection.
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: +connecting-to-device
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(---J-)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] Discarding unused printer-state-changed event...
D [29/Aug/2018:13:24:48 +0300] [Job 569] Looking up \"ricoh-copier\"...
D [29/Aug/2018:13:24:48 +0300] [Job 569] Calling FindDeviceById(cups-ricoh-copier)
D [29/Aug/2018:13:24:48 +0300] [Job 569] Found device /org/freedesktop/ColorManager/devices/cups_ricoh_copier
D [29/Aug/2018:13:24:48 +0300] [Job 569] Calling org.freedesktop.ColorManager.Device.Get(ProfilingInhibitors)
D [29/Aug/2018:13:24:48 +0300] [Job 569] \'CM Color Calibration\' Mode in SPOOLER-LESS: Off
D [29/Aug/2018:13:24:48 +0300] [Job 569] Getting input from file 
D [29/Aug/2018:13:24:48 +0300] [Job 569] foomatic-rip version 1.20.4 running...
D [29/Aug/2018:13:24:48 +0300] [Job 569] Parsing PPD file ...
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option ColorSpace
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option OptionTray
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option ShiftTray
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option InnerTray2
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option Finisher
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option Duplex
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option GSDuplex
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -connecting-to-device
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(---J-)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [29/Aug/2018:13:24:48 +0300] [Job 569] ricoh-copier=192.168.201.253
D [29/Aug/2018:13:24:48 +0300] Discarding unused printer-state-changed event...
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option JCLDuplex
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option Collate
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option Resolution
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option GSResolution
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option JCLResolution
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option ColorModel
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option GSCmdLine
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option PageSize
D [29/Aug/2018:13:24:48 +0300] [Job 569] pdftopdf: Last filter determined by the PPD: foomatic-rip; FINAL_CONTENT_TYPE: application/vnd.cups-pdf => pdftopdf will log pages in page_log.
D [29/Aug/2018:13:24:48 +0300] [Job 569] PAGE: 1 1
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(---J-)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(---J-)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] Discarding unused job-progress event...
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option InputSlot
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option RIPrintMode
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option MediaType
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option OutputBin
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option StapleLocation
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option PaperDimension
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option ImageableArea
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option JobType
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option Password
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option UserCode
D [29/Aug/2018:13:24:48 +0300] [Job 569] Added option Font
D [29/Aug/2018:13:24:48 +0300] [Job 569] Parameter Summary
D [29/Aug/2018:13:24:48 +0300] [Job 569] -----------------
D [29/Aug/2018:13:24:48 +0300] [Job 569] Spooler: cups
D [29/Aug/2018:13:24:48 +0300] [Job 569] Printer: ricoh-copier
D [29/Aug/2018:13:24:48 +0300] [Job 569] Shell: /bin/bash
D [29/Aug/2018:13:24:48 +0300] [Job 569] PPD file: /etc/cups/ppd/ricoh-copier.ppd
D [29/Aug/2018:13:24:48 +0300] [Job 569] ATTR file: 
D [29/Aug/2018:13:24:48 +0300] [Job 569] Printer model: Ricoh Aficio MP 2352 , pxlmono-Ricoh 20161206 (OpenPrinting LSB 3.2)
D [29/Aug/2018:13:24:48 +0300] [Job 569] Job title: Payment Receipt 22702600
D [29/Aug/2018:13:24:48 +0300] [Job 569] File(s) to be printed:
D [29/Aug/2018:13:24:48 +0300] [Job 569] <STDIN>
D [29/Aug/2018:13:24:48 +0300] [Job 569] Ghostscript extra search path (\'GS_LIB\'): /usr/share/cups/fonts
D [29/Aug/2018:13:24:48 +0300] [Job 569] Printing system options:
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'number-up=1\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Unknown option number-up=1.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'job-uuid=urn:uuid:4d14de8b-4f88-3551-6184-9952cdda9f49\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Unknown option job-uuid=urn:uuid:4d14de8b-4f88-3551-6184-9952cdda9f49.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'job-originating-host-name=localhost\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Unknown option job-originating-host-name=localhost.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'date-time-at-creation=\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Unknown option date-time-at-creation=.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'date-time-at-processing=\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Unknown option date-time-at-processing=.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'time-at-creation=1535538288\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Unknown option time-at-creation=1535538288.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'time-at-processing=1535538288\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Unknown option time-at-processing=1535538288.
D [29/Aug/2018:13:24:48 +0300] [Job 569] CM Color Calibration Mode in CUPS: Off
D [29/Aug/2018:13:24:48 +0300] [Job 569] Options from the PPD file:
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'OutputBin=Default\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'Password=None\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'noCollate\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'PageSize=A4\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'InputSlot=Auto\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'Duplex=DuplexNoTumble\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'JobType=Normal\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'UserCode=None\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Pondering option \'MediaType=Plain\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] ================================================
D [29/Aug/2018:13:24:48 +0300] [Job 569] File: <STDIN>
D [29/Aug/2018:13:24:48 +0300] [Job 569] ================================================
D [29/Aug/2018:13:24:48 +0300] [Job 569] Filetype: PDF
D [29/Aug/2018:13:24:48 +0300] [Job 569] Neither PDF renderer command line nor Ghostscript-based renderer command line found
D [29/Aug/2018:13:24:48 +0300] [Job 569] Driver does not understand PDF input, converting to PostScript
D [29/Aug/2018:13:24:48 +0300] [Job 569] Storing temporary files in /var/spool/cups/tmp
D [29/Aug/2018:13:24:48 +0300] [Job 569] PID 9789 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Starting process \"pdf-to-ps\" (generation 1)
D [29/Aug/2018:13:24:48 +0300] [Job 569] Printer make and model: Ricoh RICOH Aficio MP 2352 PS3
D [29/Aug/2018:13:24:48 +0300] [Job 569] Running command line for pstops: pstops 569 plp \'Payment Receipt 22702600\' 1 \' OutputBin=Default Password=None PageSize=A4 InputSlot=Auto Duplex=DuplexNoTumble JobType=Normal UserCode=None MediaType=Plain job-uuid=urn:uuid:4d14de8b-4f88-3551-6184-9952cdda9f49 job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1535538288 time-at-processing=1535538288\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] Using image rendering resolution 600 dpi
D [29/Aug/2018:13:24:48 +0300] [Job 569] Running command line for gs: gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sDEVICE=ps2write -dShowAcroForm -sOUTPUTFILE=%stdout -dLanguageLevel=3 -r600 -dCompressFonts=false -dNoT3CCITT -dNOINTERPOLATE -c \'save pop\' -f /var/spool/cups/tmp/foomatic-Qwfkfb
D [29/Aug/2018:13:24:48 +0300] [Job 569] Started filter gs (PID 9793)
D [29/Aug/2018:13:24:48 +0300] [Job 569] Started filter pstops (PID 9794)
D [29/Aug/2018:13:24:48 +0300] [Job 569] ATTR: marker-colors=#000000
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(P----)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] [Job 569] ATTR: marker-names=\'\"Toner\"\'
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(P----)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] [Job 569] ATTR: marker-types=toner
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(P----)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] [Job 569] ATTR: marker-levels=-1
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(P----)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] [Job 569] new_supply_state=0, change_state=ffff
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -developer-low-report
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -developer-empty-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -marker-supply-low-report
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -marker-supply-empty-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -opc-near-eol-report
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -opc-life-over-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -toner-low-report
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -toner-empty-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -waste-receptacle-almost-full-report
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -waste-receptacle-full-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -cleaner-life-almost-over-report
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -cleaner-life-over-warning
D [29/Aug/2018:13:24:48 +0300] Discarding unused printer-state-changed event...
D [29/Aug/2018:13:24:48 +0300] [Job 569] new_state=0, change_state=ffff
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -media-empty-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -door-open-report
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -media-jam-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -input-tray-missing-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -output-tray-missing-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -marker-supply-missing-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -output-area-almost-full-report
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -output-area-full-warning
D [29/Aug/2018:13:24:48 +0300] [Job 569] backendWaitLoop(snmp_fd=5, addr=0x55b2d33e12b8, side_cb=0x55b2d2ae1ec0)
D [29/Aug/2018:13:24:48 +0300] [Job 569] Page = 595x842; 12,12 to 583,830
D [29/Aug/2018:13:24:48 +0300] [Job 569] slow_collate=0, slow_duplex=0, slow_order=0
D [29/Aug/2018:13:24:48 +0300] [Job 569] Before copy_comments - %!PS-Adobe-3.0
D [29/Aug/2018:13:24:48 +0300] [Job 569] %!PS-Adobe-3.0
D [29/Aug/2018:13:24:48 +0300] [Job 569] %%BoundingBox: 0 0 596 842
D [29/Aug/2018:13:24:48 +0300] [Job 569] %%HiResBoundingBox: 0 0 596.00 842.00
D [29/Aug/2018:13:24:48 +0300] [Job 569] %%Creator: GPL Ghostscript 923 (ps2write)
D [29/Aug/2018:13:24:48 +0300] [Job 569] %%LanguageLevel: 2
D [29/Aug/2018:13:24:48 +0300] [Job 569] %%CreationDate: D:20180829132448+03\'00\'
D [29/Aug/2018:13:24:48 +0300] [Job 569] %%Pages: 1
D [29/Aug/2018:13:24:48 +0300] [Job 569] %%EndComments
D [29/Aug/2018:13:24:48 +0300] [Job 569] Before copy_prolog - %%BeginProlog
D [29/Aug/2018:13:24:48 +0300] [Job 569] Filetype: PostScript
D [29/Aug/2018:13:24:48 +0300] [Job 569] Reading PostScript input ...
D [29/Aug/2018:13:24:48 +0300] [Job 569] --> This document is DSC-conforming!
D [29/Aug/2018:13:24:48 +0300] [Job 569] Found %RBINumCopies: 1
D [29/Aug/2018:13:24:48 +0300] [Job 569] -----------
D [29/Aug/2018:13:24:48 +0300] [Job 569] Found: %%BeginProlog
D [29/Aug/2018:13:24:48 +0300] [Job 569] Inserting option code into \"Prolog\" section.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Flushing FIFO.
D [29/Aug/2018:13:24:48 +0300] [Job 569] \"Prolog\" section is missing, inserting it.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Inserting option code into \"Prolog\" section.
D [29/Aug/2018:13:24:48 +0300] [Job 569] Starting renderer with command: \"(printf \'\\033%%-12345X@PJL\\n@PJL JOB\\n@PJL SET COPIES=1\\n\'|perl -p -e \"s/\\x26copies\\x3b/1/\");
D [29/Aug/2018:13:24:48 +0300] [Job 569] (gs -q -dBATCH -dPARANOIDSAFER -dNOPAUSE -dNOINTERPOLATE  -sDEVICE=pxlmono -r600x600 -sPAPERSIZE=a4 -sOutputFile=- -  | perl -p -e \"s/\\xf8\\x26\\xc0\\x00\\xf8\\x34/\\xf8\\x26\\xc0\\x01\\xf8\\x35/g\" | perl -p -e \"s/^\\x1b\\x25-12345X//\" | perl -p -e \"s/\\xc1\\x01\\x00\\xf8\\x31\\x44/\\x44/g\");
D [29/Aug/2018:13:24:48 +0300] [Job 569] (printf \'@PJL\\n@PJL EOJ\\n\\033%%-12345X\')\"
D [29/Aug/2018:13:24:48 +0300] [Job 569] Starting process \"kid3\" (generation 1)
D [29/Aug/2018:13:24:48 +0300] [Job 569] Closing renderer
D [29/Aug/2018:13:24:48 +0300] [Job 569] Starting process \"kid4\" (generation 2)
D [29/Aug/2018:13:24:48 +0300] [Job 569] Starting process \"renderer\" (generation 2)
D [29/Aug/2018:13:24:48 +0300] [Job 569] JCL: \033%-12345X@PJL
D [29/Aug/2018:13:24:48 +0300] [Job 569] @PJL SET RESOLUTION=600
D [29/Aug/2018:13:24:48 +0300] [Job 569] @PJL SET ECONOMODE=OFF
D [29/Aug/2018:13:24:48 +0300] [Job 569] @PJL SET DUPLEX=ON\\n@PJL SET BINDING=LONGEDGE
D [29/Aug/2018:13:24:48 +0300] [Job 569] @PJL SET MEDIATYPE=PLAIN
D [29/Aug/2018:13:24:48 +0300] [Job 569] @PJL SET OUTBIN=SYSDEFAULT
D [29/Aug/2018:13:24:48 +0300] [Job 569] @PJL SET STAPLE=OFF
D [29/Aug/2018:13:24:48 +0300] [Job 569] <job data> \033%-12345X@PJL RESET
D [29/Aug/2018:13:24:48 +0300] [Job 569] Connecting to ricoh-copier:9100
D [29/Aug/2018:13:24:48 +0300] [Job 569] Connecting to printer.
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(---J-)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] [Job 569] Set job-printer-state-message to "Connecting to printer.", current level=INFO
D [29/Aug/2018:13:24:48 +0300] Discarding unused job-progress event...
D [29/Aug/2018:13:24:48 +0300] Discarding unused printer-state-changed event...
D [29/Aug/2018:13:24:48 +0300] [Job 569] renderer exited with status 0
D [29/Aug/2018:13:24:48 +0300] [Job 569] kid4 exited with status 0
D [29/Aug/2018:13:24:48 +0300] [Job 569] kid3 finished
D [29/Aug/2018:13:24:48 +0300] [Job 569] STATE: -connecting-to-device
D [29/Aug/2018:13:24:48 +0300] [Job 569] Connected to printer.
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(---J-)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] [Job 569] Set job-printer-state-message to "Connected to printer.", current level=INFO
D [29/Aug/2018:13:24:48 +0300] Discarding unused job-progress event...
D [29/Aug/2018:13:24:48 +0300] Discarding unused printer-state-changed event...
D [29/Aug/2018:13:24:48 +0300] [Job 569] Connected to 192.168.201.253:9100...
D [29/Aug/2018:13:24:48 +0300] [Job 569] backendRunLoop(print_fd=0, device_fd=6, snmp_fd=5, addr=0x55b2d33e12b8, use_bc=1, side_cb=0x55b2d2ae1ec0)
D [29/Aug/2018:13:24:48 +0300] [Job 569] Read 8192 bytes of print data...
D [29/Aug/2018:13:24:48 +0300] [Job 569] kid3 exited with status 0
D [29/Aug/2018:13:24:48 +0300] [Job 569] ATTR: marker-levels=-1
D [29/Aug/2018:13:24:48 +0300] cupsdMarkDirty(P----)
D [29/Aug/2018:13:24:48 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:48 +0300] [Job 569] new_supply_state=0, change_state=0
D [29/Aug/2018:13:24:48 +0300] Discarding unused printer-state-changed event...
D [29/Aug/2018:13:24:48 +0300] [Job 569] new_state=0, change_state=0
D [29/Aug/2018:13:24:48 +0300] [Job 569] Wrote 8192 bytes of print data...
D [29/Aug/2018:13:24:48 +0300] [Job 569] Read 4669 bytes of print data...
D [29/Aug/2018:13:24:48 +0300] [Job 569] Wrote 4669 bytes of print data...
D [29/Aug/2018:13:24:53 +0300] [Job 569] ATTR: marker-levels=-1
D [29/Aug/2018:13:24:53 +0300] cupsdMarkDirty(P----)
D [29/Aug/2018:13:24:53 +0300] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:53 +0300] [Job 569] new_supply_state=0, change_state=0
D [29/Aug/2018:13:24:53 +0300] Discarding unused printer-state-changed event...
D [29/Aug/2018:13:24:53 +0300] [Job 569] new_state=0, change_state=0
D [29/Aug/2018:13:24:55 +0300] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [29/Aug/2018:13:24:55 +0300] [Client 26] Server address is "[v1.::1]".
D [29/Aug/2018:13:24:55 +0300] [Client 26] Accepted from localhost:40670 (IPv6)
D [29/Aug/2018:13:24:55 +0300] [Client 26] Waiting for request.
D [29/Aug/2018:13:24:55 +0300] [Client 26] GET /admin/log/error_log HTTP/1.1
D [29/Aug/2018:13:24:55 +0300] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [29/Aug/2018:13:24:55 +0300] [Client 26] Read: status=200, state=3
D [29/Aug/2018:13:24:55 +0300] [Client 26] Authorized as "root" using Basic.
D [29/Aug/2018:13:24:55 +0300] cupsdIsAuthorized: username="root"
D [29/Aug/2018:13:24:55 +0300] [Client 26] Processing GET /admin/log/error_log

Any ideas would be greatly appreciated.

P.S. I've already tried deleting and re-creating the printer, and completely removing (pacman -Rns) and re-installing all printing-related packages, but to no avail.

Last edited by plp (2018-08-29 11:21:56)

GoldbergAF · 2018-08-31 17:24:27

Seeing the same issue with a Ricoh MP C2800. Cropped up at some point in the last month or so judging from my last print jobs. Maybe it's a Ricoh-specific issue?

Edit: Tried a Brother printer and that works fine.

Last edited by GoldbergAF (2018-08-31 18:49:25)

plp · 2018-08-31 20:22:34

GoldbergAF:

This is interesting. I'm the maintainer of the openprinting-ppds-pxlcolor-ricoh and openprinting-ppds-pxlmono-ricoh PCL drivers for Ricoh. But I haven't done anything to the packages recently because the driver hasn't really changed since 2016.

There's also openprinting-ppds-postscript-ricoh, which uses Postscript. I wonder if that works and, if so, whether the problem lies with Ghostscript or something.

plp · 2018-08-31 20:32:24

Update: It doesn't for me, because my printer doesn't support Postscript. However, there's a native PDF driver, which my printer should support. I'll try to make an AUR package for that and will let you know of the results.

plp · 2018-08-31 20:46:07

Another update:

Unfortunately, making an AUR package for the PDF driver will be a bit of a challenge, as Open Printing doesn't provide an RPM or a DEB for it.

In spite of that, I downloaded the PPD file directly from their website and installed it for my printer using the Cups web interface. And now it works!

Trouble is, your printer (the C2800) isn't supported by it, and I'm sure there are a lot of Ricoh drivers out there that are dependent on the pxlmono and/or the pxlcolor drivers. So, we still need to find out what has caused the problem with them.

Last edited by plp (2018-08-31 20:54:33)

arai · 2018-10-02 18:31:50

I had the same problem with Aficio MP 4001. Everything used to work fine before but now every time I sent a print command (even CUPS test page), the printer would go bonkers. The first page printed would start with "[Error handled by...]" and then page after page with one-line of gibberish or nothing at all. I had to unplug the device to make it stop.

Tried Postscript-Ricoh as well as PDF-Ricoh from OpenPrinting with no success. In the end the driver that worked for me was CUPS+Gutenprint v5.2.14. It doesn't offer all features like finishing with staples but at least it helps me print stuff.

Arch Linux

#1 2018-08-29 10:48:55

Suddenly can't print anything

#2 2018-08-31 17:24:27

Re: Suddenly can't print anything

#3 2018-08-31 20:22:34

Re: Suddenly can't print anything

#4 2018-08-31 20:32:24

Re: Suddenly can't print anything

#5 2018-08-31 20:46:07

Re: Suddenly can't print anything

#6 2018-10-02 18:31:50

Re: Suddenly can't print anything

Board footer