Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed

To: Brian Potkin <claremont102@gmail.com>
Cc: 860591@bugs.debian.org
Subject: Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed
From: Ben Finney <bignose@debian.org>
Date: Thu, 20 Apr 2017 09:19:49 +1000
Message-id: <[🔎] 20170419231947.tcdgepmastrnzggn@benfinney.id.au>
Reply-to: Ben Finney <bignose@debian.org>, 860591@bugs.debian.org
In-reply-to: <[🔎] 19042017135849.c788ee3c97d5@desktop.copernicus.org.uk>
References: <[🔎] 20170419003022.5fpdaiyadozmlue4@benfinney.id.au> <[🔎] 19042017104657.3a12690b6b57@desktop.copernicus.org.uk> <[🔎] 20170419110951.5fyxwf4tfeqagpbt@benfinney.id.au> <[🔎] 19042017135849.c788ee3c97d5@desktop.copernicus.org.uk>

On 19-Apr-2017, Brian Potkin wrote:

> Set up this print queue (as root):
> 
>  lpadmin -p testq -v /home/<user>/testq-out -E -P </etc/cups/ppd/<PPD_for_the_Samsung>

I have set that queue up now.

The server now stops when I try to print to a queue:

=====
$ sudo systemctl restart cups

$ sudo systemctl status cups
● cups.service - CUPS Scheduler
   Loaded: loaded (/lib/systemd/system/cups.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2017-04-20 09:13:47 AEST; 2s ago
     Docs: man:cupsd(8)
 Main PID: 15217 (cupsd)
    Tasks: 1 (limit: 4915)
   Memory: 3.9M
      CPU: 32ms
   CGroup: /system.slice/cups.service
           └─15217 /usr/sbin/cupsd -l

Apr 20 09:13:47 lantana systemd[1]: Started CUPS Scheduler.

$ lpstat -t
scheduler is running
system default destination: SCX-4623-Series
device for HP-LaserJet-MFP-M227-M231: dnssd://HP%20LaserJet%20MFP%20M227fdw%20(09EB59)._ipp._tcp.local/?uuid=564e4333-3930-3031-3137-98e7f409eb59
device for PDF: cups-pdf:/
device for SCX-4623-Series: usb://Samsung/SCX-4623%20Series?serial=Z2WUBFFZ300396N&interface=1
device for testq: /home/bignose/testq-out
device for XP-310: usb://EPSON/XP-310%20Series?serial=533538503030343819&interface=1
device for XP-310-Series: usb://EPSON/XP-310%20Series?serial=533538503030343819&interface=1
HP-LaserJet-MFP-M227-M231 accepting requests since Tue 18 Apr 2017 20:33:31 AEST
PDF accepting requests since Tue 18 Apr 2017 20:22:05 AEST
SCX-4623-Series accepting requests since Wed 05 Apr 2017 11:29:50 AEST
testq accepting requests since Thu 20 Apr 2017 08:39:26 AEST
XP-310 accepting requests since Fri 30 Dec 2016 12:00:16 AEDT
XP-310-Series accepting requests since Fri 30 Dec 2016 12:00:16 AEDT
printer HP-LaserJet-MFP-M227-M231 is idle.  enabled since Tue 18 Apr 2017 20:33:31 AEST
printer PDF is idle.  enabled since Tue 18 Apr 2017 20:22:05 AEST
printer SCX-4623-Series is idle.  enabled since Wed 05 Apr 2017 11:29:50 AEST
printer testq is idle.  enabled since Thu 20 Apr 2017 08:39:26 AEST
printer XP-310 disabled since Fri 30 Dec 2016 12:00:16 AEDT -
        Unplugged or turned off
printer XP-310-Series disabled since Fri 30 Dec 2016 12:00:16 AEDT -
        Unplugged or turned off

$ sudo cupsctl --debug-logging

$ [… submit a Test Page job to ‘testq’, using GNOME 3 control center …]

$ lpq
lpq: Unable to connect to server.

$ sudo systemctl status cups
● cups.service - CUPS Scheduler
   Loaded: loaded (/lib/systemd/system/cups.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Thu 2017-04-20 09:14:08 AEST; 20s ago
     Docs: man:cupsd(8)
  Process: 15217 ExecStart=/usr/sbin/cupsd -l (code=exited, status=1/FAILURE)
 Main PID: 15217 (code=exited, status=1/FAILURE)
      CPU: 44ms

Apr 20 09:13:47 lantana systemd[1]: Started CUPS Scheduler.
Apr 20 09:14:08 lantana systemd[1]: cups.service: Main process exited, code=exited, status=1/FAILURE
Apr 20 09:14:08 lantana systemd[1]: cups.service: Unit entered failed state.
Apr 20 09:14:08 lantana systemd[1]: cups.service: Failed with result 'exit-code'.

$ ls /home/bignose/testq*
ls: cannot access '/home/bignose/testq*': No such file or directory

=====

I am attaching the resulting ‘/var/log/cups/error_log’ to this message.

-- 
 \                         “Sometimes I — no, I don't.” —Steven Wright |
  `\                                                                   |
_o__)                                                                  |
Ben Finney <bignose@debian.org>

I [20/Apr/2017:09:13:47 +1000] Listening to [v1.::1]:631 (IPv6)
I [20/Apr/2017:09:13:47 +1000] Listening to 127.0.0.1:631 (IPv4)
I [20/Apr/2017:09:13:47 +1000] Listening to /var/run/cups/cups.sock (Domain)
I [20/Apr/2017:09:13:47 +1000] Remote access is disabled.
D [20/Apr/2017:09:13:47 +1000] Added auto ServerAlias lantana
I [20/Apr/2017:09:13:47 +1000] Loaded configuration file "/etc/cups/cupsd.conf"
D [20/Apr/2017:09:13:47 +1000] Using keychain "/etc/cups/ssl" for server name "lantana".
I [20/Apr/2017:09:13:47 +1000] Using default TempDir of /var/spool/cups/tmp...
I [20/Apr/2017:09:13:47 +1000] Configured for up to 100 clients.
I [20/Apr/2017:09:13:47 +1000] Allowing up to 100 client connections per host.
I [20/Apr/2017:09:13:47 +1000] Using policy "default" as the default.
I [20/Apr/2017:09:13:47 +1000] Full reload is required.
I [20/Apr/2017:09:13:47 +1000] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 50 types, 86 filters...
D [20/Apr/2017:09:13:47 +1000] Loading printer HP-LaserJet-MFP-M227-M231...
D [20/Apr/2017:09:13:47 +1000] load_ppd: Loading /var/cache/cups/HP-LaserJet-MFP-M227-M231.data...
D [20/Apr/2017:09:13:47 +1000] cupsdRegisterPrinter(p=0x55c12f42e4b0(HP-LaserJet-MFP-M227-M231))
D [20/Apr/2017:09:13:47 +1000] load_ppd: Loading /var/cache/cups/HP-LaserJet-MFP-M227-M231.data...
D [20/Apr/2017:09:13:47 +1000] cupsdRegisterPrinter(p=0x55c12f42e4b0(HP-LaserJet-MFP-M227-M231))
D [20/Apr/2017:09:13:47 +1000] Loading printer PDF...
D [20/Apr/2017:09:13:47 +1000] load_ppd: Loading /var/cache/cups/PDF.data...
D [20/Apr/2017:09:13:47 +1000] cupsdRegisterPrinter(p=0x55c12f4de9b0(PDF))
D [20/Apr/2017:09:13:47 +1000] Loading printer SCX-4623-Series...
D [20/Apr/2017:09:13:47 +1000] load_ppd: Loading /var/cache/cups/SCX-4623-Series.data...
D [20/Apr/2017:09:13:47 +1000] cupsdRegisterPrinter(p=0x55c12f4f1930(SCX-4623-Series))
D [20/Apr/2017:09:13:47 +1000] Loading printer testq...
D [20/Apr/2017:09:13:47 +1000] load_ppd: Loading /var/cache/cups/testq.data...
D [20/Apr/2017:09:13:47 +1000] cupsdRegisterPrinter(p=0x55c12f509bf0(testq))
D [20/Apr/2017:09:13:47 +1000] Loading printer XP-310...
D [20/Apr/2017:09:13:47 +1000] load_ppd: Loading /var/cache/cups/XP-310.data...
D [20/Apr/2017:09:13:47 +1000] cupsdRegisterPrinter(p=0x55c12f592f40(XP-310))
D [20/Apr/2017:09:13:47 +1000] Loading printer XP-310-Series...
D [20/Apr/2017:09:13:47 +1000] load_ppd: Loading /var/cache/cups/XP-310-Series.data...
D [20/Apr/2017:09:13:47 +1000] cupsdRegisterPrinter(p=0x55c12f61b8a0(XP-310-Series))
I [20/Apr/2017:09:13:47 +1000] Loading job cache file "/var/cache/cups/job.cache"...
D [20/Apr/2017:09:13:47 +1000] [Job 66] Loading from cache...
D [20/Apr/2017:09:13:47 +1000] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [20/Apr/2017:09:13:47 +1000] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
I [20/Apr/2017:09:13:47 +1000] Full reload complete.
D [20/Apr/2017:09:13:47 +1000] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)")
I [20/Apr/2017:09:13:47 +1000] Cleaning out old files in "/var/spool/cups/tmp".
D [20/Apr/2017:09:13:47 +1000] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp")
I [20/Apr/2017:09:13:47 +1000] Cleaning out old files in "/var/cache/cups".
D [20/Apr/2017:09:13:47 +1000] service_checkin: pid=15217
D [20/Apr/2017:09:13:47 +1000] service_checkin: 0 listeners.
D [20/Apr/2017:09:13:47 +1000] Creating keep-alive file "/var/cache/cups/org.cups.cupsd".
D [20/Apr/2017:09:13:47 +1000] Calling FindDeviceById(cups-HP-LaserJet-MFP-M227-M231)
D [20/Apr/2017:09:13:47 +1000] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-HP-LaserJet-MFP-M227-M231\' does not exist
D [20/Apr/2017:09:13:47 +1000] Using profile ID "HP-LaserJet-MFP-M227-M231-Gray..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(HP-LaserJet-MFP-M227-M231-Gray..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/HP_LaserJet_MFP_M227_M231_Gray__".
D [20/Apr/2017:09:13:47 +1000] Using profile ID "HP-LaserJet-MFP-M227-M231-RGB..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(HP-LaserJet-MFP-M227-M231-RGB..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/HP_LaserJet_MFP_M227_M231_RGB__".
I [20/Apr/2017:09:13:47 +1000] Registering ICC color profiles for "HP-LaserJet-MFP-M227-M231".
D [20/Apr/2017:09:13:47 +1000] Calling CreateDevice(cups-HP-LaserJet-MFP-M227-M231,temp)
D [20/Apr/2017:09:13:47 +1000] Created device "/org/freedesktop/ColorManager/devices/cups_HP_LaserJet_MFP_M227_M231".
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_HP_LaserJet_MFP_M227_M231:AddProfile(/org/freedesktop/ColorManager/profiles/HP_LaserJet_MFP_M227_M231_Gray__) [soft]
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_HP_LaserJet_MFP_M227_M231:AddProfile(/org/freedesktop/ColorManager/profiles/HP_LaserJet_MFP_M227_M231_RGB__) [soft]
D [20/Apr/2017:09:13:47 +1000] Calling FindDeviceById(cups-PDF)
D [20/Apr/2017:09:13:47 +1000] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-PDF\' does not exist
D [20/Apr/2017:09:13:47 +1000] Using profile ID "PDF-Gray..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(PDF-Gray..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/PDF_Gray__".
D [20/Apr/2017:09:13:47 +1000] Using profile ID "PDF-RGB..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(PDF-RGB..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/PDF_RGB__".
I [20/Apr/2017:09:13:47 +1000] Registering ICC color profiles for "PDF".
D [20/Apr/2017:09:13:47 +1000] Calling CreateDevice(cups-PDF,temp)
D [20/Apr/2017:09:13:47 +1000] Created device "/org/freedesktop/ColorManager/devices/cups_PDF".
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_PDF:AddProfile(/org/freedesktop/ColorManager/profiles/PDF_Gray__) [soft]
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_PDF:AddProfile(/org/freedesktop/ColorManager/profiles/PDF_RGB__) [soft]
D [20/Apr/2017:09:13:47 +1000] Calling FindDeviceById(cups-SCX-4623-Series)
D [20/Apr/2017:09:13:47 +1000] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-SCX-4623-Series\' does not exist
D [20/Apr/2017:09:13:47 +1000] Using profile ID "SCX-4623-Series-Gray..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(SCX-4623-Series-Gray..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/SCX_4623_Series_Gray__".
I [20/Apr/2017:09:13:47 +1000] Registering ICC color profiles for "SCX-4623-Series".
D [20/Apr/2017:09:13:47 +1000] Calling CreateDevice(cups-SCX-4623-Series,temp)
D [20/Apr/2017:09:13:47 +1000] Created device "/org/freedesktop/ColorManager/devices/cups_SCX_4623_Series".
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_SCX_4623_Series:AddProfile(/org/freedesktop/ColorManager/profiles/SCX_4623_Series_Gray__) [soft]
D [20/Apr/2017:09:13:47 +1000] Calling FindDeviceById(cups-testq)
D [20/Apr/2017:09:13:47 +1000] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-testq\' does not exist
D [20/Apr/2017:09:13:47 +1000] Using profile ID "testq-Gray..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(testq-Gray..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/testq_Gray__".
I [20/Apr/2017:09:13:47 +1000] Registering ICC color profiles for "testq".
D [20/Apr/2017:09:13:47 +1000] Calling CreateDevice(cups-testq,temp)
D [20/Apr/2017:09:13:47 +1000] Created device "/org/freedesktop/ColorManager/devices/cups_testq".
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_testq:AddProfile(/org/freedesktop/ColorManager/profiles/testq_Gray__) [soft]
D [20/Apr/2017:09:13:47 +1000] Calling FindDeviceById(cups-XP-310)
D [20/Apr/2017:09:13:47 +1000] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-XP-310\' does not exist
D [20/Apr/2017:09:13:47 +1000] Using profile ID "XP-310-Gray..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(XP-310-Gray..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/XP_310_Gray__".
D [20/Apr/2017:09:13:47 +1000] Using profile ID "XP-310-RGB..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(XP-310-RGB..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/XP_310_RGB__".
I [20/Apr/2017:09:13:47 +1000] Registering ICC color profiles for "XP-310".
D [20/Apr/2017:09:13:47 +1000] Calling CreateDevice(cups-XP-310,temp)
D [20/Apr/2017:09:13:47 +1000] Created device "/org/freedesktop/ColorManager/devices/cups_XP_310".
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_XP_310:AddProfile(/org/freedesktop/ColorManager/profiles/XP_310_Gray__) [soft]
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_XP_310:AddProfile(/org/freedesktop/ColorManager/profiles/XP_310_RGB__) [soft]
D [20/Apr/2017:09:13:47 +1000] Calling FindDeviceById(cups-XP-310-Series)
D [20/Apr/2017:09:13:47 +1000] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-XP-310-Series\' does not exist
D [20/Apr/2017:09:13:47 +1000] Using profile ID "XP-310-Series-Gray..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(XP-310-Series-Gray..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/XP_310_Series_Gray__".
D [20/Apr/2017:09:13:47 +1000] Using profile ID "XP-310-Series-RGB..".
D [20/Apr/2017:09:13:47 +1000] Calling CreateProfile(XP-310-Series-RGB..,temp)
D [20/Apr/2017:09:13:47 +1000] Created profile "/org/freedesktop/ColorManager/profiles/XP_310_Series_RGB__".
I [20/Apr/2017:09:13:47 +1000] Registering ICC color profiles for "XP-310-Series".
D [20/Apr/2017:09:13:47 +1000] Calling CreateDevice(cups-XP-310-Series,temp)
D [20/Apr/2017:09:13:47 +1000] Created device "/org/freedesktop/ColorManager/devices/cups_XP_310_Series".
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_XP_310_Series:AddProfile(/org/freedesktop/ColorManager/profiles/XP_310_Series_Gray__) [soft]
D [20/Apr/2017:09:13:47 +1000] Calling /org/freedesktop/ColorManager/devices/cups_XP_310_Series:AddProfile(/org/freedesktop/ColorManager/profiles/XP_310_Series_RGB__) [soft]
I [20/Apr/2017:09:13:47 +1000] Listening to [v1.::1]:631 on fd 6...
I [20/Apr/2017:09:13:47 +1000] Listening to 127.0.0.1:631 on fd 7...
I [20/Apr/2017:09:13:47 +1000] Listening to /var/run/cups/cups.sock on fd 8...
I [20/Apr/2017:09:13:47 +1000] Resuming new connection processing...
D [20/Apr/2017:09:13:47 +1000] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [20/Apr/2017:09:13:47 +1000] cupsdAddCert: Adding certificate for PID 0
D [20/Apr/2017:09:13:47 +1000] Discarding unused server-started event...
I [20/Apr/2017:09:13:48 +1000] Expiring subscriptions...
I [20/Apr/2017:09:13:48 +1000] Subscription 696 has expired...
D [20/Apr/2017:09:13:48 +1000] cupsdMarkDirty(----S)
D [20/Apr/2017:09:13:48 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy"
D [20/Apr/2017:09:13:48 +1000] Report: clients=0
D [20/Apr/2017:09:13:48 +1000] Report: jobs=1
D [20/Apr/2017:09:13:48 +1000] Report: jobs-active=0
D [20/Apr/2017:09:13:48 +1000] Report: printers=6
D [20/Apr/2017:09:13:48 +1000] Report: stringpool-string-count=33656
D [20/Apr/2017:09:13:48 +1000] Report: stringpool-alloc-bytes=17256
D [20/Apr/2017:09:13:48 +1000] Report: stringpool-total-bytes=652776
D [20/Apr/2017:09:13:52 +1000] [Client 1] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:13:52 +1000] [Client 1] Accepted from localhost (Domain)
D [20/Apr/2017:09:13:52 +1000] [Client 1] Waiting for request.
I [20/Apr/2017:09:13:52 +1000] Expiring subscriptions...
D [20/Apr/2017:09:13:52 +1000] [Client 1] POST / HTTP/1.1
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 1] Read: status=200, state=6
D [20/Apr/2017:09:13:52 +1000] [Client 1] No authentication data provided.
D [20/Apr/2017:09:13:52 +1000] [Client 1] 2.0 CUPS-Get-Printers 1
D [20/Apr/2017:09:13:52 +1000] CUPS-Get-Printers
D [20/Apr/2017:09:13:52 +1000] [Client 1] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [20/Apr/2017:09:13:52 +1000] [Client 1] Content-Length: 6747
D [20/Apr/2017:09:13:52 +1000] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Apr/2017:09:13:52 +1000] [Client 1] con->http=0x55c12f6d69c0
D [20/Apr/2017:09:13:52 +1000] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=6747, response=0x55c12f6ceb00(IPP_STATE_DATA), pipe_pid=0, file=-1
D [20/Apr/2017:09:13:52 +1000] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Apr/2017:09:13:52 +1000] [Client 1] bytes=0, http_state=0, data_remaining=6747
D [20/Apr/2017:09:13:52 +1000] [Client 1] Flushing write buffer.
D [20/Apr/2017:09:13:52 +1000] [Client 1] New state is HTTP_STATE_WAITING
D [20/Apr/2017:09:13:52 +1000] [Client 1] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 1] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:13:52 +1000] [Client 1] Closing connection.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 2] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:13:52 +1000] [Client 2] Accepted from localhost (Domain)
D [20/Apr/2017:09:13:52 +1000] [Client 2] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] [Client 2] POST / HTTP/1.1
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 2] Read: status=200, state=6
D [20/Apr/2017:09:13:52 +1000] [Client 2] No authentication data provided.
D [20/Apr/2017:09:13:52 +1000] [Client 2] 2.0 CUPS-Get-Default 2
D [20/Apr/2017:09:13:52 +1000] CUPS-Get-Default
D [20/Apr/2017:09:13:52 +1000] [Client 2] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [20/Apr/2017:09:13:52 +1000] [Client 2] Content-Length: 10058
D [20/Apr/2017:09:13:52 +1000] [Client 2] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Apr/2017:09:13:52 +1000] [Client 2] con->http=0x55c12f6d69c0
D [20/Apr/2017:09:13:52 +1000] [Client 2] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=10058, response=0x55c12f6cf010(IPP_STATE_DATA), pipe_pid=0, file=-1
D [20/Apr/2017:09:13:52 +1000] [Client 2] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Apr/2017:09:13:52 +1000] [Client 2] bytes=0, http_state=0, data_remaining=10058
D [20/Apr/2017:09:13:52 +1000] [Client 2] Flushing write buffer.
D [20/Apr/2017:09:13:52 +1000] [Client 2] New state is HTTP_STATE_WAITING
D [20/Apr/2017:09:13:52 +1000] [Client 2] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 3] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:13:52 +1000] [Client 3] Accepted from localhost (Domain)
D [20/Apr/2017:09:13:52 +1000] [Client 3] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] [Client 4] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:13:52 +1000] [Client 4] Accepted from localhost (Domain)
D [20/Apr/2017:09:13:52 +1000] [Client 4] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] [Client 2] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:13:52 +1000] [Client 2] Closing connection.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 3] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:13:52 +1000] [Client 3] Closing connection.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 4] POST / HTTP/1.1
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 4] Read: status=200, state=6
D [20/Apr/2017:09:13:52 +1000] [Client 4] No authentication data provided.
D [20/Apr/2017:09:13:52 +1000] [Client 4] 2.0 CUPS-Get-Classes 3
D [20/Apr/2017:09:13:52 +1000] CUPS-Get-Classes
D [20/Apr/2017:09:13:52 +1000] [Client 4] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from localhost
D [20/Apr/2017:09:13:52 +1000] [Client 4] Content-Length: 75
D [20/Apr/2017:09:13:52 +1000] [Client 4] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Apr/2017:09:13:52 +1000] [Client 4] con->http=0x55c12f6df160
D [20/Apr/2017:09:13:52 +1000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x55c12f6cea50(IPP_STATE_DATA), pipe_pid=0, file=-1
D [20/Apr/2017:09:13:52 +1000] [Client 4] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Apr/2017:09:13:52 +1000] [Client 4] bytes=0, http_state=0, data_remaining=75
D [20/Apr/2017:09:13:52 +1000] [Client 4] Flushing write buffer.
D [20/Apr/2017:09:13:52 +1000] [Client 4] New state is HTTP_STATE_WAITING
D [20/Apr/2017:09:13:52 +1000] [Client 4] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 4] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:13:52 +1000] [Client 4] Closing connection.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 5] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:13:52 +1000] [Client 5] Accepted from localhost (Domain)
D [20/Apr/2017:09:13:52 +1000] [Client 5] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] [Client 5] POST / HTTP/1.1
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 5] Read: status=200, state=6
D [20/Apr/2017:09:13:52 +1000] [Client 5] No authentication data provided.
D [20/Apr/2017:09:13:52 +1000] [Client 5] 2.0 CUPS-Get-Printers 4
D [20/Apr/2017:09:13:52 +1000] CUPS-Get-Printers
D [20/Apr/2017:09:13:52 +1000] [Client 5] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [20/Apr/2017:09:13:52 +1000] [Client 5] Content-Length: 1054
D [20/Apr/2017:09:13:52 +1000] [Client 5] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Apr/2017:09:13:52 +1000] [Client 5] con->http=0x55c12f6d69c0
D [20/Apr/2017:09:13:52 +1000] [Client 5] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1054, response=0x55c12f6ceb00(IPP_STATE_DATA), pipe_pid=0, file=-1
D [20/Apr/2017:09:13:52 +1000] [Client 5] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Apr/2017:09:13:52 +1000] [Client 5] bytes=0, http_state=0, data_remaining=1054
D [20/Apr/2017:09:13:52 +1000] [Client 5] Flushing write buffer.
D [20/Apr/2017:09:13:52 +1000] [Client 5] New state is HTTP_STATE_WAITING
D [20/Apr/2017:09:13:52 +1000] [Client 5] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 5] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:13:52 +1000] [Client 5] Closing connection.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 6] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:13:52 +1000] [Client 6] Accepted from localhost (Domain)
D [20/Apr/2017:09:13:52 +1000] [Client 6] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] [Client 6] POST / HTTP/1.1
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 6] Read: status=200, state=6
D [20/Apr/2017:09:13:52 +1000] [Client 6] No authentication data provided.
D [20/Apr/2017:09:13:52 +1000] [Client 6] 2.0 CUPS-Get-Printers 5
D [20/Apr/2017:09:13:52 +1000] CUPS-Get-Printers
D [20/Apr/2017:09:13:52 +1000] [Client 6] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [20/Apr/2017:09:13:52 +1000] [Client 6] Content-Length: 842
D [20/Apr/2017:09:13:52 +1000] [Client 6] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Apr/2017:09:13:52 +1000] [Client 6] con->http=0x55c12f6d69c0
D [20/Apr/2017:09:13:52 +1000] [Client 6] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=842, response=0x55c12f6ceb00(IPP_STATE_DATA), pipe_pid=0, file=-1
D [20/Apr/2017:09:13:52 +1000] [Client 6] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Apr/2017:09:13:52 +1000] [Client 6] bytes=0, http_state=0, data_remaining=842
D [20/Apr/2017:09:13:52 +1000] [Client 6] Flushing write buffer.
D [20/Apr/2017:09:13:52 +1000] [Client 6] New state is HTTP_STATE_WAITING
D [20/Apr/2017:09:13:52 +1000] [Client 6] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 6] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:13:52 +1000] [Client 6] Closing connection.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 7] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:13:52 +1000] [Client 7] Accepted from localhost (Domain)
D [20/Apr/2017:09:13:52 +1000] [Client 7] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] [Client 7] POST / HTTP/1.1
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 7] Read: status=200, state=6
D [20/Apr/2017:09:13:52 +1000] [Client 7] No authentication data provided.
D [20/Apr/2017:09:13:52 +1000] [Client 7] 2.0 CUPS-Get-Printers 6
D [20/Apr/2017:09:13:52 +1000] CUPS-Get-Printers
D [20/Apr/2017:09:13:52 +1000] [Client 7] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [20/Apr/2017:09:13:52 +1000] [Client 7] Content-Length: 2225
D [20/Apr/2017:09:13:52 +1000] [Client 7] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Apr/2017:09:13:52 +1000] [Client 7] con->http=0x55c12f6d69c0
D [20/Apr/2017:09:13:52 +1000] [Client 7] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2225, response=0x55c12f440500(IPP_STATE_DATA), pipe_pid=0, file=-1
D [20/Apr/2017:09:13:52 +1000] [Client 7] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Apr/2017:09:13:52 +1000] [Client 7] bytes=0, http_state=0, data_remaining=2225
D [20/Apr/2017:09:13:52 +1000] [Client 7] Flushing write buffer.
D [20/Apr/2017:09:13:52 +1000] [Client 7] New state is HTTP_STATE_WAITING
D [20/Apr/2017:09:13:52 +1000] [Client 7] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 7] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:13:52 +1000] [Client 7] Closing connection.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 8] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:13:52 +1000] [Client 8] Accepted from localhost (Domain)
D [20/Apr/2017:09:13:52 +1000] [Client 8] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] [Client 8] POST / HTTP/1.1
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 8] Read: status=200, state=6
D [20/Apr/2017:09:13:52 +1000] [Client 8] No authentication data provided.
D [20/Apr/2017:09:13:52 +1000] [Client 8] 2.0 Get-Jobs 7
D [20/Apr/2017:09:13:52 +1000] Get-Jobs ipp://localhost/
D [20/Apr/2017:09:13:52 +1000] [Client 8] Returning IPP successful-ok for Get-Jobs (ipp://localhost/) from localhost
D [20/Apr/2017:09:13:52 +1000] [Client 8] Content-Length: 75
D [20/Apr/2017:09:13:52 +1000] [Client 8] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [20/Apr/2017:09:13:52 +1000] [Client 8] con->http=0x55c12f6d69c0
D [20/Apr/2017:09:13:52 +1000] [Client 8] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=75, response=0x55c12f6cea50(IPP_STATE_DATA), pipe_pid=0, file=-1
D [20/Apr/2017:09:13:52 +1000] [Client 8] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [20/Apr/2017:09:13:52 +1000] [Client 8] bytes=0, http_state=0, data_remaining=75
D [20/Apr/2017:09:13:52 +1000] [Client 8] Flushing write buffer.
D [20/Apr/2017:09:13:52 +1000] [Client 8] New state is HTTP_STATE_WAITING
D [20/Apr/2017:09:13:52 +1000] [Client 8] Waiting for request.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Apr/2017:09:13:52 +1000] [Client 8] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:13:52 +1000] [Client 8] Closing connection.
D [20/Apr/2017:09:13:52 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
I [20/Apr/2017:09:13:53 +1000] Expiring subscriptions...
D [20/Apr/2017:09:14:08 +1000] [Client 9] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:14:08 +1000] [Client 9] Accepted from localhost (Domain)
D [20/Apr/2017:09:14:08 +1000] [Client 9] Waiting for request.
I [20/Apr/2017:09:14:08 +1000] Expiring subscriptions...
D [20/Apr/2017:09:14:08 +1000] [Client 9] PUT /admin/conf/cupsd.conf HTTP/1.1
D [20/Apr/2017:09:14:08 +1000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Apr/2017:09:14:08 +1000] [Client 9] Read: status=200, state=9
D [20/Apr/2017:09:14:08 +1000] [Client 9] No authentication data provided.
D [20/Apr/2017:09:14:08 +1000] cupsdIsAuthorized: username=""
D [20/Apr/2017:09:14:08 +1000] [Client 9] cupsdSendHeader: code=401, type="text/html", auth_type=0
D [20/Apr/2017:09:14:08 +1000] [Client 9] WWW-Authenticate: Basic realm=\"CUPS\", trc=\"y\"
D [20/Apr/2017:09:14:08 +1000] [Client 9] Closing connection.
D [20/Apr/2017:09:14:08 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Apr/2017:09:14:08 +1000] [Client 10] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:14:08 +1000] [Client 10] Accepted from localhost (Domain)
D [20/Apr/2017:09:14:08 +1000] [Client 10] Waiting for request.
D [20/Apr/2017:09:14:08 +1000] [Client 11] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:14:08 +1000] [Client 11] Accepted from localhost (Domain)
D [20/Apr/2017:09:14:08 +1000] [Client 11] Waiting for request.
D [20/Apr/2017:09:14:08 +1000] [Client 10] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:14:08 +1000] [Client 10] Closing connection.
D [20/Apr/2017:09:14:08 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Apr/2017:09:14:08 +1000] [Client 12] Server address is "/var/run/cups/cups.sock".
D [20/Apr/2017:09:14:08 +1000] [Client 12] Accepted from localhost (Domain)
D [20/Apr/2017:09:14:08 +1000] [Client 12] Waiting for request.
D [20/Apr/2017:09:14:08 +1000] [Client 11] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [20/Apr/2017:09:14:08 +1000] [Client 11] Closing connection.
D [20/Apr/2017:09:14:08 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [20/Apr/2017:09:14:08 +1000] [Client 12] PUT /admin/conf/cupsd.conf HTTP/1.1
D [20/Apr/2017:09:14:08 +1000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [20/Apr/2017:09:14:08 +1000] [Client 12] Read: status=200, state=9
D [20/Apr/2017:09:14:08 +1000] [Client 12] Authorized as root using PeerCred.
D [20/Apr/2017:09:14:08 +1000] cupsdIsAuthorized: username="root"
D [20/Apr/2017:09:14:08 +1000] [Client 12] Read: status=100, state=9
I [20/Apr/2017:09:14:08 +1000] [Client 12] Installing config file "/etc/cups/cupsd.conf"...
D [20/Apr/2017:09:14:08 +1000] [Client 12] cupsdSendHeader: code=201, type="(null)", auth_type=0
D [20/Apr/2017:09:14:08 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [20/Apr/2017:09:14:08 +1000] [Client 12] Closing connection.
D [20/Apr/2017:09:14:08 +1000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
E [20/Apr/2017:09:14:08 +1000] Scheduler shutting down due to program error.
D [20/Apr/2017:09:14:08 +1000] Discarding unused server-stopped event...
I [20/Apr/2017:09:14:08 +1000] Saving subscriptions.conf...
D [20/Apr/2017:09:14:08 +1000] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
D [20/Apr/2017:09:14:08 +1000] Creating keep-alive file "/var/cache/cups/org.cups.cupsd".
I [20/Apr/2017:09:14:08 +1000] Saving job.cache...
D [20/Apr/2017:09:14:08 +1000] cupsdStopSelect()

Attachment: signature.asc
Description: PGP signature

Reply to:

Follow-Ups:
- Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed
  - From: Brian Potkin <claremont102@gmail.com>

References:
- Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed
  - From: Ben Finney <bignose@debian.org>
- Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed
  - From: Brian Potkin <claremont102@gmail.com>
- Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed
  - From: Ben Finney <bignose@debian.org>
- Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed
  - From: Brian Potkin <claremont102@gmail.com>

Prev by Date: Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed
Next by Date: Processed: jbig2dec: CVE-2017-7976: Integer overflow in function jbig2_image_compose
Previous by thread: Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed
Next by thread: Bug#860591: cups-daemon: Job enters queue, then stops and can't be removed
Index(es):
- Date
- Thread