No print output when set to CMYK (SOLVED)

Forum rules
Before you post please read this
Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

No print output when set to CMYK (SOLVED)

Post by Keldorum » Wed Feb 06, 2019 9:09 am

Hi, I am running Cinnamon 3.8.9 32bit on an Acer laptop, but experienced the exact same problem when running this same OS version on a Dell desktop. I have a Canon MG2500 series printer which was printing just fine when I first used mint quite some time ago but for no reason decided it would not print at all suddenly? In the print dialogue box it gets stuck on "Rendering complete" but goes no further. After trial and error, removing the printer, reinstalling (to no avail) I discovered that if the printer settings were changed in CUPS to RGB it would print but the colours are all wrong obviously. It will also print in CMYcolor but well overprinted background. As soon as I re set the printer back to CMYK (which is what it should be) any print job, including a test page gets stuck on "Rendering complete"
BTW this is a fresh installation of MINT on this laptop and definitely not corrupted from any crashes. I have searched the web for this issue but nothing seems to relate to the CMYK issue.
This printer on both machines are hooked up via USB

Any help on this would be very much appreciated. Thank you in advance. :)
Last edited by Keldorum on Thu Feb 14, 2019 9:42 am, edited 1 time in total.

brian_p
Level 3
Level 3
Posts: 157
Joined: Thu Jan 17, 2019 9:20 am

Re: No print output when set to CMYK

Post by brian_p » Wed Feb 06, 2019 10:16 am

You need to get error_logs. See

https://wiki.debian.org/DissectingandDe ... ingSystem

Look for things like "filter", exited" and "crashed".
--
Brian.

brian_p
Level 3
Level 3
Posts: 157
Joined: Thu Jan 17, 2019 9:20 am

Re: No print output when set to CMYK

Post by brian_p » Wed Feb 06, 2019 1:41 pm

I forgot: you say
....if the printer settings were changed in CUPS to RGB....
Whereabouts in CUPS are the settings changed?
--
Brian.

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Wed Feb 06, 2019 5:43 pm

The printer installs as RGB mode so either in CUPS browser interface "set default options for MG2500 series"" OR in the CUPS Mint utility in "printer - properties - printer options" I have tried this multiple times. I can initiate "Print test page " in CMYK mode and it hangs at "Rendering completed" stage and you can wait forever,but if, during this stage I change the colour to RGB the printer jumps into life and prints out the page and finishes. Albeit in the wrong colours. Scanning the print logs there is mention of "Broken pipe"

Short section of parts with the error code

D [06/Feb/2019:16:42:00 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [06/Feb/2019:16:42:00 +0000] [Client 11] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [06/Feb/2019:16:42:00 +0000] [Client 11] Closing connection.
D [06/Feb/2019:16:42:00 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [06/Feb/2019:16:42:00 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [06/Feb/2019:16:42:00 +0000] [Client 12] Server address is "/run/cups/cups.sock".
D [06/Feb/2019:16:42:00 +0000] [Client 12] Accepted from localhost (Domain)
D [06/Feb/2019:16:42:00 +0000] [Client 12] Waiting for request.
D [06/Feb/2019:16:42:00 +0000] [Client 12] PUT /admin/conf/cupsd.conf HTTP/1.1
D [06/Feb/2019:16:42:00 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [06/Feb/2019:16:42:00 +0000] [Client 12] Read: status=200, state=9
D [06/Feb/2019:16:42:00 +0000] [Client 12] Authorized as root using Local.
D [06/Feb/2019:16:42:00 +0000] cupsdIsAuthorized: username="root"
D [06/Feb/2019:16:42:00 +0000] [Client 12] Read: status=100, state=9
I [06/Feb/2019:16:42:00 +0000] [Client 12] Installing config file "/etc/cups/cupsd.conf"...
D [06/Feb/2019:16:42:00 +0000] [Client 12] cupsdSendHeader: code=201, type="(null)", auth_type=0
D [06/Feb/2019:16:42:00 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [06/Feb/2019:16:42:00 +0000] [Client 7] Closing connection.
D [06/Feb/2019:16:42:00 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [06/Feb/2019:16:42:00 +0000] [Client 12] Closing connection.
D [06/Feb/2019:16:42:00 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
E [06/Feb/2019:16:42:00 +0000] Scheduler shutting down due to program error.

If I attempt to print a test page in the browser interface set as CMYK I can see at the bottom in the status bar a message whizzing by "Waiting for localhost" multiple times as if the printer is cocking a deaf ear...

brian_p
Level 3
Level 3
Posts: 157
Joined: Thu Jan 17, 2019 9:20 am

Re: No print output when set to CMYK

Post by brian_p » Wed Feb 06, 2019 6:27 pm

The data you provide for a failed job are not very useful.

Empty the error_log with

Code: Select all

>/var/log/cups/error_log
Then print and send the error_log here as an attachment.
--
Brian.

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Thu Feb 07, 2019 9:55 am

Error log in CUPS cleared, this is todays error log in total with a CMYK print test command sent to the printer. No need for attachment due to small size

E [07/Feb/2019:13:38:33 +0000] Unknown directive JobPrivateAccess on line 123 of /etc/cups/cupsd.conf.
E [07/Feb/2019:13:38:33 +0000] Unknown directive JobPrivateValues on line 124 of /etc/cups/cupsd.conf.
E [07/Feb/2019:13:38:33 +0000] Unknown directive SubscriptionPrivateAccess on line 125 of /etc/cups/cupsd.conf.
E [07/Feb/2019:13:38:33 +0000] Unknown directive SubscriptionPrivateValues on line 126 of /etc/cups/cupsd.conf.
W [07/Feb/2019:13:49:15 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-Gray..\' already exists
W [07/Feb/2019:13:49:15 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-RGB..\' already exists
E [07/Feb/2019:13:49:44 +0000] [cups-deviced] PID 2791 (gutenprint52+usb) stopped with status 1!

brian_p
Level 3
Level 3
Posts: 157
Joined: Thu Jan 17, 2019 9:20 am

Re: No print output when set to CMYK

Post by brian_p » Thu Feb 07, 2019 12:06 pm

My first thought is that, for a print job (successful or not), your log is way too minimal. The type of file sent to the printer and the filters used should be recorded at the very least. You will have a PPD in /etc/cups/ppd. Another approach is to try

Code: Select all

sudo cupsfilter -p <PPD> -m printer/foo -e /etc/adjtime > output.dat 2>log
Four filters are used. Look in log and see whether all four exit with "no error".

Incidentally, the default for DefaultColorSpace in the PPD provided by Gutenprint is "RGB".
--
Brian.

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Sat Feb 09, 2019 6:46 am

Hi Brian, I have inputted the last code you posted and now its returning this.

*crunch@crunch-Extensa-5235:~$ sudo cupsfilter -p <PPD> -m printer/foo -e /etc/adjtime > output.dat 2>log
bash: PPD: No such file or directory*

BTW I was obtaining the error log directly from cups browser interface. The above was what terminal came back with. When I tried to run *>/var/log/cups/error_log* it comes back with *Permission denied* and when I attempt to log in as sudo it comes back with *Authentication failure* even though my pw is correct. tried this a hundred times. I am not having a great time! I appreciate your help. We will get there eventually!!
Last edited by Keldorum on Sat Feb 09, 2019 7:36 am, edited 1 time in total.

brian_p
Level 3
Level 3
Posts: 157
Joined: Thu Jan 17, 2019 9:20 am

Re: No print output when set to CMYK

Post by brian_p » Sat Feb 09, 2019 7:34 am

Keldorum wrote:
Sat Feb 09, 2019 6:46 am
Hi Brian, I have inputted the last code you posted and now its returning this.

*bash: PPD: No such file or directory*
I think I will have to be more explicit in the future. <PPD> means - substitute whatever the PPD in /etc/cups/ppd is (without "<" and ">"). For example, if it is /etc/cups/ppd/mg2500.ppd, the command would be

Code: Select all

sudo cupsfilter -p /etc/cups/ppd/mg2500.ppd  -m printer/foo -e /etc/adjtime > output.dat 2>log
BTW I was obtaining the error log directly from cups browser interface. The above was what terminal came back with. When I tried to run *>/var/log/cups/error_log* it comes back with *Permission denied* and when I attempt to log in as sudo it comes back with *Authentication failure* even though my pw is correct. tried this a hundred times. I am not having a great time! I appreciate your help. We will get there eventually!!
My fault. The command is

Code: Select all

sudo >/var/log/cups/error_log
I cannot help with the pw problem but there are ways to get a user a new pw if it has been forgotten.
--
Brian.

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Sat Feb 09, 2019 7:38 am

Thanks Brian. Must explain I am relatively new to this, also got M.E. and my head is full off fog most of the time! Will correct the code...
Its taking my password fine now but it throws back this;

crunch@crunch-Extensa-5235:~$ sudo cupsfilter -p /etc/cups/ppd/mg2500.ppd -m printer/foo -e /etc/adjtime > output.dat 2>log
[sudo] password for crunch:
Segmentation fault

I have also typed the printer name as mg2500-series as that is how it is actually described. And without a hyphen between mg2500 and series. Keeps throwing back "segmentation fault" which I searched for and got this

"A segmentation fault, or segfault, is a memory error in which a program tries to access a memory address that does not exist or the program does not have the rights to access. It is a common bug in poorly written C and C++ programs. When a program hits a segmentation fault, it often crashes with the error phrase "Segmentation Fault."

BTW you must be banging your head against the desktop! I used to do what you are doing for me with Windows users! I admit that what I found quite easy was hell for the person on the other end of the telephone or computer. I know how you feel! lol

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Sat Feb 09, 2019 9:44 am

Cant attach error log. Get this message from the server; I will have to post it

Error

The file is too big, maximum allowed size is 16 KiB.

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Sat Feb 09, 2019 9:56 am

W [09/Feb/2019:13:23:34 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-Gray..\' already exists
W [09/Feb/2019:13:23:34 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-RGB..\' already exists
W [09/Feb/2019:13:25:16 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-Gray..\' already exists
W [09/Feb/2019:13:25:16 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-RGB..\' already exists
W [09/Feb/2019:13:26:27 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-Gray..\' already exists
W [09/Feb/2019:13:26:27 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-RGB..\' already exists
W [09/Feb/2019:13:27:44 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-Gray..\' already exists
W [09/Feb/2019:13:27:44 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-RGB..\' already exists
W [09/Feb/2019:13:28:20 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-Gray..\' already exists
W [09/Feb/2019:13:28:20 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-RGB..\' already exists
W [09/Feb/2019:13:28:54 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-Gray..\' already exists
W [09/Feb/2019:13:28:54 +0000] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id \'MG2500-series-RGB..\' already exists
E [09/Feb/2019:13:30:53 +0000] Scheduler shutting down due to program error.
I [09/Feb/2019:13:31:10 +0000] Listening to [v1.::1]:631 (IPv6)
I [09/Feb/2019:13:31:10 +0000] Listening to 127.0.0.1:631 (IPv4)
I [09/Feb/2019:13:31:10 +0000] Listening to /run/cups/cups.sock (Domain)
E [09/Feb/2019:13:31:10 +0000] Unknown directive JobPrivateAccess on line 123 of /etc/cups/cupsd.conf.
E [09/Feb/2019:13:31:10 +0000] Unknown directive JobPrivateValues on line 124 of /etc/cups/cupsd.conf.
E [09/Feb/2019:13:31:10 +0000] Unknown directive SubscriptionPrivateAccess on line 125 of /etc/cups/cupsd.conf.
E [09/Feb/2019:13:31:10 +0000] Unknown directive SubscriptionPrivateValues on line 126 of /etc/cups/cupsd.conf.
I [09/Feb/2019:13:31:10 +0000] Remote access is disabled.
D [09/Feb/2019:13:31:10 +0000] Added auto ServerAlias crunch-Extensa-5235
I [09/Feb/2019:13:31:10 +0000] Loaded configuration file "/etc/cups/cupsd.conf"
D [09/Feb/2019:13:31:10 +0000] Using keychain "/etc/cups/ssl" for server name "crunch-Extensa-5235".
I [09/Feb/2019:13:31:10 +0000] Using default TempDir of /var/spool/cups/tmp...
I [09/Feb/2019:13:31:10 +0000] Configured for up to 100 clients.
I [09/Feb/2019:13:31:10 +0000] Allowing up to 100 client connections per host.
I [09/Feb/2019:13:31:10 +0000] Using policy "default" as the default.
I [09/Feb/2019:13:31:10 +0000] Full reload is required.
I [09/Feb/2019:13:31:10 +0000] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 78 types, 118 filters...
D [09/Feb/2019:13:31:10 +0000] Loading printer MG2500-series...
D [09/Feb/2019:13:31:10 +0000] load_ppd: Loading /var/cache/cups/MG2500-series.data...
D [09/Feb/2019:13:31:10 +0000] cupsdRegisterPrinter(p=0x63b220(MG2500-series))
I [09/Feb/2019:13:31:10 +0000] Loading job cache file "/var/cache/cups/job.cache"...
D [09/Feb/2019:13:31:10 +0000] [Job 10] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 11] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 12] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 13] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 14] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 15] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 16] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 17] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 18] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 19] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 20] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 21] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 22] Loading from cache...
D [09/Feb/2019:13:31:10 +0000] [Job 22] Loading attributes...
D [09/Feb/2019:13:31:10 +0000] [Job 22] Unloading...
D [09/Feb/2019:13:31:10 +0000] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [09/Feb/2019:13:31:10 +0000] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [09/Feb/2019:13:31:10 +0000] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
D [09/Feb/2019:13:31:10 +0000] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)")
I [09/Feb/2019:13:31:10 +0000] Full reload complete.
D [09/Feb/2019:13:31:10 +0000] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)")
I [09/Feb/2019:13:31:10 +0000] Cleaning out old files in "/var/spool/cups/tmp".
D [09/Feb/2019:13:31:10 +0000] cupsdCleanFiles(path="/var/spool/cups/tmp/.hplip", pattern="(null)")
I [09/Feb/2019:13:31:10 +0000] Cleaning out old files in "/var/spool/cups/tmp/.hplip".
D [09/Feb/2019:13:31:10 +0000] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp")
I [09/Feb/2019:13:31:10 +0000] Cleaning out old files in "/var/cache/cups".
D [09/Feb/2019:13:31:10 +0000] service_checkin: pid=2638
D [09/Feb/2019:13:31:10 +0000] service_checkin: 1 listeners.
D [09/Feb/2019:13:31:10 +0000] service_add_listener: Listener #1 at fd 3, "/run/cups/cups.sock".
D [09/Feb/2019:13:31:10 +0000] service_add_listener: Matched existing listener #1 to /run/cups/cups.sock.
D [09/Feb/2019:13:31:10 +0000] Creating KeepAlive/PID file "/var/cache/cups/org.cups.cupsd".
D [09/Feb/2019:13:31:10 +0000] Calling FindDeviceById(cups-MG2500-series)
D [09/Feb/2019:13:31:10 +0000] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id \'cups-MG2500-series\' does not exist
D [09/Feb/2019:13:31:10 +0000] Using profile ID "MG2500-series-Gray..".
D [09/Feb/2019:13:31:10 +0000] Calling CreateProfile(MG2500-series-Gray..,temp)
D [09/Feb/2019:13:31:10 +0000] Created profile "/org/freedesktop/ColorManager/profiles/MG2500_series_Gray__".
D [09/Feb/2019:13:31:10 +0000] Using profile ID "MG2500-series-RGB..".
D [09/Feb/2019:13:31:10 +0000] Calling CreateProfile(MG2500-series-RGB..,temp)
D [09/Feb/2019:13:31:10 +0000] Created profile "/org/freedesktop/ColorManager/profiles/MG2500_series_RGB__".
I [09/Feb/2019:13:31:10 +0000] Registering ICC color profiles for "MG2500-series".
D [09/Feb/2019:13:31:10 +0000] Calling CreateDevice(cups-MG2500-series,temp)
D [09/Feb/2019:13:31:10 +0000] Created device "/org/freedesktop/ColorManager/devices/cups_MG2500_series".
D [09/Feb/2019:13:31:10 +0000] Calling /org/freedesktop/ColorManager/devices/cups_MG2500_series:AddProfile(/org/freedesktop/ColorManager/profiles/MG2500_series_Gray__) [soft]
D [09/Feb/2019:13:31:10 +0000] Calling /org/freedesktop/ColorManager/devices/cups_MG2500_series:AddProfile(/org/freedesktop/ColorManager/profiles/MG2500_series_RGB__) [soft]
I [09/Feb/2019:13:31:10 +0000] Listening to [v1.::1]:631 on fd 7...
I [09/Feb/2019:13:31:10 +0000] Listening to 127.0.0.1:631 on fd 8...
I [09/Feb/2019:13:31:10 +0000] Listening to /run/cups/cups.sock on fd 3...
I [09/Feb/2019:13:31:10 +0000] Resuming new connection processing...
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [09/Feb/2019:13:31:10 +0000] cupsdAddCert: Adding certificate for PID 0
D [09/Feb/2019:13:31:10 +0000] Notifier dbus started - PID = 2643
D [09/Feb/2019:13:31:10 +0000] cupsdMarkDirty(----S)
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy"
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 1] Server address is "/run/cups/cups.sock".
D [09/Feb/2019:13:31:10 +0000] [Client 1] Accepted from localhost (Domain)
D [09/Feb/2019:13:31:10 +0000] [Client 1] Waiting for request.
D [09/Feb/2019:13:31:10 +0000] Report: clients=1
D [09/Feb/2019:13:31:10 +0000] Report: jobs=13
D [09/Feb/2019:13:31:10 +0000] Report: jobs-active=0
D [09/Feb/2019:13:31:10 +0000] Report: printers=1
D [09/Feb/2019:13:31:10 +0000] Report: stringpool-string-count=27115
D [09/Feb/2019:13:31:10 +0000] Report: stringpool-alloc-bytes=18032
D [09/Feb/2019:13:31:10 +0000] Report: stringpool-total-bytes=504328
D [09/Feb/2019:13:31:10 +0000] [Client 1] POST / HTTP/1.1
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 1] Read: status=200, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 1] No authentication data provided.
D [09/Feb/2019:13:31:10 +0000] [Client 1] 2.0 Create-Printer-Subscriptions 1
D [09/Feb/2019:13:31:10 +0000] Create-Printer-Subscriptions /
D [09/Feb/2019:13:31:10 +0000] create_subscriptions(con=0x7e3a00(1), uri="/")
D [09/Feb/2019:13:31:10 +0000] pullmethod="ippget"
D [09/Feb/2019:13:31:10 +0000] notify-lease-duration=86400
D [09/Feb/2019:13:31:10 +0000] notify-time-interval=60
D [09/Feb/2019:13:31:10 +0000] cupsdAddSubscription(mask=7ff, dest=(nil)(), job=(nil)(0), uri="(null)")
D [09/Feb/2019:13:31:10 +0000] Added subscription #193 for server.
D [09/Feb/2019:13:31:10 +0000] cupsdMarkDirty(----S)
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 1] Returning IPP successful-ok for Create-Printer-Subscriptions (/) from localhost
D [09/Feb/2019:13:31:10 +0000] [Client 1] Content-Length: 107
D [09/Feb/2019:13:31:10 +0000] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [09/Feb/2019:13:31:10 +0000] [Client 1] con->http=0x81ee50
D [09/Feb/2019:13:31:10 +0000] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=107, response=0x7ea140(IPP_STATE_DATA), pipe_pid=0, file=-1
D [09/Feb/2019:13:31:10 +0000] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [09/Feb/2019:13:31:10 +0000] [Client 1] bytes=0, http_state=0, data_remaining=107
D [09/Feb/2019:13:31:10 +0000] [Client 1] Flushing write buffer.
D [09/Feb/2019:13:31:10 +0000] [Client 1] New state is HTTP_STATE_WAITING
D [09/Feb/2019:13:31:10 +0000] [Client 1] Waiting for request.
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 2] Server address is "/run/cups/cups.sock".
D [09/Feb/2019:13:31:10 +0000] [Client 2] Accepted from localhost (Domain)
D [09/Feb/2019:13:31:10 +0000] [Client 2] Waiting for request.
D [09/Feb/2019:13:31:10 +0000] [Client 2] POST / HTTP/1.1
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 2] Read: status=200, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 2] No authentication data provided.
D [09/Feb/2019:13:31:10 +0000] [Client 2] 2.0 CUPS-Get-Printers 2
D [09/Feb/2019:13:31:10 +0000] CUPS-Get-Printers
D [09/Feb/2019:13:31:10 +0000] [Client 2] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [09/Feb/2019:13:31:10 +0000] [Client 2] Content-Length: 1310
D [09/Feb/2019:13:31:10 +0000] [Client 2] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [09/Feb/2019:13:31:10 +0000] [Client 2] con->http=0x7f03c0
D [09/Feb/2019:13:31:10 +0000] [Client 2] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1310, response=0x646410(IPP_STATE_DATA), pipe_pid=0, file=-1
D [09/Feb/2019:13:31:10 +0000] [Client 2] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [09/Feb/2019:13:31:10 +0000] [Client 2] bytes=0, http_state=0, data_remaining=1310
D [09/Feb/2019:13:31:10 +0000] [Client 2] Flushing write buffer.
D [09/Feb/2019:13:31:10 +0000] [Client 2] New state is HTTP_STATE_WAITING
D [09/Feb/2019:13:31:10 +0000] [Client 2] Waiting for request.
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 2] POST / HTTP/1.1
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 2] Read: status=200, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 2] No authentication data provided.
D [09/Feb/2019:13:31:10 +0000] [Client 2] 2.0 CUPS-Get-Default 3
D [09/Feb/2019:13:31:10 +0000] CUPS-Get-Default
D [09/Feb/2019:13:31:10 +0000] [Client 2] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [09/Feb/2019:13:31:10 +0000] [Client 2] Content-Length: 21921
D [09/Feb/2019:13:31:10 +0000] [Client 2] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [09/Feb/2019:13:31:10 +0000] [Client 2] con->http=0x7f03c0
D [09/Feb/2019:13:31:10 +0000] [Client 2] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=21921, response=0x7c16e0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [09/Feb/2019:13:31:10 +0000] [Client 2] Writing IPP response, ipp_state=IPP_STATE_ATTRIBUTE, old wused=0, new wused=0
D [09/Feb/2019:13:31:10 +0000] [Client 2] bytes=1, http_state=7, data_remaining=21921
D [09/Feb/2019:13:31:10 +0000] [Notifier] state=3
D [09/Feb/2019:13:31:10 +0000] [Client 2] con->http=0x7f03c0
D [09/Feb/2019:13:31:10 +0000] [Client 2] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=21921, response=0x7c16e0(IPP_STATE_DATA), pipe_pid=0, file=-1
D [09/Feb/2019:13:31:10 +0000] [Client 2] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [09/Feb/2019:13:31:10 +0000] [Client 2] bytes=0, http_state=0, data_remaining=21921
D [09/Feb/2019:13:31:10 +0000] [Client 2] Flushing write buffer.
D [09/Feb/2019:13:31:10 +0000] [Client 2] New state is HTTP_STATE_WAITING
D [09/Feb/2019:13:31:10 +0000] [Client 2] Waiting for request.
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 1] POST / HTTP/1.1
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 1] Read: status=200, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 1] No authentication data provided.
D [09/Feb/2019:13:31:10 +0000] [Notifier] Connected to D-BUS
D [09/Feb/2019:13:31:10 +0000] [Notifier] ServerStarted
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 3] Server address is "/run/cups/cups.sock".
D [09/Feb/2019:13:31:10 +0000] [Client 3] Accepted from localhost (Domain)
D [09/Feb/2019:13:31:10 +0000] [Client 3] Waiting for request.
D [09/Feb/2019:13:31:10 +0000] [Client 3] POST / HTTP/1.1
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 3] Read: status=200, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 3] No authentication data provided.
D [09/Feb/2019:13:31:10 +0000] [Client 3] 2.0 Get-Notifications 1420
D [09/Feb/2019:13:31:10 +0000] Get-Notifications /printers/
D [09/Feb/2019:13:31:10 +0000] cupsdIsAuthorized: requesting-user-name="crunch"
D [09/Feb/2019:13:31:10 +0000] [Client 3] Returning IPP successful-ok for Get-Notifications (/printers/) from localhost
D [09/Feb/2019:13:31:10 +0000] [Client 3] Content-Length: 127
D [09/Feb/2019:13:31:10 +0000] [Client 3] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [09/Feb/2019:13:31:10 +0000] [Client 3] con->http=0x8319b0
D [09/Feb/2019:13:31:10 +0000] [Client 3] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=127, response=0x809a60(IPP_STATE_DATA), pipe_pid=0, file=-1
D [09/Feb/2019:13:31:10 +0000] [Client 3] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [09/Feb/2019:13:31:10 +0000] [Client 3] bytes=0, http_state=0, data_remaining=127
D [09/Feb/2019:13:31:10 +0000] [Client 3] Flushing write buffer.
D [09/Feb/2019:13:31:10 +0000] [Client 3] New state is HTTP_STATE_WAITING
D [09/Feb/2019:13:31:10 +0000] [Client 3] Waiting for request.
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:10 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:10 +0000] [Client 1] 2.0 CUPS-Get-Default 4
D [09/Feb/2019:13:31:10 +0000] CUPS-Get-Default
D [09/Feb/2019:13:31:10 +0000] [Client 1] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [09/Feb/2019:13:31:10 +0000] [Client 1] Content-Length: 21921
D [09/Feb/2019:13:31:10 +0000] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [09/Feb/2019:13:31:10 +0000] [Client 1] con->http=0x81ee50
D [09/Feb/2019:13:31:10 +0000] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=21921, response=0x809a60(IPP_STATE_DATA), pipe_pid=0, file=-1
D [09/Feb/2019:13:31:10 +0000] [Client 1] Writing IPP response, ipp_state=IPP_STATE_ATTRIBUTE, old wused=0, new wused=0
D [09/Feb/2019:13:31:10 +0000] [Client 1] bytes=1, http_state=7, data_remaining=21921
D [09/Feb/2019:13:31:10 +0000] [Client 1] con->http=0x81ee50
D [09/Feb/2019:13:31:10 +0000] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=21921, response=0x809a60(IPP_STATE_DATA), pipe_pid=0, file=-1
D [09/Feb/2019:13:31:10 +0000] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [09/Feb/2019:13:31:10 +0000] [Client 1] bytes=0, http_state=0, data_remaining=21921
D [09/Feb/2019:13:31:10 +0000] [Client 1] Flushing write buffer.
D [09/Feb/2019:13:31:10 +0000] [Client 1] New state is HTTP_STATE_WAITING
D [09/Feb/2019:13:31:10 +0000] [Client 1] Waiting for request.
D [09/Feb/2019:13:31:10 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:11 +0000] [Client 1] POST / HTTP/1.1
D [09/Feb/2019:13:31:11 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:11 +0000] [Client 1] Read: status=200, state=6
D [09/Feb/2019:13:31:11 +0000] [Client 1] No authentication data provided.
I [09/Feb/2019:13:31:11 +0000] Expiring subscriptions...
D [09/Feb/2019:13:31:11 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:11 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:11 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:11 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:11 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:11 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:11 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:11 +0000] [Client 1] Read: status=100, state=6
D [09/Feb/2019:13:31:11 +0000] [Client 1] 2.0 Create-Printer-Subscriptions 5
D [09/Feb/2019:13:31:11 +0000] Create-Printer-Subscriptions /
D [09/Feb/2019:13:31:11 +0000] create_subscriptions(con=0x7e3a00(1), uri="/")
D [09/Feb/2019:13:31:11 +0000] recipient="dbus://"
D [09/Feb/2019:13:31:11 +0000] notify-lease-duration=86400
D [09/Feb/2019:13:31:11 +0000] notify-time-interval=0
D [09/Feb/2019:13:31:11 +0000] cupsdAddSubscription(mask=1fffff, dest=(nil)(), job=(nil)(0), uri="dbus://")
D [09/Feb/2019:13:31:11 +0000] Added subscription #194 for server.
D [09/Feb/2019:13:31:11 +0000] cupsdMarkDirty(----S)
D [09/Feb/2019:13:31:11 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:11 +0000] [Client 1] Returning IPP successful-ok for Create-Printer-Subscriptions (/) from localhost
D [09/Feb/2019:13:31:11 +0000] [Client 1] Content-Length: 107
D [09/Feb/2019:13:31:11 +0000] [Client 1] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [09/Feb/2019:13:31:11 +0000] [Client 1] con->http=0x81ee50
D [09/Feb/2019:13:31:11 +0000] [Client 1] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=107, response=0x831930(IPP_STATE_DATA), pipe_pid=0, file=-1
D [09/Feb/2019:13:31:11 +0000] [Client 1] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [09/Feb/2019:13:31:11 +0000] [Client 1] bytes=0, http_state=0, data_remaining=107
D [09/Feb/2019:13:31:11 +0000] [Client 1] Flushing write buffer.
D [09/Feb/2019:13:31:11 +0000] [Client 1] New state is HTTP_STATE_WAITING
D [09/Feb/2019:13:31:11 +0000] [Client 1] Waiting for request.
D [09/Feb/2019:13:31:11 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
I [09/Feb/2019:13:31:12 +0000] Expiring subscriptions...
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:17 +0000] [Client 4] Server address is "127.0.0.1".
D [09/Feb/2019:13:31:17 +0000] [Client 4] Accepted from localhost:48200 (IPv4)
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for request.
I [09/Feb/2019:13:31:17 +0000] Expiring subscriptions...
D [09/Feb/2019:13:31:17 +0000] [Client 4] GET /admin/?OP=redirect HTTP/1.1
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:17 +0000] [Client 4] Read: status=200, state=3
D [09/Feb/2019:13:31:17 +0000] [Client 4] Authorized as "crunch" using Basic.
D [09/Feb/2019:13:31:17 +0000] [Client 4] Processing GET /admin/?OP=redirect
D [09/Feb/2019:13:31:17 +0000] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/admin.cgi"
D [09/Feb/2019:13:31:17 +0000] [CGI] argv[1] = "OP=redirect"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc-root"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[10] = "SERVER_ADMIN=root@crunch-Extensa-5235"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.7"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[13] = "USER=root"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[17] = "IPP_PORT=631"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[19] = "LANG=en_GB.UTF8"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[22] = "SERVER_NAME=127.0.0.1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[23] = "SERVER_PORT=631"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[24] = "REMOTE_ADDR=127.0.0.1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[26] = "SCRIPT_NAME=/admin/"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc-root/admin/"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[28] = "REMOTE_USER=crunch"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[29] = "SERVER_PROTOCOL=HTTP/1.1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[30] = "HTTP_COOKIE=org.cups.sid=736f19d32e58ee2435828305ff5e1742"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[31] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:65.0) Gecko/20100101 Firefox/65.0"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[32] = "REQUEST_METHOD=GET"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[33] = "QUERY_STRING=OP=redirect"
D [09/Feb/2019:13:31:17 +0000] cupsdAddCert: Adding certificate for PID 2646
D [09/Feb/2019:13:31:17 +0000] [CGI] Started /usr/lib/cups/cgi-bin/admin.cgi (PID 2646)
I [09/Feb/2019:13:31:17 +0000] [Client 4] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=2646, file=19)
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [CGI] admin.cgi started...
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:17 +0000] [Client 5] Server address is "/run/cups/cups.sock".
D [09/Feb/2019:13:31:17 +0000] [Client 5] Accepted from localhost (Domain)
D [09/Feb/2019:13:31:17 +0000] [Client 5] Waiting for request.
D [09/Feb/2019:13:31:17 +0000] [CGI] http=0x1fd2840
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SECTION=\"admin\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [09/Feb/2019:13:31:17 +0000] [CGI] org.cups.sid cookie is \"736f19d32e58ee2435828305ff5e1742\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: OP=\"redirect\"
D [09/Feb/2019:13:31:17 +0000] [CGI] redirecting with prefix http://127.0.0.1:631!
D [09/Feb/2019:13:31:17 +0000] [Client 5] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [09/Feb/2019:13:31:17 +0000] [Client 5] Closing connection.
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:17 +0000] [Client 4] CGI data ready to be sent.
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=2646, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] Script header: Location: http://127.0.0.1:631/admin
D [09/Feb/2019:13:31:17 +0000] [Client 4] Script header:
D [09/Feb/2019:13:31:17 +0000] [Client 4] Sending status 303 for CGI.
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdSendHeader: code=303, type="(null)", auth_type=0
D [09/Feb/2019:13:31:17 +0000] [Client 4] Flushing write buffer.
D [09/Feb/2019:13:31:17 +0000] [Client 4] New state is HTTP_STATE_WAITING
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for request.
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:17 +0000] PID 2646 (/usr/lib/cups/cgi-bin/admin.cgi) was terminated normally with signal 15.
D [09/Feb/2019:13:31:17 +0000] [Client 4] GET /admin HTTP/1.1
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:17 +0000] [Client 4] Read: status=200, state=3
D [09/Feb/2019:13:31:17 +0000] [Client 4] Authorized as "crunch" using Basic.
D [09/Feb/2019:13:31:17 +0000] [Client 4] Processing GET /admin
D [09/Feb/2019:13:31:17 +0000] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/admin.cgi"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc-root"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[7] = "CUPS_STATEDIR=/run/cups"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[10] = "SERVER_ADMIN=root@crunch-Extensa-5235"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[11] = "SOFTWARE=CUPS/2.2.7"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[13] = "USER=root"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[15] = "CUPS_SERVER=/run/cups/cups.sock"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[17] = "IPP_PORT=631"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[19] = "LANG=en_GB.UTF8"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[22] = "SERVER_NAME=127.0.0.1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[23] = "SERVER_PORT=631"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[24] = "REMOTE_ADDR=127.0.0.1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[26] = "SCRIPT_NAME=/admin"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc-root/admin"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[28] = "REMOTE_USER=crunch"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[29] = "SERVER_PROTOCOL=HTTP/1.1"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[30] = "HTTP_COOKIE=org.cups.sid=736f19d32e58ee2435828305ff5e1742"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[31] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:65.0) Gecko/20100101 Firefox/65.0"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[32] = "REQUEST_METHOD=GET"
D [09/Feb/2019:13:31:17 +0000] [CGI] envp[33] = "QUERY_STRING="
D [09/Feb/2019:13:31:17 +0000] cupsdAddCert: Adding certificate for PID 2647
D [09/Feb/2019:13:31:17 +0000] [CGI] Started /usr/lib/cups/cgi-bin/admin.cgi (PID 2647)
I [09/Feb/2019:13:31:17 +0000] [Client 4] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=2647, file=19)
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [CGI] admin.cgi started...
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:17 +0000] [Client 6] Server address is "/run/cups/cups.sock".
D [09/Feb/2019:13:31:17 +0000] [Client 6] Accepted from localhost (Domain)
D [09/Feb/2019:13:31:17 +0000] [Client 6] Waiting for request.
D [09/Feb/2019:13:31:17 +0000] [CGI] http=0xe34840
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SECTION=\"admin\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REFRESH_PAGE=\"\"
D [09/Feb/2019:13:31:17 +0000] [CGI] org.cups.sid cookie is \"736f19d32e58ee2435828305ff5e1742\"
D [09/Feb/2019:13:31:17 +0000] [CGI] No form data, showing main menu...
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: DEBUG_LOGGING=\"CHECKED\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: HAVE_GSSAPI=\"1\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: KERBEROS=\"\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: PRESERVE_JOBS=\"CHECKED\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: PRESERVE_JOB_HISTORY=\"Yes\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: PRESERVE_JOB_FILES=\"1d\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: MAX_CLIENTS=\"100\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: MAX_JOBS=\"500\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: MAX_LOG_SIZE=\"0\"
D [09/Feb/2019:13:31:17 +0000] [CGI] /usr/share/cups/drivers/pscript5.dll: No such file or directory
D [09/Feb/2019:13:31:17 +0000] [Client 6] POST / HTTP/1.1
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:17 +0000] [Client 6] Read: status=200, state=6
D [09/Feb/2019:13:31:17 +0000] [Client 6] No authentication data provided.
D [09/Feb/2019:13:31:17 +0000] [Client 6] Read: status=100, state=6
D [09/Feb/2019:13:31:17 +0000] [Client 6] Read: status=100, state=6
D [09/Feb/2019:13:31:17 +0000] [Client 6] Read: status=100, state=6
D [09/Feb/2019:13:31:17 +0000] [Client 6] Read: status=100, state=6
D [09/Feb/2019:13:31:17 +0000] [Client 6] Read: status=100, state=6
D [09/Feb/2019:13:31:17 +0000] [Client 6] 2.0 Get-Subscriptions 1
D [09/Feb/2019:13:31:17 +0000] Get-Subscriptions ipp://localhost/
I [09/Feb/2019:13:31:17 +0000] Expiring subscriptions...
D [09/Feb/2019:13:31:17 +0000] [Client 6] Returning IPP successful-ok for Get-Subscriptions (ipp://localhost/) from localhost
D [09/Feb/2019:13:31:17 +0000] [Client 6] Content-Length: 809
D [09/Feb/2019:13:31:17 +0000] [Client 6] cupsdSendHeader: code=200, type="application/ipp", auth_type=0
D [09/Feb/2019:13:31:17 +0000] [Client 6] con->http=0x7cf310
D [09/Feb/2019:13:31:17 +0000] [Client 6] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=809, response=0x647320(IPP_STATE_DATA), pipe_pid=0, file=-1
D [09/Feb/2019:13:31:17 +0000] [Client 6] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0
D [09/Feb/2019:13:31:17 +0000] [Client 6] bytes=0, http_state=0, data_remaining=809
D [09/Feb/2019:13:31:17 +0000] [Client 6] Flushing write buffer.
D [09/Feb/2019:13:31:17 +0000] [Client 6] New state is HTTP_STATE_WAITING
D [09/Feb/2019:13:31:17 +0000] [Client 6] Waiting for request.
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:17 +0000] PID 2647 (/usr/lib/cups/cgi-bin/admin.cgi) exited with no errors.
D [09/Feb/2019:13:31:17 +0000] [Client 6] HTTP_STATE_WAITING Closing for error 32 (Broken pipe)
D [09/Feb/2019:13:31:17 +0000] [Client 6] Closing connection.
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SERVER_NAME=\"127.0.0.1\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REMOTE_USER=\"crunch\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.7\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SERVER_NAME=\"127.0.0.1\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REMOTE_USER=\"crunch\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.7\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_lease_duration[0]=\"86400\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_time_interval[0]=\"60\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_subscription_id[0]=\"189\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SERVER_NAME=\"127.0.0.1\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REMOTE_USER=\"crunch\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.7\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_events[1]=\"all\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_lease_duration[1]=\"86400\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_recipient_uri[1]=\"dbus://\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_recipient_name[1]=\"/\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_subscriber_user_name[1]=\"anonymous\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_time_interval[1]=\"0\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_subscription_id[1]=\"190\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SERVER_NAME=\"127.0.0.1\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REMOTE_USER=\"crunch\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.7\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_lease_duration[2]=\"3600\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_time_interval[2]=\"0\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_subscription_id[2]=\"191\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SERVER_NAME=\"127.0.0.1\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REMOTE_USER=\"crunch\"
D [09/Feb/2019:13:31:17 +0000] [Client 4] CGI data ready to be sent.
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.7\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_lease_duration[3]=\"86400\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_time_interval[3]=\"0\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_subscription_id[3]=\"192\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SERVER_NAME=\"127.0.0.1\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REMOTE_USER=\"crunch\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.7\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_lease_duration[4]=\"86400\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_time_interval[4]=\"60\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_subscription_id[4]=\"193\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SERVER_NAME=\"127.0.0.1\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REMOTE_USER=\"crunch\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.7\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_events[5]=\"all\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_lease_duration[5]=\"86400\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_recipient_uri[5]=\"dbus://\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_recipient_name[5]=\"/\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_subscriber_user_name[5]=\"anonymous\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_time_interval[5]=\"0\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetArray: notify_subscription_id[5]=\"194\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: TITLE=\"Administration\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: SERVER_NAME=\"127.0.0.1\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: REMOTE_USER=\"crunch\"
D [09/Feb/2019:13:31:17 +0000] [CGI] cgiSetVariable: CUPS_VERSION=\"CUPS v2.2.7\"
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=2147483647, response=(nil)(), pipe_pid=2647, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] Script header: Content-Type: text/html;charset=utf-8
D [09/Feb/2019:13:31:17 +0000] [Client 4] Script header:
D [09/Feb/2019:13:31:17 +0000] [Client 4] Sending status 200 for CGI.
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdSendHeader: code=200, type="(null)", auth_type=0
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=2647, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] CGI data ready to be sent.
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=2647, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=2647, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] CGI data ready to be sent.
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=2647, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=2647, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] CGI data ready to be sent.
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=2647, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=2647, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] CGI data ready to be sent.
D [09/Feb/2019:13:31:17 +0000] [Client 4] con->http=0x80a5b0
D [09/Feb/2019:13:31:17 +0000] [Client 4] cupsdWriteClient error=0, used=0, state=HTTP_STATE_GET_SEND, data_encoding=HTTP_ENCODING_CHUNKED, data_remaining=0, response=(nil)(), pipe_pid=2647, file=19
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for CGI data.
D [09/Feb/2019:13:31:17 +0000] [Client 4] Sending 0-length chunk.
D [09/Feb/2019:13:31:17 +0000] [Client 4] Flushing write buffer.
D [09/Feb/2019:13:31:17 +0000] [Client 4] New state is HTTP_STATE_WAITING
D [09/Feb/2019:13:31:17 +0000] [Client 4] Waiting for request.
D [09/Feb/2019:13:31:17 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [09/Feb/2019:13:31:18 +0000] [Client 4] GET /cups.css HTTP/1.1
D [09/Feb/2019:13:31:18 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:18 +0000] [Client 4] Read: status=200, state=3
D [09/Feb/2019:13:31:18 +0000] [Client 4] Authorized as "crunch" using Basic.
D [09/Feb/2019:13:31:18 +0000] [Client 4] Processing GET /cups.css
D [09/Feb/2019:13:31:18 +0000] [Client 4] filename="/usr/share/cups/doc-root/cups.css", type=text/css
D [09/Feb/2019:13:31:18 +0000] [Client 4] cupsdSendHeader: code=304, type="(null)", auth_type=0
D [09/Feb/2019:13:31:18 +0000] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
I [09/Feb/2019:13:31:18 +0000] Expiring subscriptions...
I [09/Feb/2019:13:31:19 +0000] Expiring subscriptions...
D [09/Feb/2019:13:31:23 +0000] [Client 4] GET /admin/log/error_log HTTP/1.1
D [09/Feb/2019:13:31:23 +0000] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [09/Feb/2019:13:31:23 +0000] [Client 4] Read: status=200, state=3
D [09/Feb/2019:13:31:23 +0000] [Client 4] Authorized as "crunch" using Basic.
D [09/Feb/2019:13:31:23 +0000] cupsdIsAuthorized: username="crunch"
D [09/Feb/2019:13:31:23 +0000] [Client 4] Processing GET /admin/log/error_log

brian_p
Level 3
Level 3
Posts: 157
Joined: Thu Jan 17, 2019 9:20 am

Re: No print output when set to CMYK

Post by brian_p » Sat Feb 09, 2019 12:15 pm

crunch@crunch-Extensa-5235:~$ sudo cupsfilter -p /etc/cups/ppd/mg2500.ppd -m printer/foo -e /etc/adjtime > output.dat 2>log
[sudo] password for crunch:
Segmentation fault
A segmentation fault is not good; I am not going there. So, here is what I would do. Basically, it goes right back to the begining and is something we both know we have done in step with each other.
  • Get the URI for the print queue from

    Code: Select all

    lpinfo -v
    
    It begins with usb://
  • Get the PPD for the print queue with

    Code: Select all

    lpinfo -m | grep -i mg2500
    I have done that for you in the final step but you should check it is correct.
  • Now set up a queue called testq:

    Code: Select all

    lpadmin -p testq -v URI -E -m gutenprint.5.2://bjc-MG2500-series/expert 
    URI is what you get in the first step.
  • sudo should not be needed for any of the above three steps.
  • When you have done this please do not alter anything from a GUI or edit the PPD. Do nothing except print.
  • Print this:

    Code: Select all

    lp -d testq /etc/nsswitch.conf
  • Now print any file of your choice using an application of your choice
--
Brian.

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Mon Feb 11, 2019 10:13 am

Hi Brian. Just to let you know that I suspect a foul update for the whole problem. I will get back to you after doing what you said.
The password issue has also miraculously repaired itself after an update, beforehand when I tried to type my password in terminal the cursor did not move at all, now I am getting a line of asterisks as should happen. I must say that all these problems arose originally after an update about 7 weeks ago.

till later

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Mon Feb 11, 2019 3:21 pm

Just a quicky
Using the GUI I navigated to usr/share/cupsfilters and found NO ppd. file for the mg2500 series, just fuji,HP, ricoh and a couple of others not related to canon. This explains why all previous attempts to access this had failed. I had read somewhere about ppd. files being created on the fly? but that doesn't quite sound right to me...

brian_p
Level 3
Level 3
Posts: 157
Joined: Thu Jan 17, 2019 9:20 am

Re: No print output when set to CMYK

Post by brian_p » Mon Feb 11, 2019 3:44 pm

usr/share/cupsfilters or /usr/share/cupsfilters does not exist. In addition, you have not reported the outcome of the extensive advice I gave. Did you actually do any of it?
--
Brian.

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Mon Feb 11, 2019 4:51 pm

Yes I did and the whole bash output looks like this;

crunch@crunch-Extensa-5235:~$ lpinfo -v
network ipps
file cups-brf:/
network beh
network ipp
network lpd
network socket
network http
network https
direct hp
direct usb://Canon/MG2500%20series?serial=6D4289&interface=1
direct hpfax
crunch@crunch-Extensa-5235:~$ lpinfo -m | grep -i mg2500
gutenprint.5.2://bjc-MG2500-series/expert Canon MG2500 series - CUPS+Gutenprint v5.2.13
crunch@crunch-Extensa-5235:~$ lpadmin -p testq -v usb://Canon/MG2500%20series?serial=6D4289&interface=1 -E -m gutenprint.5.2://bjc-MG2500-series/expert
[1] 2955
-E: command not found
[1]+ Done lpadmin -p testq -v usb://Canon/MG2500%20series?serial=6D4289
crunch@crunch-Extensa-5235:~$ lp -d testq /etc/nsswitch.conf
lp: Destination "testq" is not accepting jobs.
crunch@crunch-Extensa-5235:~$


I came back home tonight before I repeated your advice (I had tried it this afternoon with the same result); tried a test page through the printer starting at ........ and copied the log from that exact moment. It is saying this;
E [11/Feb/2019:19:12:07 +0000] Unknown directive JobPrivateAccess on line 123 of /etc/cups/cupsd.conf.
E [11/Feb/2019:19:12:08 +0000] Unknown directive JobPrivateValues on line 124 of /etc/cups/cupsd.conf.
E [11/Feb/2019:19:12:08 +0000] Unknown directive SubscriptionPrivateAccess on line 125 of /etc/cups/cupsd.conf.
E [11/Feb/2019:19:12:08 +0000] Unknown directive SubscriptionPrivateValues on line 126 of /etc/cups/cupsd.conf.
E [11/Feb/2019:19:38:43 +0000] [cups-deviced] PID 2848 (gutenprint52+usb) stopped with status 1!

I cancelled the printing after leaving it for some time. I am aware that this sounds too short to be a proper log but this is really it from the exact timestamp.
I installed gedit to have a look at that cupsd.conf file.

brian_p
Level 3
Level 3
Posts: 157
Joined: Thu Jan 17, 2019 9:20 am

Re: No print output when set to CMYK

Post by brian_p » Mon Feb 11, 2019 8:07 pm

Please try with quotes round the URI:

Code: Select all

lpadmin -p testq -v "usb://Canon/MG2500%20series?serial=6D4289&interface=1" -E -m gutenprint.5.2://bjc-MG2500-series/expert
--
Brian.

Keldorum
Level 1
Level 1
Posts: 14
Joined: Wed Feb 06, 2019 8:47 am

Re: No print output when set to CMYK

Post by Keldorum » Mon Feb 11, 2019 8:25 pm

pasted the code into terminal; nuffing. Not a sossidge. Took a few steps back and pasted THIS in to terminal and hit enter *
lp -d testq /etc/nsswitch.conf

and the printer spat out a sheet of paper with /etc/nsswitch.conf as a heading!!!

I took a look in the printer settings menu and I now also have a network printer installed as well as testq, which has called itself Canon MG2500_series_crunch_Extensa_5235

Result of /etc/nsswitch.conf paper printout

passwd: compat systemd
group: compat systemd
shadow: compat
gshadow: files

hosts: files mdns4_minimal [NOTFOUND=return] dns myhostname
networks: files

protocols: db files
services: db files
ethers: db files
rpc: db files

netgroup: nis


This must be making you ill. I am going to dig out an old windows machine to install a driver on it to make sure that the printer itself hasn't caught a cold. When in doubt, try another OS to see if its a common issue, thus eliminating certain possibilities.

brian_p
Level 3
Level 3
Posts: 157
Joined: Thu Jan 17, 2019 9:20 am

Re: No print output when set to CMYK

Post by brian_p » Tue Feb 12, 2019 6:38 am

Keldorum wrote:
Mon Feb 11, 2019 8:25 pm
pasted the code into terminal; nuffing. Not a sossidge. Took a few steps back and pasted THIS in to terminal and hit enter *
lp -d testq /etc/nsswitch.conf
No output from the lpadmin command is good; it only gives one when there is an error, like you had before. In any case, nsswitch.conf printed correctly. We both know you now have a working queue for a USB printer.
I took a look in the printer settings menu and I now also have a network printer installed as well as testq, which has called itself Canon MG2500_series_crunch_Extensa_5235
How did you get this? Surely the MG2500 has only a USB interface?
This must be making you ill. I am going to dig out an old windows machine to install a driver on it to make sure that the printer itself hasn't caught a cold. When in doubt, try another OS to see if its a common issue, thus eliminating certain possibilities.
You've done well up to here. You can now go back to your RGB/CMYK issue, confident that you have a working queue. BTW, I would do a search on "gutenprint cmyk" to get the views of Gutenprint maintainers and others on the topic.
--
Brian.

Post Reply

Return to “Printers & Scanners”