I was using Debian 8 with local HP Laserjet 1022 (USB) without problems. Upon upgrade to Debian 9 printing became impossible. hp-lip and cups were reinstalled several times. CUPS detects the printer correctly, but printing a test page does nothing: no errors shown, print job terminates properly. But nothing comes from the printer. Interestingly printing is possible from win7 which runs in Virtualbox on this machine.
There is printer.conf file:
Code: Select all
# Printer configuration file for CUPS v2.2.1
# Written by cupsd
# DO NOT EDIT THIS FILE WHEN CUPSD IS RUNNING
<DefaultPrinter HP_LaserJet_1022>
UUID urn:uuid:a1643099-03c9-3452-68fb-a519a6cd6523
Info HP LaserJet 1022
Location Local Printer
MakeModel HP LaserJet 1022 Foomatic/foo2zjs-z1 (recommended)
DeviceURI usb://HP/LaserJet%201022?serial=JM154Y7
State Idle
StateTime 1548032551
ConfigTime 1548032529
Type 8425476
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy retry-job
</DefaultPrinter>
Code: Select all
lp test
Code: Select all
D [20/Jan/2019:18:25:07 -0700] [Client 21] Server address is "/var/run/cups/cups.sock".
D [20/Jan/2019:18:25:07 -0700] [Client 21] Accepted from localhost (Domain)
D [20/Jan/2019:18:25:07 -0700] [Client 21] Waiting for request.
I [20/Jan/2019:18:25:07 -0700] Expiring subscriptions...
D [20/Jan/2019:18:25:07 -0700] Report: clients=3
D [20/Jan/2019:18:25:07 -0700] Report: jobs=16
D [20/Jan/2019:18:25:07 -0700] Report: jobs-active=0
D [20/Jan/2019:18:25:07 -0700] Report: printers=1
D [20/Jan/2019:18:25:07 -0700] Report: stringpool-string-count=15148
D [20/Jan/2019:18:25:07 -0700] Report: stringpool-alloc-bytes=9792
D [20/Jan/2019:18:25:07 -0700] Report: stringpool-total-bytes=279992
D [20/Jan/2019:18:25:07 -0700] [Client 21] POST / HTTP/1.1
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [20/Jan/2019:18:25:07 -0700] [Client 21] Read: status=200
D [20/Jan/2019:18:25:07 -0700] [Client 21] No authentication data provided.
D [20/Jan/2019:18:25:07 -0700] [Client 21] 2.0 CUPS-Get-Default 1
D [20/Jan/2019:18:25:07 -0700] CUPS-Get-Default
D [20/Jan/2019:18:25:07 -0700] [Client 21] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [20/Jan/2019:18:25:07 -0700] [Client 21] Content-Length: 1204
D [20/Jan/2019:18:25:07 -0700] [Client 21] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Jan/2019:18:25:07 -0700] [Client 21] con->http=0x55b61d231c30
D [20/Jan/2019:18:25:07 -0700] [Client 21] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1204, response=0x55b61d21aef0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [20/Jan/2019:18:25:07 -0700] [Client 21] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Jan/2019:18:25:07 -0700] [Client 21] bytes=0, http_state=0, data_remaining=1204
D [20/Jan/2019:18:25:07 -0700] [Client 21] Flushing write buffer.
D [20/Jan/2019:18:25:07 -0700] [Client 21] New state is HTTP_STATE_WAITING
D [20/Jan/2019:18:25:07 -0700] [Client 21] Waiting for request.
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [20/Jan/2019:18:25:07 -0700] [Client 21] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Jan/2019:18:25:07 -0700] [Client 21] Closing connection.
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [20/Jan/2019:18:25:07 -0700] [Client 22] Server address is "/var/run/cups/cups.sock".
D [20/Jan/2019:18:25:07 -0700] [Client 22] Accepted from localhost (Domain)
D [20/Jan/2019:18:25:07 -0700] [Client 22] Waiting for request.
D [20/Jan/2019:18:25:07 -0700] [Client 22] POST /printers/HP_LaserJet_1022 HTTP/1.1
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [20/Jan/2019:18:25:07 -0700] [Client 22] Read: status=200
D [20/Jan/2019:18:25:07 -0700] [Client 22] No authentication data provided.
D [20/Jan/2019:18:25:07 -0700] [Client 22] 2.0 Create-Job 2
D [20/Jan/2019:18:25:07 -0700] Create-Job ipp://localhost:631/printers/HP_LaserJet_1022
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [20/Jan/2019:18:25:07 -0700] add_job: requesting-user-name="yehor"
I [20/Jan/2019:18:25:07 -0700] [Job 184] Adding start banner page "none".
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [20/Jan/2019:18:25:07 -0700] [Job 184] Queued on "HP_LaserJet_1022" by "yehor".
D [20/Jan/2019:18:25:07 -0700] [Client 22] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/HP_LaserJet_1022) from localhost
D [20/Jan/2019:18:25:07 -0700] [Client 22] Content-Length: 201
D [20/Jan/2019:18:25:07 -0700] [Client 22] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Jan/2019:18:25:07 -0700] [Client 22] con->http=0x55b61d231c30
D [20/Jan/2019:18:25:07 -0700] [Client 22] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=201, response=0x55b61d20afe0(IPP_STATE_IDLE), pipe_pid=0, file=-1
D [20/Jan/2019:18:25:07 -0700] [Client 22] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Jan/2019:18:25:07 -0700] [Client 22] bytes=0, http_state=0, data_remaining=201
D [20/Jan/2019:18:25:07 -0700] [Client 22] Flushing write buffer.
D [20/Jan/2019:18:25:07 -0700] [Client 22] New state is HTTP_STATE_WAITING
D [20/Jan/2019:18:25:07 -0700] [Client 22] Waiting for request.
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] JobCreated
D [20/Jan/2019:18:25:07 -0700] [Client 22] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Jan/2019:18:25:07 -0700] [Client 22] Closing connection.
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Jan/2019:18:25:07 -0700] [Client 23] Server address is "/var/run/cups/cups.sock".
D [20/Jan/2019:18:25:07 -0700] [Client 23] Accepted from localhost (Domain)
D [20/Jan/2019:18:25:07 -0700] [Client 23] Waiting for request.
D [20/Jan/2019:18:25:07 -0700] [Client 23] POST /printers/HP_LaserJet_1022 HTTP/1.1
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Jan/2019:18:25:07 -0700] [Client 23] Read: status=200
D [20/Jan/2019:18:25:07 -0700] [Client 23] No authentication data provided.
D [20/Jan/2019:18:25:07 -0700] [Client 23] 2.0 Send-Document 3
D [20/Jan/2019:18:25:07 -0700] Send-Document ipp://localhost:631/printers/HP_LaserJet_1022
D [20/Jan/2019:18:25:07 -0700] cupsdIsAuthorized: requesting-user-name="yehor"
D [20/Jan/2019:18:25:07 -0700] [Job 184] Auto-typing file...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Request file type is text/plain.
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [20/Jan/2019:18:25:07 -0700] [Job 184] File of type text/plain queued by "yehor".
I [20/Jan/2019:18:25:07 -0700] [Job 184] Adding end banner page "none".
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Job 184] time-at-processing=1548033907
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Job 184] 3 filters for job:
D [20/Jan/2019:18:25:07 -0700] [Job 184] texttopdf (text/plain to application/pdf, cost 32)
D [20/Jan/2019:18:25:07 -0700] [Job 184] pdftopdf (application/pdf to application/vnd.cups-pdf, cost 66)
D [20/Jan/2019:18:25:07 -0700] [Job 184] foomatic-rip (application/vnd.cups-pdf to printer/HP_LaserJet_1022, cost 0)
D [20/Jan/2019:18:25:07 -0700] [Job 184] job-sheets=none,none
D [20/Jan/2019:18:25:07 -0700] [Job 184] argv[0]="HP_LaserJet_1022"
D [20/Jan/2019:18:25:07 -0700] [Job 184] argv[1]="184"
D [20/Jan/2019:18:25:07 -0700] [Job 184] argv[2]="yehor"
D [20/Jan/2019:18:25:07 -0700] [Job 184] argv[3]="test"
D [20/Jan/2019:18:25:07 -0700] [Job 184] argv[4]="1"
D [20/Jan/2019:18:25:07 -0700] [Job 184] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:bdbeae69-6ca2-3b5d-7451-10cc9f8bf40b job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1548033907 time-at-processing=1548033907 document-name-supplied=test"
D [20/Jan/2019:18:25:07 -0700] [Job 184] argv[6]="/var/spool/cups/d00184-001"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[8]="HOME=/var/spool/cups/tmp"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[10]="SERVER_ADMIN=root@desktop3"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[11]="SOFTWARE=CUPS/2.2.1"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[13]="USER=root"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[14]="CUPS_MAX_MESSAGE=2047"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[15]="CUPS_SERVER=/var/run/cups/cups.sock"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[17]="IPP_PORT=631"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[18]="CHARSET=utf-8"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[19]="LANG=en_US.UTF-8"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[20]="PPD=/etc/cups/ppd/HP_LaserJet_1022.ppd"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[21]="RIP_MAX_CACHE=128m"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[22]="CONTENT_TYPE=text/plain"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[23]="DEVICE_URI=usb://HP/LaserJet%201022?serial=JM154Y7"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[24]="PRINTER_INFO=HP LaserJet 1022"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[25]="PRINTER_LOCATION=Local Printer"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[26]="PRINTER=HP_LaserJet_1022"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[27]="PRINTER_STATE_REASONS=none"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[28]="CUPS_FILETYPE=document"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[29]="FINAL_CONTENT_TYPE=application/vnd.cups-pdf"
D [20/Jan/2019:18:25:07 -0700] [Job 184] envp[30]="AUTH_I****"
I [20/Jan/2019:18:25:07 -0700] [Job 184] Started filter /usr/lib/cups/filter/texttopdf (PID 4425)
I [20/Jan/2019:18:25:07 -0700] [Job 184] Started filter /usr/lib/cups/filter/pdftopdf (PID 4426)
I [20/Jan/2019:18:25:07 -0700] [Job 184] Started filter /usr/lib/cups/filter/foomatic-rip (PID 4427)
I [20/Jan/2019:18:25:07 -0700] [Job 184] Started backend /usr/lib/cups/backend/usb (PID 4428)
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Client 23] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/HP_LaserJet_1022) from localhost
D [20/Jan/2019:18:25:07 -0700] [Client 23] Content-Length: 171
D [20/Jan/2019:18:25:07 -0700] [Client 23] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Jan/2019:18:25:07 -0700] [Client 23] con->http=0x55b61d231c30
D [20/Jan/2019:18:25:07 -0700] [Client 23] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=171, response=0x55b61d231890(IPP_STATE_DATA), pipe_pid=0, file=-1
D [20/Jan/2019:18:25:07 -0700] [Client 23] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Jan/2019:18:25:07 -0700] [Client 23] bytes=0, http_state=0, data_remaining=171
D [20/Jan/2019:18:25:07 -0700] [Client 23] Flushing write buffer.
D [20/Jan/2019:18:25:07 -0700] [Client 23] New state is HTTP_STATE_WAITING
D [20/Jan/2019:18:25:07 -0700] [Client 23] Waiting for request.
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] PrinterStateChanged
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] JobState
D [20/Jan/2019:18:25:07 -0700] [Client 23] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Jan/2019:18:25:07 -0700] [Client 23] Closing connection.
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Job 184] Calling FindDeviceById(cups-HP_LaserJet_1022)
D [20/Jan/2019:18:25:07 -0700] [Job 184] Loading USB quirks from \"/usr/share/cups/usb\".
D [20/Jan/2019:18:25:07 -0700] [Job 184] pdftopdf: Last filter determined by the PPD: foomatic-rip; FINAL_CONTENT_TYPE: application/vnd.cups-pdf => pdftopdf will log pages in page_log.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Loaded 132 quirks.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Printing on printer with URI: usb://HP/LaserJet%201022?serial=JM154Y7
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found device /org/freedesktop/ColorManager/devices/cups_HP_LaserJet_1022
D [20/Jan/2019:18:25:07 -0700] [Job 184] Calling org.freedesktop.ColorManager.Device.Get(ProfilingInhibitors)
D [20/Jan/2019:18:25:07 -0700] [Job 184] \'CM Color Calibration\' Mode in SPOOLER-LESS: Off
D [20/Jan/2019:18:25:07 -0700] [Job 184] Getting input from file
D [20/Jan/2019:18:25:07 -0700] [Job 184] foomatic-rip version 1.11.6 running...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Parsing PPD file ...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option ColorSpace
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option PageSize
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option Quality
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option Resolution
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option ImageableArea
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option PaperDimension
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option InputSlot
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option MediaType
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option Density
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option Copies
D [20/Jan/2019:18:25:07 -0700] [Job 184] libusb_get_device_list=10
D [20/Jan/2019:18:25:07 -0700] [Job 184] STATE: +connecting-to-device
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] PrinterStateChanged
D [20/Jan/2019:18:25:07 -0700] [Job 184] STATE: -connecting-to-device
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [20/Jan/2019:18:25:07 -0700] [Job 184] Device protocol: 2
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Job 184] Page = 612x792; 11,11 to 601,781
D [20/Jan/2019:18:25:07 -0700] [Job 184] Sending data to printer.
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Job 184] Set job-printer-state-message to "Sending data to printer.", current level=INFO
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] PrinterStateChanged
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] JobProgress
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] PrinterStateChanged
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option halftone
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option NupOrient
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option NupPages
D [20/Jan/2019:18:25:07 -0700] [Job 184] Added option Font
D [20/Jan/2019:18:25:07 -0700] [Job 184] Parameter Summary
D [20/Jan/2019:18:25:07 -0700] [Job 184] -----------------
D [20/Jan/2019:18:25:07 -0700] [Job 184] Spooler: cups
D [20/Jan/2019:18:25:07 -0700] [Job 184] Printer: HP_LaserJet_1022
D [20/Jan/2019:18:25:07 -0700] [Job 184] Shell: /bin/sh
D [20/Jan/2019:18:25:07 -0700] [Job 184] PPD file: /etc/cups/ppd/HP_LaserJet_1022.ppd
D [20/Jan/2019:18:25:07 -0700] [Job 184] ATTR file:
D [20/Jan/2019:18:25:07 -0700] [Job 184] Printer model: HP LaserJet 1022 Foomatic/foo2zjs-z1 (recommended)
D [20/Jan/2019:18:25:07 -0700] [Job 184] Job title: test
D [20/Jan/2019:18:25:07 -0700] [Job 184] File(s) to be printed:
D [20/Jan/2019:18:25:07 -0700] [Job 184] <STDIN>
D [20/Jan/2019:18:25:07 -0700] [Job 184] Ghostscript extra search path (\'GS_LIB\'): /usr/share/cups/fonts
D [20/Jan/2019:18:25:07 -0700] [Job 184] Printing system options:
D [20/Jan/2019:18:25:07 -0700] [Job 184] Pondering option \'finishings=3\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Unknown option finishings=3.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Pondering option \'number-up=1\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Unknown option number-up=1.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Pondering option \'job-uuid=urn:uuid:bdbeae69-6ca2-3b5d-7451-10cc9f8bf40b\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Unknown option job-uuid=urn:uuid:bdbeae69-6ca2-3b5d-7451-10cc9f8bf40b.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Pondering option \'job-originating-host-name=localhost\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Unknown option job-originating-host-name=localhost.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Pondering option \'date-time-at-creation=\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Unknown option date-time-at-creation=.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Pondering option \'date-time-at-processing=\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Unknown option date-time-at-processing=.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Pondering option \'time-at-creation=1548033907\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Unknown option time-at-creation=1548033907.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Pondering option \'time-at-processing=1548033907\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Unknown option time-at-processing=1548033907.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Pondering option \'document-name-supplied=test\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Unknown option document-name-supplied=test.
D [20/Jan/2019:18:25:07 -0700] [Job 184] CM Color Calibration Mode in CUPS: Off
D [20/Jan/2019:18:25:07 -0700] [Job 184] Options from the PPD file:
D [20/Jan/2019:18:25:07 -0700] [Job 184] ================================================
D [20/Jan/2019:18:25:07 -0700] [Job 184] File: <STDIN>
D [20/Jan/2019:18:25:07 -0700] [Job 184] ================================================
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 26 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 44 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 59 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 58 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] PID 4425 (/usr/lib/cups/filter/texttopdf) exited with no errors.
D [20/Jan/2019:18:25:07 -0700] [Job 184] PAGE: 1 1
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] JobProgress
D [20/Jan/2019:18:25:07 -0700] [Job 184] Filetype: PDF
D [20/Jan/2019:18:25:07 -0700] [Job 184] Neither PDF renderer command line nor Ghostscript-based renderer command line found
D [20/Jan/2019:18:25:07 -0700] [Job 184] Driver does not understand PDF input, converting to PostScript
D [20/Jan/2019:18:25:07 -0700] [Job 184] Storing temporary files in /var/spool/cups/tmp
D [20/Jan/2019:18:25:07 -0700] [Job 184] PID 4426 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Starting process \"pdf-to-ps\" (generation 1)
D [20/Jan/2019:18:25:07 -0700] [Job 184] Printer make and model: HP HP LaserJet 1022
D [20/Jan/2019:18:25:07 -0700] [Job 184] Switching to Poppler\'s pdftops instead of Ghostscript for old HP LaserJet (\"LaserJet <number>\", no letters before <number>) printers to work around bugs in the printer\'s PS interpreters
D [20/Jan/2019:18:25:07 -0700] [Job 184] Running command line for pstops: pstops 184 yehor test 1 \' finishings=3 job-uuid=urn:uuid:bdbeae69-6ca2-3b5d-7451-10cc9f8bf40b job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1548033907 time-at-processing=1548033907 document-name-supplied=test\'
D [20/Jan/2019:18:25:07 -0700] [Job 184] Using image rendering resolution 600 dpi
D [20/Jan/2019:18:25:07 -0700] [Job 184] Running command line for pdftops: pdftops -level2 -origpagesizes -nocenter -r 600 /var/spool/cups/tmp/foomatic-8Oncug -
D [20/Jan/2019:18:25:07 -0700] [Job 184] Started filter pdftops (PID 4435)
D [20/Jan/2019:18:25:07 -0700] [Job 184] Started filter pstops (PID 4436)
D [20/Jan/2019:18:25:07 -0700] [Job 184] Page = 612x792; 11,11 to 601,781
D [20/Jan/2019:18:25:07 -0700] [Job 184] slow_collate=0, slow_duplex=0, slow_order=0
D [20/Jan/2019:18:25:07 -0700] [Job 184] Before copy_comments - %!PS-Adobe-3.0
D [20/Jan/2019:18:25:07 -0700] [Job 184] %!PS-Adobe-3.0
D [20/Jan/2019:18:25:07 -0700] [Job 184] %Produced by poppler pdftops version: 0.48.0 (http://poppler.freedesktop.org)
D [20/Jan/2019:18:25:07 -0700] [Job 184] %%Creator: texttopdf/1.11.6
D [20/Jan/2019:18:25:07 -0700] [Job 184] %%LanguageLevel: 2
D [20/Jan/2019:18:25:07 -0700] [Job 184] %%DocumentSuppliedResources: (atend)
D [20/Jan/2019:18:25:07 -0700] [Job 184] %%DocumentMedia: Letter 612 792 0 () ()
D [20/Jan/2019:18:25:07 -0700] [Job 184] %%BoundingBox: 0 0 612 792
D [20/Jan/2019:18:25:07 -0700] [Job 184] %%Pages: 1
D [20/Jan/2019:18:25:07 -0700] [Job 184] %%EndComments
D [20/Jan/2019:18:25:07 -0700] [Job 184] Before copy_prolog - %%BeginProlog
D [20/Jan/2019:18:25:07 -0700] [Job 184] Filetype: PostScript
D [20/Jan/2019:18:25:07 -0700] [Job 184] Before copy_setup - %%BeginSetup
D [20/Jan/2019:18:25:07 -0700] [Job 184] Reading PostScript input ...
D [20/Jan/2019:18:25:07 -0700] [Job 184] --> This document is DSC-conforming!
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found %RBINumCopies: 1
D [20/Jan/2019:18:25:07 -0700] [Job 184] -----------
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginProlog
D [20/Jan/2019:18:25:07 -0700] [Job 184] Inserting option code into \"Prolog\" section.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%EndProlog
D [20/Jan/2019:18:25:07 -0700] [Job 184] -----------
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginSetup
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *Quality normal
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: Quality=normal
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: Quality=normal
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: Quality=normal
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *halftone default
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: halftone=default
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: halftone=default
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: halftone=default
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *Resolution 1200x600dpi
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: Resolution=1200x600dpi
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: Resolution=1200x600dpi
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: Resolution=1200x600dpi
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *PageSize Letter
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: PageSize=Letter
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: PageSize=Letter
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: PageSize=Letter
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *InputSlot Auto
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: InputSlot=Auto
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: InputSlot=Auto
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: InputSlot=Auto
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *MediaType Standard
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: MediaType=Standard
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: MediaType=Standard
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: MediaType=Standard
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *Density Density3
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: Density=Density3
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: Density=Density3
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: Density=Density3
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *NupOrient port
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: NupOrient=port
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: NupOrient=port
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: NupOrient=port
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *NupPages 1up
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: NupPages=1up
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: NupPages=1up
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: NupPages=1up
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginFeature: *Copies 1
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: Copies=1
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %% FoomaticRIPOptionSetting: Copies=1
D [20/Jan/2019:18:25:07 -0700] [Job 184] Option: Copies=1
D [20/Jan/2019:18:25:07 -0700] [Job 184] Setting option
D [20/Jan/2019:18:25:07 -0700] [Job 184] Before page loop - %%Page: 1 1
D [20/Jan/2019:18:25:07 -0700] [Job 184] Copying page 1...
D [20/Jan/2019:18:25:07 -0700] [Job 184] pagew = 589.3, pagel = 769.3
D [20/Jan/2019:18:25:07 -0700] [Job 184] bboxx = 0, bboxy = 0, bboxw = 612, bboxl = 792
D [20/Jan/2019:18:25:07 -0700] [Job 184] PageLeft = 11.3, PageRight = 600.7
D [20/Jan/2019:18:25:07 -0700] [Job 184] PageTop = 780.7, PageBottom = 11.3
D [20/Jan/2019:18:25:07 -0700] [Job 184] PageWidth = 612.0, PageLength = 792.0
D [20/Jan/2019:18:25:07 -0700] [Job 184] Wrote 1 pages...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%EndSetup
D [20/Jan/2019:18:25:07 -0700] [Job 184] -----------
D [20/Jan/2019:18:25:07 -0700] [Job 184] New page: %%Page: 1 1
D [20/Jan/2019:18:25:07 -0700] [Job 184] \"Setup\" section is missing, inserting it.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Inserting option code into \"Setup\" section.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Found: %%BeginPageSetup
D [20/Jan/2019:18:25:07 -0700] [Job 184] Inserting option code into \"PageSetup\" section.
D [20/Jan/2019:18:25:07 -0700] [Job 184] PID 4435 (pdftops) exited with no errors.
D [20/Jan/2019:18:25:07 -0700] [Job 184] PID 4436 (pstops) exited with no errors.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Flushing FIFO.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Starting renderer with command: \"foo2zjs-wrapper -z1 -P -L0 -r1200x600 -p1 -T3 -m1 -s7 -n1 \"
D [20/Jan/2019:18:25:07 -0700] [Job 184] Starting process \"kid3\" (generation 1)
D [20/Jan/2019:18:25:07 -0700] [Job 184] Closing renderer
D [20/Jan/2019:18:25:07 -0700] [Job 184] Starting process \"kid4\" (generation 2)
D [20/Jan/2019:18:25:07 -0700] [Job 184] Starting process \"renderer\" (generation 2)
D [20/Jan/2019:18:25:07 -0700] [Job 184] JCL: \033%-12345X@PJL
D [20/Jan/2019:18:25:07 -0700] [Job 184] <job data>
D [20/Jan/2019:18:25:07 -0700] [Job 184] gs: symbol lookup error: /usr/lib/x86_64-linux-gnu/libgs.so.9: undefined symbol: FT_Property_Set
D [20/Jan/2019:18:25:07 -0700] [Job 184] Not a pbm file!
D [20/Jan/2019:18:25:07 -0700] [Job 184] renderer exited with status 0
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 324 bytes of print data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Wrote 324 bytes of print data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 56 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] kid4 exited with status 0
D [20/Jan/2019:18:25:07 -0700] [Job 184] kid3 finished
D [20/Jan/2019:18:25:07 -0700] [Job 184] kid3 exited with status 0
D [20/Jan/2019:18:25:07 -0700] [Job 184] pdf-to-ps exited with status 0
D [20/Jan/2019:18:25:07 -0700] [Job 184] Closing foomatic-rip.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Sent 324 bytes...
D [20/Jan/2019:18:25:07 -0700] [Job 184] PID 4427 (/usr/lib/cups/filter/foomatic-rip) exited with no errors.
D [20/Jan/2019:18:25:07 -0700] [Job 184] Waiting for read thread to exit...
D [20/Jan/2019:18:25:07 -0700] [Job 184] Read 59 bytes of back-channel data...
D [20/Jan/2019:18:25:07 -0700] [Job 184] PID 4428 (/usr/lib/cups/backend/usb) exited with no errors.
D [20/Jan/2019:18:25:07 -0700] [Job 184] time-at-completed=1548033907
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
I [20/Jan/2019:18:25:07 -0700] [Job 184] Job completed.
I [20/Jan/2019:18:25:07 -0700] Expiring subscriptions...
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(----S)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Job 184] Removing document files.
D [20/Jan/2019:18:25:07 -0700] cupsdMarkDirty(---J-)
D [20/Jan/2019:18:25:07 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files"
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] JobCompleted
D [20/Jan/2019:18:25:07 -0700] [Notifier] state=3
D [20/Jan/2019:18:25:07 -0700] [Notifier] PrinterStateChanged
I [20/Jan/2019:18:25:08 -0700] Expiring subscriptions...
D [20/Jan/2019:18:25:08 -0700] [Job 184] Unloading...
D [20/Jan/2019:18:25:10 -0700] [Client 20] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Jan/2019:18:25:10 -0700] [Client 20] Closing connection.
D [20/Jan/2019:18:25:10 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
I [20/Jan/2019:18:25:10 -0700] Expiring subscriptions...
D [20/Jan/2019:18:25:10 -0700] [Client 24] Server address is "[v1.::1]".
D [20/Jan/2019:18:25:10 -0700] [Client 24] Accepted from localhost:57488 (IPv6)
D [20/Jan/2019:18:25:10 -0700] [Client 24] Waiting for request.
I [20/Jan/2019:18:25:11 -0700] Expiring subscriptions...
D [20/Jan/2019:18:25:12 -0700] [Client 13] GET /admin/log/error_log? HTTP/1.1
D [20/Jan/2019:18:25:12 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Jan/2019:18:25:12 -0700] [Client 13] Read: status=200
D [20/Jan/2019:18:25:12 -0700] [Client 13] Authorized as "root" using Basic.
D [20/Jan/2019:18:25:12 -0700] cupsdIsAuthorized: username="root"
D [20/Jan/2019:18:25:12 -0700] [Client 13] Processing GET /admin/log/error_log?
Yehor