You are not logged in.

#1 2013-05-09 10:09:17

Jindur
Member
Registered: 2011-09-29
Posts: 184

CUPS error_log shows colourmanager problems

I installed a Canon network printer LBP5050n in 3 different ways, and at least 2 "seem" to work, of which one is THE way it should be configured according to the manufacturer. I can send an order to calibrate just fine and the printer will start calibrating, and it says "idle" or "sleeping" and that it accepts jobs. I can also configure all printing options. So communication with the printer basically works.
But when I try to print test page, self-test page, or print anything, it will just stay silent (green LED on as usual), and the job disappears after a short delay as if it was completed.
--NOPE: as opposed to yesterday, now the print job actually stays and does not disappear. Don't ask me why though.

error_log after 'systemctl restart cups' shows some AddProfile failed/colour manager stuff:

I [09/May/2013:11:46:52 +0200] Scheduler shutting down normally.
D [09/May/2013:11:46:52 +0200] Discarding unused server-stopped event...
I [09/May/2013:11:46:52 +0200] Saving job.cache...
I [09/May/2013:11:46:52 +0200] Listening to [v1.::1]:631 (IPv6)
I [09/May/2013:11:46:52 +0200] Listening to 127.0.0.1:631 (IPv4)
I [09/May/2013:11:46:52 +0200] Listening to /var/run/cups/cups.sock (Domain)
I [09/May/2013:11:46:52 +0200] Remote access is disabled.
D [09/May/2013:11:46:52 +0200] Added auto ServerAlias localhost
I [09/May/2013:11:46:52 +0200] Loaded configuration file "/etc/cups/cupsd.conf"
I [09/May/2013:11:46:52 +0200] Using default TempDir of /var/spool/cups/tmp...
I [09/May/2013:11:46:52 +0200] Configured for up to 100 clients.
I [09/May/2013:11:46:52 +0200] Allowing up to 100 client connections per host.
I [09/May/2013:11:46:52 +0200] Using policy "default" as the default.
I [09/May/2013:11:46:52 +0200] Full reload is required.
I [09/May/2013:11:46:52 +0200] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 39 types, 52 filters...
D [09/May/2013:11:46:52 +0200] Loading printer Canon_LBP5050_1.01...
D [09/May/2013:11:46:52 +0200] load_ppd: Loading /var/cache/cups/Canon_LBP5050_1.01.data...
D [09/May/2013:11:46:52 +0200] cupsdRegisterPrinter(p=0x7f86534b8160(Canon_LBP5050_1.01))
D [09/May/2013:11:46:52 +0200] load_ppd: Loading /var/cache/cups/Canon_LBP5050_1.01.data...
D [09/May/2013:11:46:52 +0200] cupsdRegisterPrinter(p=0x7f86534b8160(Canon_LBP5050_1.01))
D [09/May/2013:11:46:52 +0200] Loading printer LBP5050n...
D [09/May/2013:11:46:52 +0200] load_ppd: Loading /var/cache/cups/LBP5050n.data...
D [09/May/2013:11:46:52 +0200] cupsdRegisterPrinter(p=0x7f86534ccd60(LBP5050n))
D [09/May/2013:11:46:52 +0200] Loading printer LBP5050x...
D [09/May/2013:11:46:52 +0200] load_ppd: Loading /var/cache/cups/LBP5050x.data...
D [09/May/2013:11:46:52 +0200] cupsdRegisterPrinter(p=0x7f86535207b0(LBP5050x))
I [09/May/2013:11:46:52 +0200] Loading job cache file "/var/cache/cups/job.cache"...
D [09/May/2013:11:46:52 +0200] [Job 18] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 19] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 20] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 21] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 22] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 22] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 23] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 24] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 25] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 26] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 27] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 28] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 29] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 30] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 31] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 32] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 33] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 34] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 35] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 36] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 37] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 38] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 39] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 40] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 41] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 42] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 43] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 44] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 45] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 46] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 47] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 48] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 49] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 50] Loading from cache...
D [09/May/2013:11:46:52 +0200] [Job 51] Loading from cache...
I [09/May/2013:11:46:52 +0200] Full reload complete.
D [09/May/2013:11:46:52 +0200] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)")
I [09/May/2013:11:46:52 +0200] Cleaning out old files in "/var/spool/cups/tmp"...
D [09/May/2013:11:46:52 +0200] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp")
I [09/May/2013:11:46:52 +0200] Cleaning out old files in "/var/cache/cups"...
D [09/May/2013:11:46:52 +0200] systemd_checkin: Matched existing listener /var/run/cups/cups.sock with fd 3...
D [09/May/2013:11:46:52 +0200] Calling FindDeviceById(cups-Canon_LBP5050_1.01)
D [09/May/2013:11:46:52 +0200] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id 'cups-Canon_LBP5050_1.01' does not exists
D [09/May/2013:11:46:52 +0200] Using profile ID "Canon_LBP5050_1.01-Gray..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(Canon_LBP5050_1.01-Gray..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/Canon_LBP5050_1_01_Gray__".
D [09/May/2013:11:46:52 +0200] Using profile ID "Canon_LBP5050_1.01-RGB..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(Canon_LBP5050_1.01-RGB..,temp)
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(Canon_LBP5050_1.01-RGB..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/Canon_LBP5050_1_01_RGB__".
I [09/May/2013:11:46:52 +0200] Registering ICC color profiles for "Canon_LBP5050_1.01".
D [09/May/2013:11:46:52 +0200] Calling CreateDevice(cups-Canon_LBP5050_1.01,temp)
D [09/May/2013:11:46:52 +0200] Created device "/org/freedesktop/ColorManager/devices/cups_Canon_LBP5050_1_01".
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_Canon_LBP5050_1_01:AddProfile(/org/freedesktop/ColorManager/profiles/Canon_LBP5050_1_01_Gray__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_Canon_LBP5
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_Canon_LBP5050_1_01:AddProfile(/org/freedesktop/ColorManager/profiles/Canon_LBP5050_1_01_RGB__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_Canon_LBP5
D [09/May/2013:11:46:52 +0200] Calling FindDeviceById(cups-LBP5050n)
D [09/May/2013:11:46:52 +0200] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id 'cups-LBP5050n' does not exists
D [09/May/2013:11:46:52 +0200] Using profile ID "LBP5050n-Gray..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(LBP5050n-Gray..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/LBP5050n_Gray__".
D [09/May/2013:11:46:52 +0200] Using profile ID "LBP5050n-RGB..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(LBP5050n-RGB..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/LBP5050n_RGB__".
I [09/May/2013:11:46:52 +0200] Registering ICC color profiles for "LBP5050n".
D [09/May/2013:11:46:52 +0200] Calling CreateDevice(cups-LBP5050n,temp)
D [09/May/2013:11:46:52 +0200] Created device "/org/freedesktop/ColorManager/devices/cups_LBP5050n".
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_LBP5050n:AddProfile(/org/freedesktop/ColorManager/profiles/LBP5050n_Gray__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_LBP5050n
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_LBP5050n:AddProfile(/org/freedesktop/ColorManager/profiles/LBP5050n_RGB__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_LBP5050n
D [09/May/2013:11:46:52 +0200] Calling FindDeviceById(cups-LBP5050x)
D [09/May/2013:11:46:52 +0200] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id 'cups-LBP5050x' does not exists
D [09/May/2013:11:46:52 +0200] Using profile ID "LBP5050x-Gray..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(LBP5050x-Gray..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/LBP5050x_Gray__".
D [09/May/2013:11:46:52 +0200] Using profile ID "LBP5050x-RGB..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(LBP5050x-RGB..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/LBP5050x_RGB__".
I [09/May/2013:11:46:52 +0200] Registering ICC color profiles for "LBP5050x".
D [09/May/2013:11:46:52 +0200] Calling CreateDevice(cups-LBP5050x,temp)
D [09/May/2013:11:46:52 +0200] Created device "/org/freedesktop/ColorManager/devices/cups_LBP5050x".
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_LBP5050x:AddProfile(/org/freedesktop/ColorManager/profiles/LBP5050x_Gray__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_LBP5050x
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_LBP5050x:AddProfile(/org/freedesktop/ColorManager/profiles/LBP5050x_RGB__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_LBP5050x
I [09/May/2013:11:46:52 +0200] Listening to [v1.::1]:631 on fd 10...
I [09/May/2013:11:46:52 +0200] Listening to 127.0.0.1:631 on fd 11...
I [09/May/2013:11:46:52 +0200] Listening to /var/run/cups/cups.sock:631 on fd 3...
I [09/May/2013:11:46:52 +0200] Resuming new connection processing...
D [09/May/2013:11:46:52 +0200] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id 'cups-LBP5050n' does not exists
D [09/May/2013:11:46:52 +0200] Using profile ID "LBP5050n-Gray..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(LBP5050n-Gray..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/LBP5050n_Gray__".
D [09/May/2013:11:46:52 +0200] Using profile ID "LBP5050n-RGB..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(LBP5050n-RGB..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/LBP5050n_RGB__".
I [09/May/2013:11:46:52 +0200] Registering ICC color profiles for "LBP5050n".
D [09/May/2013:11:46:52 +0200] Calling CreateDevice(cups-LBP5050n,temp)
D [09/May/2013:11:46:52 +0200] Created device "/org/freedesktop/ColorManager/devices/cups_LBP5050n".
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_LBP5050n:AddProfile(/org/freedesktop/ColorManager/profiles/LBP5050n_Gray__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_LBP5050n
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_LBP5050n:AddProfile(/org/freedesktop/ColorManager/profiles/LBP5050n_RGB__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_LBP5050n
D [09/May/2013:11:46:52 +0200] Calling FindDeviceById(cups-LBP5050x)
D [09/May/2013:11:46:52 +0200] FindDeviceById failed: org.freedesktop.ColorManager.NotFound:device id 'cups-LBP5050x' does not exists
D [09/May/2013:11:46:52 +0200] Using profile ID "LBP5050x-Gray..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(LBP5050x-Gray..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/LBP5050x_Gray__".
D [09/May/2013:11:46:52 +0200] Using profile ID "LBP5050x-RGB..".
D [09/May/2013:11:46:52 +0200] Calling CreateProfile(LBP5050x-RGB..,temp)
D [09/May/2013:11:46:52 +0200] Created profile "/org/freedesktop/ColorManager/profiles/LBP5050x_RGB__".
I [09/May/2013:11:46:52 +0200] Registering ICC color profiles for "LBP5050x".
D [09/May/2013:11:46:52 +0200] Calling CreateDevice(cups-LBP5050x,temp)
D [09/May/2013:11:46:52 +0200] Created device "/org/freedesktop/ColorManager/devices/cups_LBP5050x".
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_LBP5050x:AddProfile(/org/freedesktop/ColorManager/profiles/LBP5050x_Gray__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_LBP5050x
D [09/May/2013:11:46:52 +0200] Calling /org/freedesktop/ColorManager/devices/cups_LBP5050x:AddProfile(/org/freedesktop/ColorManager/profiles/LBP5050x_RGB__) [soft]
W [09/May/2013:11:46:52 +0200] AddProfile failed: org.freedesktop.DBus.Error.UnknownMethod:No such interface `org.freedesktop.ColorManager' on object at path /org/freedesktop/ColorManager/devices/cups_LBP5050x
I [09/May/2013:11:46:52 +0200] Listening to [v1.::1]:631 on fd 10...
I [09/May/2013:11:46:52 +0200] Listening to 127.0.0.1:631 on fd 11...
I [09/May/2013:11:46:52 +0200] Listening to /var/run/cups/cups.sock:631 on fd 3...
I [09/May/2013:11:46:52 +0200] Resuming new connection processing...
D [09/May/2013:11:46:52 +0200] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [09/May/2013:11:46:52 +0200] Discarding unused server-started event...
D [09/May/2013:11:46:53 +0200] Report: clients=0
D [09/May/2013:11:46:53 +0200] Report: jobs=34
D [09/May/2013:11:46:53 +0200] Report: jobs-active=0
D [09/May/2013:11:46:53 +0200] Report: printers=3
D [09/May/2013:11:46:53 +0200] Report: stringpool-string-count=11703
D [09/May/2013:11:46:53 +0200] Report: stringpool-alloc-bytes=9640
D [09/May/2013:11:46:53 +0200] Report: stringpool-total-bytes=215296

and error_log when trying to print self-test page:
(cups says "Printer command job completed")

D [09/May/2013:12:03:26 +0200] [Client 14] Accepted from localhost:631 (IPv4)
D [09/May/2013:12:03:26 +0200] Report: clients=1
D [09/May/2013:12:03:26 +0200] Report: jobs=36
D [09/May/2013:12:03:26 +0200] Report: jobs-active=0
D [09/May/2013:12:03:26 +0200] Report: printers=3
D [09/May/2013:12:03:26 +0200] Report: stringpool-string-count=11708
D [09/May/2013:12:03:26 +0200] Report: stringpool-alloc-bytes=9680
D [09/May/2013:12:03:26 +0200] Report: stringpool-total-bytes=215376
D [09/May/2013:12:03:26 +0200] [Client 14] POST /printers/LBP5050n HTTP/1.1
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [09/May/2013:12:03:26 +0200] [Client 14] Authorized as root using Basic
D [09/May/2013:12:03:26 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"
D [09/May/2013:12:03:26 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [09/May/2013:12:03:26 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [09/May/2013:12:03:26 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [09/May/2013:12:03:26 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [09/May/2013:12:03:26 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [09/May/2013:12:03:26 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [09/May/2013:12:03:26 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [09/May/2013:12:03:26 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups"
D [09/May/2013:12:03:26 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [09/May/2013:12:03:26 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [09/May/2013:12:03:26 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@localhost"
D [09/May/2013:12:03:26 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/1.6.2"
D [09/May/2013:12:03:26 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [09/May/2013:12:03:26 +0200] [CGI] envp[13] = "USER=root"
D [09/May/2013:12:03:26 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [09/May/2013:12:03:26 +0200] [CGI] envp[15] = "CUPS_SERVER=/var/run/cups/cups.sock"
D [09/May/2013:12:03:26 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [09/May/2013:12:03:26 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [09/May/2013:12:03:26 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [09/May/2013:12:03:26 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [09/May/2013:12:03:26 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [09/May/2013:12:03:26 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [09/May/2013:12:03:26 +0200] [CGI] envp[22] = "SERVER_NAME=127.0.0.1"
D [09/May/2013:12:03:26 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [09/May/2013:12:03:26 +0200] [CGI] envp[24] = "REMOTE_ADDR=127.0.0.1"
D [09/May/2013:12:03:26 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [09/May/2013:12:03:26 +0200] [CGI] envp[26] = "SCRIPT_NAME=/printers/LBP5050n"
D [09/May/2013:12:03:26 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/LBP5050n"
D [09/May/2013:12:03:26 +0200] [CGI] envp[28] = "PATH_INFO=/LBP5050n"
D [09/May/2013:12:03:26 +0200] [CGI] envp[29] = "REMOTE_USER=root"
D [09/May/2013:12:03:26 +0200] [CGI] envp[30] = "SERVER_PROTOCOL=HTTP/1.1"
D [09/May/2013:12:03:26 +0200] [CGI] envp[31] = "HTTP_COOKIE=org.cups.sid=b91e676f5dd19450485609b086d50326"
D [09/May/2013:12:03:26 +0200] [CGI] envp[32] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:20.0) Gecko/20100101 Firefox/20.0"
D [09/May/2013:12:03:26 +0200] [CGI] envp[33] = "HTTP_REFERER=http://127.0.0.1:631/printers/LBP5050n"
D [09/May/2013:12:03:26 +0200] [CGI] envp[34] = "REQUEST_METHOD=POST"
D [09/May/2013:12:03:26 +0200] [CGI] envp[35] = "CONTENT_LENGTH=69"
D [09/May/2013:12:03:26 +0200] [CGI] envp[36] = "CONTENT_TYPE=application/x-www-form-urlencoded"
D [09/May/2013:12:03:26 +0200] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 16412)
I [09/May/2013:12:03:26 +0200] [Client 14] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=16412)
D [09/May/2013:12:03:26 +0200] [Client 14] file=16
D [09/May/2013:12:03:26 +0200] [CGI] org.cups.sid cookie is "b91e676f5dd19450485609b086d50326"
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: org.cups.sid="b91e676f5dd19450485609b086d50326"
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: OP="print-self-test-page"
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: SECTION="printers"
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=""
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: PRINTER_NAME="LBP5050n"
D [09/May/2013:12:03:26 +0200] [Client 15] Accepted from localhost (Domain)
D [09/May/2013:12:03:26 +0200] [Client 15] POST /printers/LBP5050n HTTP/1.1
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients", busy="Active clients"
D [09/May/2013:12:03:26 +0200] [Client 15] No authentication data provided.
D [09/May/2013:12:03:26 +0200] [Client 15] 2.0 Create-Job 1
D [09/May/2013:12:03:26 +0200] Create-Job ipp://localhost:631/printers/LBP5050n
D [09/May/2013:12:03:26 +0200] cupsdMarkDirty(---J-)
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [09/May/2013:12:03:26 +0200] add_job: requesting-user-name="root"
D [09/May/2013:12:03:26 +0200] Adding default job-sheets values "none,none"...
I [09/May/2013:12:03:26 +0200] [Job 54] Adding start banner page "none".
D [09/May/2013:12:03:26 +0200] Discarding unused job-created event...
I [09/May/2013:12:03:26 +0200] [Job 54] Queued on "LBP5050n" by "root".
D [09/May/2013:12:03:26 +0200] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/LBP5050n) from localhost
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/May/2013:12:03:26 +0200] [Client 15] POST /printers/LBP5050n HTTP/1.1
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/May/2013:12:03:26 +0200] [Client 15] No authentication data provided.
D [09/May/2013:12:03:26 +0200] [Client 15] 2.0 Send-Document 2
D [09/May/2013:12:03:26 +0200] Send-Document ipp://localhost:631/printers/LBP5050n
D [09/May/2013:12:03:26 +0200] cupsdIsAuthorized: requesting-user-name="root"
D [09/May/2013:12:03:26 +0200] cupsdMarkDirty(---J-)
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [09/May/2013:12:03:26 +0200] [Job 54] File of type application/vnd.cups-command queued by "root".
I [09/May/2013:12:03:26 +0200] [Job 54] Adding end banner page "none".
D [09/May/2013:12:03:26 +0200] cupsdMarkDirty(---J-)
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/May/2013:12:03:26 +0200] [Job 54] time-at-processing=1368093806
D [09/May/2013:12:03:26 +0200] cupsdMarkDirty(---J-)
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [09/May/2013:12:03:26 +0200] Discarding unused printer-state-changed event...
D [09/May/2013:12:03:26 +0200] [Job 54] job-sheets=none,none
D [09/May/2013:12:03:26 +0200] [Job 54] argv[0]="LBP5050n"
D [09/May/2013:12:03:26 +0200] [Job 54] argv[1]="54"
D [09/May/2013:12:03:26 +0200] [Job 54] argv[2]="root"
D [09/May/2013:12:03:26 +0200] [Job 54] argv[3]="Print Self-Test Page"
D [09/May/2013:12:03:26 +0200] [Job 54] argv[4]="1"
D [09/May/2013:12:03:26 +0200] [Job 54] argv[5]="job-uuid=urn:uuid:19b0234c-ab9a-33fd-4d6c-fc73efaa8ed3 job-originating-host-name=localhost time-at-creation=1368093806 time-at-processing=1368093806"
D [09/May/2013:12:03:26 +0200] [Job 54] argv[6]="/var/spool/cups/d00054-001"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[8]="HOME=/var/spool/cups/tmp"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[10]="SERVER_ADMIN=root@localhost"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[11]="SOFTWARE=CUPS/1.6.2"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[13]="USER=root"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[14]="CUPS_MAX_MESSAGE=2047"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[15]="CUPS_SERVER=/var/run/cups/cups.sock"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[17]="IPP_PORT=631"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[18]="CHARSET=utf-8"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[19]="LANG=en_US.UTF-8"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[20]="PPD=/etc/cups/ppd/LBP5050n.ppd"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[21]="RIP_MAX_CACHE=128m"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[22]="CONTENT_TYPE=application/vnd.cups-command"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[23]="DEVICE_URI=ccp://localhost:59687"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[24]="PRINTER_INFO=LBP5050n"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[25]="PRINTER_LOCATION="
D [09/May/2013:12:03:26 +0200] [Job 54] envp[26]="PRINTER=LBP5050n"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[27]="PRINTER_STATE_REASONS=none"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[28]="CUPS_FILETYPE=document"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[29]="FINAL_CONTENT_TYPE=application/postscript"
D [09/May/2013:12:03:26 +0200] [Job 54] envp[30]="AUTH_I****"
I [09/May/2013:12:03:26 +0200] [Job 54] Started filter /usr/lib/cups/filter/commandtops (PID 16413)
I [09/May/2013:12:03:26 +0200] [Job 54] Started backend /usr/lib/cups/backend/ccp (PID 16414)
D [09/May/2013:12:03:26 +0200] Discarding unused job-state-changed event...
D [09/May/2013:12:03:26 +0200] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/LBP5050n) from localhost
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients and dirty files"
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: refresh_page="5;URL=/printers/LBP5050n"
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: TITLE="Print Self-Test Page"
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: SERVER_NAME="127.0.0.1"
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: REMOTE_USER="root"
D [09/May/2013:12:03:26 +0200] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.6.2"
D [09/May/2013:12:03:26 +0200] Script header: Content-Type: text/html;charset=utf-8
D [09/May/2013:12:03:26 +0200] Script header:.
D [09/May/2013:12:03:26 +0200] [Client 15] HTTP_WAITING Closing on EOF
D [09/May/2013:12:03:26 +0200] [Client 15] Closing connection.
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:26 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:26 +0200] PID 16412 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [09/May/2013:12:03:26 +0200] [Job 54] PID 16413 (/usr/lib/cups/filter/commandtops) exited with no errors.
D [09/May/2013:12:03:31 +0200] [Client 14] GET /printers/LBP5050n HTTP/1.1
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
 D [09/May/2013:12:03:31 +0200] [Client 14] Authorized as root using Basic
D [09/May/2013:12:03:31 +0200] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"
D [09/May/2013:12:03:31 +0200] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [09/May/2013:12:03:31 +0200] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [09/May/2013:12:03:31 +0200] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc"
D [09/May/2013:12:03:31 +0200] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [09/May/2013:12:03:31 +0200] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [09/May/2013:12:03:31 +0200] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [09/May/2013:12:03:31 +0200] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [09/May/2013:12:03:31 +0200] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups"
D [09/May/2013:12:03:31 +0200] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [09/May/2013:12:03:31 +0200] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [09/May/2013:12:03:31 +0200] [CGI] envp[10] = "SERVER_ADMIN=root@localhost"
D [09/May/2013:12:03:31 +0200] [CGI] envp[11] = "SOFTWARE=CUPS/1.6.2"
D [09/May/2013:12:03:31 +0200] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [09/May/2013:12:03:31 +0200] [CGI] envp[13] = "USER=root"
D [09/May/2013:12:03:31 +0200] [CGI] envp[14] = "CUPS_MAX_MESSAGE=2047"
D [09/May/2013:12:03:31 +0200] [CGI] envp[15] = "CUPS_SERVER=/var/run/cups/cups.sock"
D [09/May/2013:12:03:31 +0200] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [09/May/2013:12:03:31 +0200] [CGI] envp[17] = "IPP_PORT=631"
D [09/May/2013:12:03:31 +0200] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [09/May/2013:12:03:31 +0200] [CGI] envp[19] = "LANG=en_US.UTF8"
D [09/May/2013:12:03:31 +0200] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [09/May/2013:12:03:31 +0200] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [09/May/2013:12:03:31 +0200] [CGI] envp[22] = "SERVER_NAME=127.0.0.1"
D [09/May/2013:12:03:31 +0200] [CGI] envp[23] = "SERVER_PORT=631"
D [09/May/2013:12:03:31 +0200] [CGI] envp[24] = "REMOTE_ADDR=127.0.0.1"
D [09/May/2013:12:03:31 +0200] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [09/May/2013:12:03:31 +0200] [CGI] envp[26] = "SCRIPT_NAME=/printers/LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc/printers/LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] envp[28] = "PATH_INFO=/LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] envp[29] = "REMOTE_USER=root"
D [09/May/2013:12:03:31 +0200] [CGI] envp[30] = "SERVER_PROTOCOL=HTTP/1.1"
D [09/May/2013:12:03:31 +0200] [CGI] envp[31] = "HTTP_COOKIE=org.cups.sid=b91e676f5dd19450485609b086d50326"
D [09/May/2013:12:03:31 +0200] [CGI] envp[32] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux x86_64; rv:20.0) Gecko/20100101 Firefox/20.0"
D [09/May/2013:12:03:31 +0200] [CGI] envp[33] = "REQUEST_METHOD=GET"
D [09/May/2013:12:03:31 +0200] [CGI] envp[34] = "QUERY_STRING="
D [09/May/2013:12:03:31 +0200] [CGI] Started /usr/lib/cups/cgi-bin/printers.cgi (PID 16447)
I [09/May/2013:12:03:31 +0200] [Client 14] Started "/usr/lib/cups/cgi-bin/printers.cgi" (pid=16447)
D [09/May/2013:12:03:31 +0200] [Client 14] file=15
D [09/May/2013:12:03:31 +0200] [CGI] org.cups.sid cookie is "b91e676f5dd19450485609b086d50326"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: SECTION="printers"
 D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=""
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: PRINTER_NAME="LBP5050n"
D [09/May/2013:12:03:31 +0200] [Client 16] Accepted from localhost (Domain)
D [09/May/2013:12:03:31 +0200] [Client 16] POST / HTTP/1.1
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 16] No authentication data provided.
D [09/May/2013:12:03:31 +0200] [Client 16] 2.0 CUPS-Get-Default 1
D [09/May/2013:12:03:31 +0200] CUPS-Get-Default
D [09/May/2013:12:03:31 +0200] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: DEFAULT_NAME="LBP5050x"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: DEFAULT_URI="/printers/LBP5050x"
D [09/May/2013:12:03:31 +0200] [CGI] show_printer(http=0x7ff7bcbd5ba0, printer="LBP5050n")
D [09/May/2013:12:03:31 +0200] [Client 16] POST / HTTP/1.1
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 16] No authentication data provided.
D [09/May/2013:12:03:31 +0200] [Client 16] 2.0 Get-Printer-Attributes 2
D [09/May/2013:12:03:31 +0200] Get-Printer-Attributes ipp://localhost/printers/LBP5050n
D [09/May/2013:12:03:31 +0200] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/LBP5050n) from localhost
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: SERVER_NAME="127.0.0.1"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: REMOTE_USER="root"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.6.2"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: SERVER_NAME="127.0.0.1"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: REMOTE_USER="root"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.6.2"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: printer_is_accepting_jobs[0]="1"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: printer_is_shared[0]="0"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: printer_state[0]="4"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: admin_uri[0]="/admin/"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: printer_uri_supported[0]="/printers/LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: printer_name[0]="LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: printer_location[0]=""
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: printer_info[0]="LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: job_sheets_default[0]="none, none"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: device_uri[0]="ccp://localhost:59687"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: color_supported[0]="1"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: printer_make_and_model[0]="Canon LBP5050 CAPT (UK)"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: media_default[0]="iso_a4_210x297mm"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: sides_supported[0]="one-sided"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: sides_default[0]="one-sided"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: printer_commands[0]="AutoConfigure, Clean, PrintSelfTestPage"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: server_is_sharing_printers[0]="0"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: refresh_page="10;URL=/printers/LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: TITLE="LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: SERVER_NAME="127.0.0.1"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: REMOTE_USER="root"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.6.2"
D [09/May/2013:12:03:31 +0200] Script header: Content-Type: text/html;charset=utf-8
D [09/May/2013:12:03:31 +0200] Script header:.
D [09/May/2013:12:03:31 +0200] [CGI] Regular expression ".*Clean.*"
D [09/May/2013:12:03:31 +0200] [CGI] matches[0].rm_so=0
D [09/May/2013:12:03:31 +0200] [CGI] matches[1].rm_so=-1
D [09/May/2013:12:03:31 +0200] [CGI] Regular expression ".*PrintSelfTestPage.*"
D [09/May/2013:12:03:31 +0200] [CGI] matches[0].rm_so=0
D [09/May/2013:12:03:31 +0200] [CGI] matches[1].rm_so=-1
D [09/May/2013:12:03:31 +0200] [Client 16] POST / HTTP/1.1
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 16] No authentication data provided.
D [09/May/2013:12:03:31 +0200] [Client 16] 2.0 Get-Jobs 3
D [09/May/2013:12:03:31 +0200] Get-Jobs ipp://localhost:631/printers/LBP5050n
D [09/May/2013:12:03:31 +0200] Returning IPP successful-ok for Get-Jobs (ipp://localhost:631/printers/LBP5050n) from localhost
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [CGI] cgiClearVariables called.
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: ORDER="asc"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: SECTION="printers"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: TOTAL="1"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: SERVER_NAME="127.0.0.1"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: REMOTE_USER="root"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: CUPS_VERSION="CUPS v1.6.2"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: job_printer_name[0]="LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: job_printer_uri[0]="/printers/LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: time_at_creation[0]="Thu May  9 12:03:26 2013"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: time_at_processing[0]="Thu May  9 12:03:26 2013"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: time_at_completed[0]="novalue"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: job_id[0]="54"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: job_state[0]="5"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: job_media_sheets_completed[0]="0"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetArray: job_k_octets[0]="1"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: PRINTER_NAME="LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: PRINTER_URI_SUPPORTED="/printers/LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: THISURL="/printers/LBP5050n"
D [09/May/2013:12:03:31 +0200] [CGI] cgiSetVariable: SEARCH_DEST="LBP5050n"
D [09/May/2013:12:03:31 +0200] [Client 16] HTTP_WAITING Closing on EOF
D [09/May/2013:12:03:31 +0200] [Client 16] Closing connection.
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] PID 16447 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 14] GET /cups.css HTTP/1.1
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 14] Authorized as root using Basic
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 15] Accepted from localhost:631 (IPv4)
D [09/May/2013:12:03:31 +0200] [Client 16] Accepted from localhost:631 (IPv4)
D [09/May/2013:12:03:31 +0200] [Client 15] GET /images/left.gif HTTP/1.1
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 15] Authorized as root using Basic
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 18] Accepted from localhost:631 (IPv4)
D [09/May/2013:12:03:31 +0200] [Client 16] GET /images/right.gif HTTP/1.1
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 16] Authorized as root using Basic
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 14] GET /images/unsel.gif HTTP/1.1
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 14] Authorized as root using Basic
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [09/May/2013:12:03:31 +0200] [Client 18] GET /images/sel.gif HTTP/1.1
D [09/May/2013:12:03:31 +0200] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [09/May/2013:12:03:32 +0200] [Client 18] Authorized as root using Basic
D [09/May/2013:12:03:32 +0200] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"

and in CUPS it now says
"Can't connect to CCPD: Connection refused"
which is interesting because it didn't say that yesterday. (It "completed" the jobs and they disappeared, although nothing happened.)

If I used another instance of that printer added in CUPS, the one that actually used CUPS' autodetection, the job does disappear and no error happens (and the printer doesn't print, as usual).
Also, when I used that CUPS auto-detection, I had to manually do ccpdadmin to add it or there was some error message - is that normal, that CUPS only does half the work?

(I have worked through the CUPS wiki page and enabled debug log output, hence the D lines)

Last edited by Jindur (2013-05-09 11:03:11)

Offline

#2 2013-05-12 03:14:18

kenny3794
Member
Registered: 2013-05-04
Posts: 20

Re: CUPS error_log shows colourmanager problems

I had a similar problem with my printer (HP Deskjet F4200) and I browsed the forums for several hours each evening for 3 days to try and fix the problem.  I eventually succeeded... Hope some of what I went through elps.  In short, I did the following:

- installed system-config-printer
- installed libgnomeprint, libgnomecups, libgnomeprintui
- restarted and played with CUPS configurations including adding printer through every possible interface.  nothing worked.  I could only print a test page from the CUPS server itself (http://localhost:631)

- Uninstalled evreything hplip, print or cups related ignoring dependencies and then reinstalled.  I then installed the printer using the hp-setup utility but received some errors in cups logs about unable to find printer at the uri.  I did notice the color errors seemed gone, so I did more playing with the config files and uninstalled and reinstalled using system-config-printer, when I noticed the URI errors were gone.  Not sure what fixed it, but I believe running as ROOT helped.

- at this point, the printer would respond to test page from the hp-lip utility and print from the command line. However, the printer was ever absent from gnome applications. After more reading, I found some information from BSD forums about not using libgnomeprint for the print dialogs anymore (everyone uses GTK print instead). 
- I uninstalled libgnomeprint, libgnomeprintui, libgnomecups.
- I reinstalled GTK3 and GTK2 to ensure that the gtk print library files were up-to-date (gtk library print files are stored in /usr/lib/gtk-x.0/x.x0.0/printbackends/)

At this point, I suddenly had all of my applications showing my printer responding to my print requests.  Not sure if any of this will help, but I hope it does.

Offline

#3 2013-05-14 12:31:24

Jindur
Member
Registered: 2011-09-29
Posts: 184

Re: CUPS error_log shows colourmanager problems

I don't use Gnome, but I'll randomly try that stuff I guess.
Why is printing on Linux such a nightmare, even though there are drivers provided.

Ok, system-config-printer seems like a CUPS GUI? Basically offering exactly the same stuff.
I didn't try removing and reinstalling all printer-related software because I don't even know which packages exactly are involved apart from the obvious ones like cups and gutenprint.
Giving up on printing on Linux again for the time being I guess. I've been retrying every couple months, involving days of googling each.
Maybe Linux becomes more usable in that regard in a year or two if the devs actually focus more on getting printing to work (admitted: Canonical does, this stuff supposedly works np under Ubuntu, but I'm not an Ubuntu fan).

I think the main problem is the whole CUPS crap. It just doesn't work and is a chore to use/maintain.
For example it just now AGAIN "forgot" the admin password that I just reset 2 weeks ago, prompting me to auth when I want to delete a printer, and then refusing although I entered exactly the same, and of course working, values from 2 weeks ago when I already had to reset its password.
And not to speak of, if you ever click "cancel" in CUPS instead of terminating the webbrowser, it will just never prompt you again for auth but simply present you a "refused" screen right away until you log in as root and modify some CUPS config files in strange ways. That's unfortunately the current state of Linux printing - unusuable when not on Ubuntu (or possibly some other mainstream distro, not sure) or not having a lucky shot with your printer.

I already did some exchange with a maintainer of an AUR printer driver package, involving logs and cats on pastebin, which ended in "hm seems your settings and setup are exactly like mine, I don't know why it doesn't work, sorry". To all Linux devs: Please fix something as basic as printing, thanks!

Last edited by Jindur (2013-05-14 13:40:50)

Offline

#4 2013-05-14 14:08:48

kenny3794
Member
Registered: 2013-05-04
Posts: 20

Re: CUPS error_log shows colourmanager problems

I couldn't agree more.  I have been an Ubuntu user since 2009 and only last month switch to Arch (by way of Cinnarch, due to time constraints available for learning).  I was surprised by how difficult a few things have been since moving to Arch.  Printer setup was by far the most complicated!  It shouldn't be so hard, as is obvious by Ubuntu and Apple --- both of which use CUPS backend and work without headache.

Perhaps just a very smart install script is all that'd be required? One that knows exactly who needs to be setup where and would check all permissions and file existences.

Offline

Board footer

Powered by FluxBB