[Pkg-cups-devel] Bug#660420: Also affecting Brother HL-5240 PostScript

Nate Bargmann n0nb at n0nb.us
Thu Feb 23 22:53:45 UTC 2012 

Attached is a CUPS debug log of sending a page from Iceweasel to my
printer.  Interestingly enough, I tried to print the error log and all I
got was a single blank sheet ejected from the printer.  I am using the
PPD from the Foomatic package which is also attached.

- Nate >>

-- 

"The optimist proclaims that we live in the best of all
possible worlds.  The pessimist fears this is true."

Ham radio, Linux, bikes, and more: http://www.n0nb.us
-------------- next part --------------
I [23/Feb/2012:16:36:38 -0600] Remote access is disabled.
D [23/Feb/2012:16:36:38 -0600] Added auto ServerAlias merlin
I [23/Feb/2012:16:36:38 -0600] Loaded configuration file "/etc/cups/cupsd.conf"
I [23/Feb/2012:16:36:38 -0600] Using default TempDir of /var/spool/cups/tmp...
I [23/Feb/2012:16:36:38 -0600] Configured for up to 100 clients.
I [23/Feb/2012:16:36:38 -0600] Allowing up to 100 client connections per host.
I [23/Feb/2012:16:36:38 -0600] Using policy "default" as the default.
D [23/Feb/2012:16:36:38 -0600] load_ppd: Loading /var/cache/cups/Brother-HL-5240.data...
D [23/Feb/2012:16:36:38 -0600] Calling DeleteDevice(cups-Brother-HL-5240)
D [23/Feb/2012:16:36:38 -0600] failed to DeleteDevice: org.freedesktop.DBus.Error.InvalidArgs:Type of message, `(s)', does not match expected type `(o)'
D [23/Feb/2012:16:36:38 -0600] Using profile id of Brother-HL-5240-Gray..
D [23/Feb/2012:16:36:38 -0600] Calling CreateProfile(Brother-HL-5240-Gray..,temp)
W [23/Feb/2012:16:36:38 -0600] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'Brother-HL-5240-Gray..' already exists
I [23/Feb/2012:16:36:38 -0600] Registering ICC color profiles for "Brother-HL-5240"
D [23/Feb/2012:16:36:38 -0600] Calling CreateDevice(cups-Brother-HL-5240,temp)
W [23/Feb/2012:16:36:38 -0600] failed to CreateDevice: org.freedesktop.ColorManager.AlreadyExists:device id 'cups-Brother-HL-5240' already exists
D [23/Feb/2012:16:36:38 -0600] cupsdRegisterPrinter(p=0xb8aa0750(Brother-HL-5240))
D [23/Feb/2012:16:36:38 -0600] load_ppd: Loading /var/cache/cups/PDF.data...
D [23/Feb/2012:16:36:38 -0600] Calling DeleteDevice(cups-PDF)
D [23/Feb/2012:16:36:38 -0600] failed to DeleteDevice: org.freedesktop.DBus.Error.InvalidArgs:Type of message, `(s)', does not match expected type `(o)'
D [23/Feb/2012:16:36:38 -0600] Using profile id of PDF-Gray..
D [23/Feb/2012:16:36:38 -0600] Calling CreateProfile(PDF-Gray..,temp)
W [23/Feb/2012:16:36:38 -0600] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'PDF-Gray..' already exists
D [23/Feb/2012:16:36:38 -0600] Using profile id of PDF-RGB..
D [23/Feb/2012:16:36:38 -0600] Calling CreateProfile(PDF-RGB..,temp)
W [23/Feb/2012:16:36:38 -0600] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'PDF-RGB..' already exists
I [23/Feb/2012:16:36:38 -0600] Registering ICC color profiles for "PDF"
D [23/Feb/2012:16:36:38 -0600] Calling CreateDevice(cups-PDF,temp)
W [23/Feb/2012:16:36:38 -0600] failed to CreateDevice: org.freedesktop.ColorManager.AlreadyExists:device id 'cups-PDF' already exists
D [23/Feb/2012:16:36:38 -0600] cupsdRegisterPrinter(p=0xb8ae2398(PDF))
D [23/Feb/2012:16:36:38 -0600] cupsdMarkDirty(---p--)
D [23/Feb/2012:16:36:38 -0600] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy"
I [23/Feb/2012:16:36:38 -0600] Partial reload complete.
I [23/Feb/2012:16:36:38 -0600] Listening to [v1.::1]:631 on fd 6...
I [23/Feb/2012:16:36:38 -0600] Listening to 127.0.0.1:631 on fd 9...
I [23/Feb/2012:16:36:38 -0600] Listening to /var/run/cups/cups.sock:631 on fd 10...
I [23/Feb/2012:16:36:38 -0600] Resuming new connection processing...
D [23/Feb/2012:16:36:38 -0600] cupsdRegisterPrinter(p=0xb8aa0750(Brother-HL-5240))
D [23/Feb/2012:16:36:38 -0600] cupsdRegisterPrinter(p=0xb8ae2398(PDF))
D [23/Feb/2012:16:36:38 -0600] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [23/Feb/2012:16:36:38 -0600] Discarding unused server-restarted event...
D [23/Feb/2012:16:36:39 -0600] Report: clients=0
D [23/Feb/2012:16:36:39 -0600] Report: jobs=4
D [23/Feb/2012:16:36:39 -0600] Report: jobs-active=0
D [23/Feb/2012:16:36:39 -0600] Report: printers=2
D [23/Feb/2012:16:36:39 -0600] Report: printers-implicit=0
D [23/Feb/2012:16:36:39 -0600] Report: stringpool-string-count=1723
D [23/Feb/2012:16:36:39 -0600] Report: stringpool-alloc-bytes=11056
D [23/Feb/2012:16:36:39 -0600] Report: stringpool-total-bytes=31360
D [23/Feb/2012:16:36:43 -0600] cupsdAcceptClient: 15 from localhost:631 (IPv4)
D [23/Feb/2012:16:36:43 -0600] cupsdReadClient: 15 GET /admin/?OP=redirect HTTP/1.1
D [23/Feb/2012:16:36:43 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Feb/2012:16:36:43 -0600] cupsdAuthorize: Authorized as root using Basic
D [23/Feb/2012:16:36:43 -0600] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/admin.cgi"
D [23/Feb/2012:16:36:43 -0600] [CGI] argv[1] = "OP=redirect"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc-root"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[10] = "SERVER_ADMIN=root at merlin"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[11] = "SOFTWARE=CUPS/1.5.2"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[13] = "TZ=America/Chicago"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[14] = "USER=root"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[15] = "CUPS_SERVER=/var/run/cups/cups.sock"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[17] = "IPP_PORT=631"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[19] = "LANG=en_US.UTF8"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[22] = "SERVER_NAME=localhost"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[23] = "SERVER_PORT=631"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[24] = "REMOTE_ADDR=127.0.0.1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[26] = "SCRIPT_NAME=/admin/"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc-root/admin/"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[28] = "REMOTE_USER=root"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[29] = "SERVER_PROTOCOL=HTTP/1.1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[30] = "HTTP_COOKIE=org.cups.sid=40f4958e3198ba77b01ac3aee099d7a1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[31] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux i686; rv:10.0.2) Gecko/20100101 Firefox/10.0.2 Iceweasel/10.0.2"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[32] = "REQUEST_METHOD=GET"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[33] = "QUERY_STRING=OP=redirect"
D [23/Feb/2012:16:36:43 -0600] [CGI] Started /usr/lib/cups/cgi-bin/admin.cgi (PID 11282)
I [23/Feb/2012:16:36:43 -0600] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=11282)
D [23/Feb/2012:16:36:43 -0600] cupsdSendCommand: 15 file=16
D [23/Feb/2012:16:36:43 -0600] [CGI] admin.cgi started...
D [23/Feb/2012:16:36:43 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:36:43 -0600] [CGI] http=0xb87279e8
D [23/Feb/2012:16:36:43 -0600] [CGI] org.cups.sid cookie is "40f4958e3198ba77b01ac3aee099d7a1"
D [23/Feb/2012:16:36:43 -0600] [CGI] redirecting with prefix http://localhost:631!
D [23/Feb/2012:16:36:43 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:36:43 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:36:43 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Feb/2012:16:36:43 -0600] Script header: Location: http://localhost:631/admin
D [23/Feb/2012:16:36:43 -0600] Script header:
D [23/Feb/2012:16:36:43 -0600] PID 11282 (/usr/lib/cups/cgi-bin/admin.cgi) exited with no errors.
D [23/Feb/2012:16:36:43 -0600] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [23/Feb/2012:16:36:43 -0600] cupsdReadClient: 15 GET /admin HTTP/1.1
D [23/Feb/2012:16:36:43 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [23/Feb/2012:16:36:43 -0600] cupsdAuthorize: Authorized as root using Basic
D [23/Feb/2012:16:36:43 -0600] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/admin.cgi"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc-root"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[8] = "HOME=/var/spool/cups/tmp"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[10] = "SERVER_ADMIN=root at merlin"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[11] = "SOFTWARE=CUPS/1.5.2"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[13] = "TZ=America/Chicago"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[14] = "USER=root"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[15] = "CUPS_SERVER=/var/run/cups/cups.sock"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[16] = "CUPS_ENCRYPTION=IfRequested"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[17] = "IPP_PORT=631"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[18] = "AUTH_TYPE=Basic"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[19] = "LANG=en_US.UTF8"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[20] = "REDIRECT_STATUS=1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[21] = "GATEWAY_INTERFACE=CGI/1.1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[22] = "SERVER_NAME=localhost"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[23] = "SERVER_PORT=631"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[24] = "REMOTE_ADDR=127.0.0.1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[25] = "REMOTE_HOST=localhost"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[26] = "SCRIPT_NAME=/admin"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[27] = "SCRIPT_FILENAME=/usr/share/cups/doc-root/admin"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[28] = "REMOTE_USER=root"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[29] = "SERVER_PROTOCOL=HTTP/1.1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[30] = "HTTP_COOKIE=org.cups.sid=40f4958e3198ba77b01ac3aee099d7a1"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[31] = "HTTP_USER_AGENT=Mozilla/5.0 (X11; Linux i686; rv:10.0.2) Gecko/20100101 Firefox/10.0.2 Iceweasel/10.0.2"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[32] = "REQUEST_METHOD=GET"
D [23/Feb/2012:16:36:43 -0600] [CGI] envp[33] = "QUERY_STRING="
D [23/Feb/2012:16:36:43 -0600] [CGI] Started /usr/lib/cups/cgi-bin/admin.cgi (PID 11283)
I [23/Feb/2012:16:36:43 -0600] Started "/usr/lib/cups/cgi-bin/admin.cgi" (pid=11283)
D [23/Feb/2012:16:36:43 -0600] cupsdSendCommand: 15 file=16
D [23/Feb/2012:16:36:43 -0600] [CGI] admin.cgi started...
D [23/Feb/2012:16:36:43 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:36:43 -0600] [CGI] http=0xb87249e8
D [23/Feb/2012:16:36:43 -0600] [CGI] org.cups.sid cookie is "40f4958e3198ba77b01ac3aee099d7a1"
D [23/Feb/2012:16:36:43 -0600] [CGI] No form data, showing main menu...
D [23/Feb/2012:16:36:43 -0600] [CGI] /usr/share/cups/drivers/pscript5.dll: No such file or directory
D [23/Feb/2012:16:36:43 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:36:43 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Feb/2012:16:36:43 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:36:43 -0600] cupsdReadClient: 17 1.1 Get-Subscriptions 1
D [23/Feb/2012:16:36:43 -0600] Get-Subscriptions ipp://localhost/
D [23/Feb/2012:16:36:43 -0600] Get-Subscriptions client-error-not-found: No subscriptions found.
D [23/Feb/2012:16:36:43 -0600] Returning IPP client-error-not-found for Get-Subscriptions (ipp://localhost/) from localhost
D [23/Feb/2012:16:36:43 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Feb/2012:16:36:43 -0600] Script header: Content-Type: text/html;charset=utf-8
D [23/Feb/2012:16:36:43 -0600] Script header:
D [23/Feb/2012:16:36:43 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:36:43 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:36:43 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Feb/2012:16:36:43 -0600] PID 11283 (/usr/lib/cups/cgi-bin/admin.cgi) exited with no errors.
D [23/Feb/2012:16:36:43 -0600] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
I [23/Feb/2012:16:37:09 -0600] Generating printcap /var/run/cups/printcap...
D [23/Feb/2012:16:37:09 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
D [23/Feb/2012:16:37:10 -0600] cupsdReadClient: 15 GET /admin/log/error_log HTTP/1.1
D [23/Feb/2012:16:37:10 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:37:10 -0600] cupsdAuthorize: Authorized as root using Basic
D [23/Feb/2012:16:37:10 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:37:10 -0600] cupsdReadClient: 15 GET /favicon.ico HTTP/1.1
D [23/Feb/2012:16:37:10 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:37:11 -0600] cupsdAuthorize: Authorized as root using Basic
D [23/Feb/2012:16:37:11 -0600] cupsdReadClient: 15 Closing because Keep-Alive disabled
D [23/Feb/2012:16:37:11 -0600] cupsdCloseClient: 15
D [23/Feb/2012:16:37:11 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:37:11 -0600] cupsdAcceptClient: 15 from localhost:631 (IPv4)
D [23/Feb/2012:16:37:11 -0600] cupsdReadClient: 15 GET /favicon.ico HTTP/1.1
D [23/Feb/2012:16:37:11 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:37:11 -0600] cupsdAuthorize: Authorized as root using Basic
D [23/Feb/2012:16:37:11 -0600] cupsdReadClient: 15 Closing because Keep-Alive disabled
D [23/Feb/2012:16:37:11 -0600] cupsdCloseClient: 15
D [23/Feb/2012:16:37:11 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:02 -0600] cupsdAcceptClient: 15 from localhost (Domain)
D [23/Feb/2012:16:38:02 -0600] Report: clients=1
D [23/Feb/2012:16:38:02 -0600] Report: jobs=4
D [23/Feb/2012:16:38:02 -0600] Report: jobs-active=0
D [23/Feb/2012:16:38:02 -0600] Report: printers=2
D [23/Feb/2012:16:38:02 -0600] Report: printers-implicit=0
D [23/Feb/2012:16:38:02 -0600] Report: stringpool-string-count=1723
D [23/Feb/2012:16:38:02 -0600] Report: stringpool-alloc-bytes=11056
D [23/Feb/2012:16:38:02 -0600] Report: stringpool-total-bytes=31360
D [23/Feb/2012:16:38:02 -0600] cupsdReadClient: 15 POST / HTTP/1.1
D [23/Feb/2012:16:38:02 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:02 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:02 -0600] cupsdReadClient: 15 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:02 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:02 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:02 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:02 -0600] cupsdReadClient: 15 POST / HTTP/1.1
D [23/Feb/2012:16:38:02 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:02 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:02 -0600] cupsdReadClient: 15 1.1 CUPS-Get-Default 1
D [23/Feb/2012:16:38:02 -0600] CUPS-Get-Default
D [23/Feb/2012:16:38:02 -0600] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [23/Feb/2012:16:38:02 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:02 -0600] cupsdReadClient: 15 POST / HTTP/1.1
D [23/Feb/2012:16:38:02 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:02 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:02 -0600] cupsdReadClient: 15 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:02 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:02 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:02 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:02 -0600] cupsdReadClient: 15 POST / HTTP/1.1
D [23/Feb/2012:16:38:02 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:02 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:02 -0600] cupsdReadClient: 15 1.1 CUPS-Get-Default 1
D [23/Feb/2012:16:38:02 -0600] CUPS-Get-Default
D [23/Feb/2012:16:38:02 -0600] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [23/Feb/2012:16:38:02 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:02 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:02 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:02 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:02 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:02 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:03 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:03 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:03 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 16 GET /printers/Brother-HL-5240.ppd HTTP/1.1
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:03 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:03 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:03 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:03 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:03 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:03 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:03 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:03 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:03 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:03 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:03 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:03 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:03 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:03 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:03 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:03 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:04 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:04 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:04 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:04 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 16 POST / HTTP/1.1
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 16 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:04 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:04 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:04 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:04 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:04 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:04 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:04 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:04 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:04 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:04 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:05 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:05 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:05 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:05 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:05 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:05 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:05 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:05 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:05 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:05 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:05 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:05 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:05 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:05 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:05 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:05 -0600] cupsdAcceptClient: 17 from localhost (Domain)
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:05 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 17 POST / HTTP/1.1
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:05 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [23/Feb/2012:16:38:05 -0600] CUPS-Get-Printers
D [23/Feb/2012:16:38:05 -0600] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [23/Feb/2012:16:38:05 -0600] cupsdReadClient: 17 WAITING Closing on EOF
D [23/Feb/2012:16:38:05 -0600] cupsdCloseClient: 17
D [23/Feb/2012:16:38:05 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"
D [23/Feb/2012:16:38:08 -0600] cupsdAcceptClient: 16 from localhost (Domain)
D [23/Feb/2012:16:38:08 -0600] cupsdReadClient: 16 POST /printers/Brother-HL-5240 HTTP/1.1
D [23/Feb/2012:16:38:08 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:08 -0600] cupsdAuthorize: No authentication data provided.
D [23/Feb/2012:16:38:08 -0600] cupsdReadClient: 16 1.1 Print-Job 1
D [23/Feb/2012:16:38:08 -0600] Print-Job ipp://localhost:631/printers/Brother-HL-5240
D [23/Feb/2012:16:38:08 -0600] [Job ???] Auto-typing file...
I [23/Feb/2012:16:38:08 -0600] [Job ???] Request file type is application/pdf.
D [23/Feb/2012:16:38:08 -0600] cupsdMarkDirty(----J-)
D [23/Feb/2012:16:38:08 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [23/Feb/2012:16:38:08 -0600] add_job: requesting-user-name="nate"
I [23/Feb/2012:16:38:08 -0600] [Job 5] Adding start banner page "none".
D [23/Feb/2012:16:38:08 -0600] Discarding unused job-created event...
D [23/Feb/2012:16:38:08 -0600] cupsdMarkDirty(----J-)
D [23/Feb/2012:16:38:08 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [23/Feb/2012:16:38:08 -0600] [Job 5] Adding end banner page "none".
I [23/Feb/2012:16:38:08 -0600] [Job 5] File of type application/pdf queued by "nate".
D [23/Feb/2012:16:38:08 -0600] [Job 5] hold_until=0
I [23/Feb/2012:16:38:08 -0600] [Job 5] Queued on "Brother-HL-5240" by "nate".
D [23/Feb/2012:16:38:08 -0600] cupsdMarkDirty(----J-)
D [23/Feb/2012:16:38:08 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Feb/2012:16:38:08 -0600] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [23/Feb/2012:16:38:08 -0600] Discarding unused printer-state-changed event...
D [23/Feb/2012:16:38:08 -0600] [Job 5] job-sheets=none,none
D [23/Feb/2012:16:38:08 -0600] [Job 5] argv[0]="Brother-HL-5240"
D [23/Feb/2012:16:38:08 -0600] [Job 5] argv[1]="5"
D [23/Feb/2012:16:38:08 -0600] [Job 5] argv[2]="nate"
D [23/Feb/2012:16:38:08 -0600] [Job 5] argv[3]="http://localhost:631/admin/log/error_log"
D [23/Feb/2012:16:38:08 -0600] [Job 5] argv[4]="1"
D [23/Feb/2012:16:38:08 -0600] [Job 5] argv[5]="Duplex=None PageSize=Letter Resolution=600x600dpi number-up=1 job-uuid=urn:uuid:9d5d33d0-45f0-3596-6df1-ba8df33db6d8 job-originating-host-name=localhost time-at-creation=1330036688 time-at-processing=1330036688 AP_D_InputSlot="
D [23/Feb/2012:16:38:08 -0600] [Job 5] argv[6]="/var/spool/cups/d00005-001"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[8]="HOME=/var/spool/cups/tmp"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[10]="SERVER_ADMIN=root at merlin"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[11]="SOFTWARE=CUPS/1.5.2"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[13]="TZ=America/Chicago"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[14]="USER=root"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[15]="CUPS_SERVER=/var/run/cups/cups.sock"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[16]="CUPS_ENCRYPTION=IfRequested"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[17]="IPP_PORT=631"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[18]="CHARSET=utf-8"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[19]="LANG=en_US.UTF-8"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[20]="PPD=/etc/cups/ppd/Brother-HL-5240.ppd"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[21]="RIP_MAX_CACHE=128m"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[22]="CONTENT_TYPE=application/pdf"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[23]="DEVICE_URI=lpd://axis/pr1"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[24]="PRINTER_INFO=Brother HL-5240 on AXIS673A94"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[25]="PRINTER_LOCATION=Home"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[26]="PRINTER=Brother-HL-5240"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[27]="PRINTER_STATE_REASONS=none"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[28]="CUPS_FILETYPE=document"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[29]="FINAL_CONTENT_TYPE=printer/Brother-HL-5240"
D [23/Feb/2012:16:38:08 -0600] [Job 5] envp[30]="AUTH_I****"
I [23/Feb/2012:16:38:08 -0600] [Job 5] Started filter /usr/lib/cups/filter/pdftopdf (PID 11291)
I [23/Feb/2012:16:38:08 -0600] [Job 5] Started filter /usr/lib/cups/filter/foomatic-rip (PID 11292)
I [23/Feb/2012:16:38:08 -0600] [Job 5] Started backend /usr/lib/cups/backend/lpd (PID 11293)
D [23/Feb/2012:16:38:08 -0600] Discarding unused job-state-changed event...
D [23/Feb/2012:16:38:08 -0600] Returning IPP successful-ok for Print-Job (ipp://localhost:631/printers/Brother-HL-5240) from localhost
D [23/Feb/2012:16:38:08 -0600] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [23/Feb/2012:16:38:08 -0600] cupsdReadClient: 16 WAITING Closing on EOF
D [23/Feb/2012:16:38:08 -0600] cupsdCloseClient: 16
D [23/Feb/2012:16:38:08 -0600] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Feb/2012:16:38:08 -0600] [Job 5] STATE: +connecting-to-device
D [23/Feb/2012:16:38:08 -0600] [Job 5] Looking up "axis"...
D [23/Feb/2012:16:38:08 -0600] Discarding unused printer-state-changed event...
D [23/Feb/2012:16:38:08 -0600] [Job 5] backendWaitLoop(snmp_fd=5, addr=0xb93ea994, side_cb=0xb7710f10)
D [23/Feb/2012:16:38:08 -0600] [Job 5] Getting input from file
D [23/Feb/2012:16:38:08 -0600] [Job 5] foomatic-rip version 4.0.12.246 running...
D [23/Feb/2012:16:38:08 -0600] [Job 5] Parsing PPD file ...
D [23/Feb/2012:16:38:08 -0600] [Job 5] Added option ColorSpace
D [23/Feb/2012:16:38:08 -0600] [Job 5] Added option PageSize
D [23/Feb/2012:16:38:08 -0600] [Job 5] CUPS page accounting disabled by driver.
D [23/Feb/2012:16:38:08 -0600] [Job 5] Added option ImageableArea
D [23/Feb/2012:16:38:08 -0600] [Job 5] Added option PaperDimension
D [23/Feb/2012:16:38:08 -0600] [Job 5] Added option Duplex
D [23/Feb/2012:16:38:08 -0600] [Job 5] Added option Resolution
D [23/Feb/2012:16:38:08 -0600] [Job 5] Added option Font
D [23/Feb/2012:16:38:08 -0600] [Job 5]
D [23/Feb/2012:16:38:08 -0600] [Job 5] Parameter Summary
D [23/Feb/2012:16:38:08 -0600] [Job 5] -----------------
D [23/Feb/2012:16:38:08 -0600] [Job 5]
D [23/Feb/2012:16:38:08 -0600] [Job 5] Spooler: cups
D [23/Feb/2012:16:38:08 -0600] [Job 5] Printer: Brother-HL-5240
D [23/Feb/2012:16:38:08 -0600] [Job 5] Shell: /bin/bash
D [23/Feb/2012:16:38:08 -0600] [Job 5] PPD file: /etc/cups/ppd/Brother-HL-5240.ppd
D [23/Feb/2012:16:38:08 -0600] [Job 5] ATTR file:
D [23/Feb/2012:16:38:08 -0600] [Job 5] Printer model: Brother HL-5240 Foomatic/Postscript
D [23/Feb/2012:16:38:08 -0600] [Job 5] Job title: http://localhost:631/admin/log/error_log
D [23/Feb/2012:16:38:08 -0600] [Job 5] File(s) to be printed:
D [23/Feb/2012:16:38:08 -0600] [Job 5] <STDIN>
D [23/Feb/2012:16:38:08 -0600] [Job 5]
D [23/Feb/2012:16:38:08 -0600] [Job 5] Ghostscript extra search path ('GS_LIB'): /usr/share/cups/fonts
D [23/Feb/2012:16:38:08 -0600] [Job 5] Printing system options:
D [23/Feb/2012:16:38:08 -0600] [Job 5] Pondering option 'number-up=1'
D [23/Feb/2012:16:38:08 -0600] [Job 5] Unknown option number-up=1.
D [23/Feb/2012:16:38:08 -0600] [Job 5] Pondering option 'job-uuid=urn:uuid:9d5d33d0-45f0-3596-6df1-ba8df33db6d8'
D [23/Feb/2012:16:38:08 -0600] [Job 5] Unknown option job-uuid=urn:uuid:9d5d33d0-45f0-3596-6df1-ba8df33db6d8.
D [23/Feb/2012:16:38:08 -0600] [Job 5] Pondering option 'job-originating-host-name=localhost'
D [23/Feb/2012:16:38:08 -0600] [Job 5] Unknown option job-originating-host-name=localhost.
D [23/Feb/2012:16:38:08 -0600] [Job 5] Pondering option 'time-at-creation=1330036688'
D [23/Feb/2012:16:38:08 -0600] [Job 5] Unknown option time-at-creation=1330036688.
D [23/Feb/2012:16:38:08 -0600] [Job 5] Pondering option 'time-at-processing=1330036688'
D [23/Feb/2012:16:38:08 -0600] [Job 5] Unknown option time-at-processing=1330036688.
D [23/Feb/2012:16:38:08 -0600] [Job 5] Pondering option 'AP_D_InputSlot='
D [23/Feb/2012:16:38:08 -0600] [Job 5] Unknown option AP_D_InputSlot=.
D [23/Feb/2012:16:38:08 -0600] [Job 5] Options from the PPD file:
D [23/Feb/2012:16:38:08 -0600] [Job 5] Pondering option 'Duplex=None'
D [23/Feb/2012:16:38:08 -0600] [Job 5] Pondering option 'PageSize=Letter'
D [23/Feb/2012:16:38:08 -0600] [Job 5] Pondering option 'Resolution=600x600dpi'
D [23/Feb/2012:16:38:08 -0600] [Job 5]
D [23/Feb/2012:16:38:08 -0600] [Job 5] ================================================
D [23/Feb/2012:16:38:08 -0600] [Job 5]
D [23/Feb/2012:16:38:08 -0600] [Job 5] File: <STDIN>
D [23/Feb/2012:16:38:08 -0600] [Job 5]
D [23/Feb/2012:16:38:08 -0600] [Job 5] ================================================
D [23/Feb/2012:16:38:08 -0600] [Job 5]
D [23/Feb/2012:16:38:08 -0600] [Job 5] Filetype: PDF
D [23/Feb/2012:16:38:08 -0600] [Job 5] Driver does not understand PDF input, converting to PostScript
D [23/Feb/2012:16:38:08 -0600] [Job 5] Storing temporary files in /var/spool/cups/tmp
D [23/Feb/2012:16:38:08 -0600] [Job 5] Starting process "pdf-to-ps" (generation 1)
D [23/Feb/2012:16:38:08 -0600] PID 11291 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [23/Feb/2012:16:38:10 -0600] [Job 5] Filetype: PostScript
D [23/Feb/2012:16:38:10 -0600] [Job 5] Reading PostScript input ...
D [23/Feb/2012:16:38:10 -0600] [Job 5] --> This document is DSC-conforming!
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5] -----------
D [23/Feb/2012:16:38:10 -0600] [Job 5] Found: %%BeginProlog
D [23/Feb/2012:16:38:10 -0600] [Job 5] Inserting option code into "Prolog" section.
D [23/Feb/2012:16:38:10 -0600] [Job 5] Found: %%EndProlog
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5] -----------
D [23/Feb/2012:16:38:10 -0600] [Job 5] New page: %%Page: 1 1
D [23/Feb/2012:16:38:10 -0600] [Job 5] "Setup" section is missing, inserting it.
D [23/Feb/2012:16:38:10 -0600] [Job 5] Inserting option code into "Setup" section.
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5] Found: %%BeginPageSetup
D [23/Feb/2012:16:38:10 -0600] [Job 5] Inserting option code into "PageSetup" section.
D [23/Feb/2012:16:38:10 -0600] [Job 5] New page found but previous not printed, print it now.
D [23/Feb/2012:16:38:10 -0600] [Job 5] Found: %%Page: 2 2
D [23/Feb/2012:16:38:10 -0600] [Job 5] --> Output goes directly to the renderer now.
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5] Starting renderer with command: "cat"
D [23/Feb/2012:16:38:10 -0600] [Job 5] Starting process "kid3" (generation 1)
D [23/Feb/2012:16:38:10 -0600] [Job 5] Starting process "kid4" (generation 2)
D [23/Feb/2012:16:38:10 -0600] [Job 5] Starting process "renderer" (generation 2)
D [23/Feb/2012:16:38:10 -0600] [Job 5] JCL: %-12345X at PJL
D [23/Feb/2012:16:38:10 -0600] [Job 5] <job data>
D [23/Feb/2012:16:38:10 -0600] [Job 5]
I [23/Feb/2012:16:38:10 -0600] [Job 5] Copying print data.
D [23/Feb/2012:16:38:10 -0600] [Job 5] Set job-printer-state-message to "Copying print data.", current level=INFO
D [23/Feb/2012:16:38:10 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:10 -0600] Discarding unused printer-state-changed event...
D [23/Feb/2012:16:38:10 -0600] [Job 5] backendRunLoop(print_fd=-1, device_fd=6, snmp_fd=5, addr=0xb93ea994, use_bc=0, side_cb=0xb7710f10)
D [23/Feb/2012:16:38:10 -0600] [Job 5] Read 4096 bytes of print data...
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5] -----------
D [23/Feb/2012:16:38:10 -0600] [Job 5] New page: %%Page: 2 2
D [23/Feb/2012:16:38:10 -0600] [Job 5] Found: %%Page: 2 2
D [23/Feb/2012:16:38:10 -0600] [Job 5] --> Output goes to the FIFO buffer now.
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5] Found: %%BeginPageSetup
D [23/Feb/2012:16:38:10 -0600] [Job 5] Inserting option code into "PageSetup" section.
D [23/Feb/2012:16:38:10 -0600] [Job 5] New page found but previous not printed, print it now.
D [23/Feb/2012:16:38:10 -0600] [Job 5] Found: %%Page: 3 3
D [23/Feb/2012:16:38:10 -0600] [Job 5] --> Output goes directly to the renderer now.
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5] -----------
D [23/Feb/2012:16:38:10 -0600] [Job 5] New page: %%Page: 3 3
D [23/Feb/2012:16:38:10 -0600] [Job 5] Found: %%Page: 3 3
D [23/Feb/2012:16:38:10 -0600] [Job 5] --> Output goes to the FIFO buffer now.
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5]
D [23/Feb/2012:16:38:10 -0600] [Job 5] Found: %%BeginPageSetup
D [23/Feb/2012:16:38:10 -0600] [Job 5] Inserting option code into "PageSetup" section.
D [23/Feb/2012:16:38:10 -0600] [Job 5] Flushing FIFO.
D [23/Feb/2012:16:38:14 -0600] [Job 5] prtGeneralCurrentLocalization type is 0, expected 2!
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 4096 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 4096 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 4096 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5]
D [23/Feb/2012:16:38:14 -0600] [Job 5] Closing renderer
D [23/Feb/2012:16:38:14 -0600] [Job 5] renderer exited with status 0
D [23/Feb/2012:16:38:14 -0600] [Job 5] kid4 exited with status 0
D [23/Feb/2012:16:38:14 -0600] [Job 5] kid3 finished
D [23/Feb/2012:16:38:14 -0600] [Job 5] kid3 exited with status 0
D [23/Feb/2012:16:38:14 -0600] [Job 5] pdf-to-ps exited with status 0
D [23/Feb/2012:16:38:14 -0600] [Job 5]
D [23/Feb/2012:16:38:14 -0600] [Job 5] Closing foomatic-rip.
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 8192 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Read 4709 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Wrote 4709 bytes of print data...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Connecting to axis:515 for printer pr1
I [23/Feb/2012:16:38:14 -0600] [Job 5] Connecting to printer.
D [23/Feb/2012:16:38:14 -0600] [Job 5] Set job-printer-state-message to "Connecting to printer.", current level=INFO
D [23/Feb/2012:16:38:14 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:14 -0600] Discarding unused printer-state-changed event...
D [23/Feb/2012:16:38:14 -0600] PID 11292 (/usr/lib/cups/filter/foomatic-rip) exited with no errors.
D [23/Feb/2012:16:38:14 -0600] [Job 5] STATE: -connecting-to-device
I [23/Feb/2012:16:38:14 -0600] [Job 5] Connected to printer.
D [23/Feb/2012:16:38:14 -0600] [Job 5] Set job-printer-state-message to "Connected to printer.", current level=INFO
D [23/Feb/2012:16:38:14 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:14 -0600] Discarding unused printer-state-changed event...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Connected to 192.168.73.51:515 (local port 1023)...
D [23/Feb/2012:16:38:14 -0600] [Job 5] lpd_command 02 pr1
D [23/Feb/2012:16:38:14 -0600] [Job 5] Sending command string (5 bytes)...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Reading command status...
D [23/Feb/2012:16:38:14 -0600] [Job 5] lpd_command returning 0
D [23/Feb/2012:16:38:14 -0600] [Job 5] Control file is:
D [23/Feb/2012:16:38:14 -0600] [Job 5] Hmerlin.n0nb.ampr.org
D [23/Feb/2012:16:38:14 -0600] [Job 5] Pnate
D [23/Feb/2012:16:38:14 -0600] [Job 5] Jhttp___localhost_631_admin_log_error_log
D [23/Feb/2012:16:38:14 -0600] [Job 5] ldfA293merlin.n0nb.amp
D [23/Feb/2012:16:38:14 -0600] [Job 5] UdfA293merlin.n0nb.amp
D [23/Feb/2012:16:38:14 -0600] [Job 5] Nhttp___localhost_631_admin_log_error_log
D [23/Feb/2012:16:38:14 -0600] [Job 5] lpd_command 02 158 cfA293merlin.n0nb.amp
D [23/Feb/2012:16:38:14 -0600] [Job 5] Sending command string (27 bytes)...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Reading command status...
D [23/Feb/2012:16:38:14 -0600] [Job 5] lpd_command returning 0
D [23/Feb/2012:16:38:14 -0600] [Job 5] Sending control file (158 bytes)
I [23/Feb/2012:16:38:14 -0600] [Job 5] Control file sent successfully.
D [23/Feb/2012:16:38:14 -0600] [Job 5] Set job-printer-state-message to "Control file sent successfully.", current level=INFO
D [23/Feb/2012:16:38:14 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:14 -0600] Discarding unused printer-state-changed event...
D [23/Feb/2012:16:38:14 -0600] [Job 5] lpd_command 03 242277 dfA293merlin.n0nb.amp
D [23/Feb/2012:16:38:14 -0600] [Job 5] Sending command string (30 bytes)...
D [23/Feb/2012:16:38:14 -0600] [Job 5] Reading command status...
D [23/Feb/2012:16:38:15 -0600] [Job 5] lpd_command returning 0
D [23/Feb/2012:16:38:15 -0600] [Job 5] Sending data file (242277 bytes)
I [23/Feb/2012:16:38:15 -0600] [Job 5] Spooling job, 0% complete.
D [23/Feb/2012:16:38:15 -0600] [Job 5] Set job-printer-state-message to "Spooling job, 0% complete.", current level=INFO
D [23/Feb/2012:16:38:15 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:15 -0600] Discarding unused printer-state-changed event...
I [23/Feb/2012:16:38:15 -0600] [Job 5] Spooling job, 14% complete.
D [23/Feb/2012:16:38:15 -0600] [Job 5] Set job-printer-state-message to "Spooling job, 14% complete.", current level=INFO
D [23/Feb/2012:16:38:15 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:15 -0600] Discarding unused printer-state-changed event...
I [23/Feb/2012:16:38:15 -0600] [Job 5] Spooling job, 27% complete.
D [23/Feb/2012:16:38:15 -0600] [Job 5] Set job-printer-state-message to "Spooling job, 27% complete.", current level=INFO
D [23/Feb/2012:16:38:15 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:15 -0600] Discarding unused printer-state-changed event...
I [23/Feb/2012:16:38:15 -0600] [Job 5] Spooling job, 41% complete.
D [23/Feb/2012:16:38:15 -0600] [Job 5] Set job-printer-state-message to "Spooling job, 41% complete.", current level=INFO
D [23/Feb/2012:16:38:15 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:15 -0600] Discarding unused printer-state-changed event...
I [23/Feb/2012:16:38:15 -0600] [Job 5] Spooling job, 54% complete.
D [23/Feb/2012:16:38:15 -0600] [Job 5] Set job-printer-state-message to "Spooling job, 54% complete.", current level=INFO
D [23/Feb/2012:16:38:15 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:15 -0600] Discarding unused printer-state-changed event...
I [23/Feb/2012:16:38:15 -0600] [Job 5] Spooling job, 68% complete.
D [23/Feb/2012:16:38:15 -0600] [Job 5] Set job-printer-state-message to "Spooling job, 68% complete.", current level=INFO
D [23/Feb/2012:16:38:15 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:15 -0600] Discarding unused printer-state-changed event...
I [23/Feb/2012:16:38:15 -0600] [Job 5] Spooling job, 81% complete.
D [23/Feb/2012:16:38:15 -0600] [Job 5] Set job-printer-state-message to "Spooling job, 81% complete.", current level=INFO
D [23/Feb/2012:16:38:15 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:15 -0600] Discarding unused printer-state-changed event...
I [23/Feb/2012:16:38:16 -0600] [Job 5] Spooling job, 95% complete.
D [23/Feb/2012:16:38:16 -0600] [Job 5] Set job-printer-state-message to "Spooling job, 95% complete.", current level=INFO
D [23/Feb/2012:16:38:16 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:16 -0600] Discarding unused printer-state-changed event...
I [23/Feb/2012:16:38:16 -0600] [Job 5] Data file sent successfully.
D [23/Feb/2012:16:38:16 -0600] [Job 5] Set job-printer-state-message to "Data file sent successfully.", current level=INFO
D [23/Feb/2012:16:38:16 -0600] Discarding unused job-progress event...
D [23/Feb/2012:16:38:16 -0600] Discarding unused printer-state-changed event...
D [23/Feb/2012:16:38:16 -0600] PID 11293 (/usr/lib/cups/backend/lpd) exited with no errors.
D [23/Feb/2012:16:38:16 -0600] Discarding unused job-completed event...
I [23/Feb/2012:16:38:16 -0600] [Job 5] Job completed.
D [23/Feb/2012:16:38:16 -0600] cupsdMarkDirty(----J-)
D [23/Feb/2012:16:38:16 -0600] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Feb/2012:16:38:16 -0600] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [23/Feb/2012:16:38:16 -0600] Discarding unused printer-state-changed event...
D [23/Feb/2012:16:38:17 -0600] [Job 5] Unloading...
I [23/Feb/2012:16:38:39 -0600] Saving job.cache...
D [23/Feb/2012:16:38:39 -0600] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files"
D [23/Feb/2012:16:38:41 -0600] cupsdAcceptClient: 16 from localhost:631 (IPv4)
D [23/Feb/2012:16:38:41 -0600] cupsdReadClient: 16 GET /admin/log/error_log HTTP/1.1
D [23/Feb/2012:16:38:41 -0600] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [23/Feb/2012:16:38:42 -0600] cupsdAuthorize: Authorized as root using Basic
-------------- next part --------------
*PPD-Adobe: "4.3"
*%
*% For information on using this, and to obtain the required backend
*% script, consult http://www.openprinting.org/
*%
*% This file is published under the GNU General Public License
*%
*% PPD-O-MATIC (4.0.0 or newer) generated this PPD file. It is for use with 
*% all programs and environments which use PPD files for dealing with
*% printer capability information. The printer must be configured with the
*% "foomatic-rip" backend filter script of Foomatic 4.0.0 or newer. This 
*% file and "foomatic-rip" work together to support PPD-controlled printer
*% driver option access with all supported printer drivers and printing
*% spoolers.
*%
*% To save this file on your disk, wait until the download has completed
*% (the animation of the browser logo must stop) and then use the
*% "Save as..." command in the "File" menu of your browser or in the 
*% pop-up manu when you click on this document with the right mouse button.
*% DO NOT cut and paste this file into an editor with your mouse. This can
*% introduce additional line breaks which lead to unexpected results.
*%
*% You may save this file as 'Brother-HL-5240-Postscript.ppd'
*%
*%
*FormatVersion:	"4.3"
*FileVersion:	"1.1"
*LanguageVersion: English 
*LanguageEncoding: ISOLatin1
*PCFileName:	"POSTSCRI.PPD"
*Manufacturer:	"Brother"
*Product:	"(Brother HL-5240 series)"
*cupsVersion:	1.0
*cupsManualCopies: True
*cupsModelNumber:  2
*cupsFilter:	"application/vnd.cups-postscript 100 foomatic-rip"
*cupsFilter:	"application/vnd.cups-pdf 0 foomatic-rip"
*%pprRIP:        foomatic-rip other
*ModelName:     "Brother HL-5240"
*ShortNickName: "Brother HL-5240 Postscript"
*NickName:      "Brother HL-5240 Foomatic/Postscript"
*PSVersion:	"(3010.000) 550"
*PSVersion:	"(3010.000) 651"
*PSVersion:	"(3010.000) 652"
*PSVersion:	"(3010.000) 653"
*PSVersion:	"(3010.000) 704"
*PSVersion:	"(3010.000) 705"
*PSVersion:	"(3010.000) 800"
*PSVersion:	"(3010.000) 815"
*PSVersion:	"(3010.000) 850"
*PSVersion:	"(3010.000) 860"
*PSVersion:	"(3010.000) 861"
*PSVersion:	"(3010.000) 862"
*PSVersion:	"(3010.000) 863"
*PSVersion:	"(3010.000) 864"
*PSVersion:	"(3010.000) 870"
*LanguageLevel:	"3"
*ColorDevice:	False
*DefaultColorSpace: Gray
*FileSystem:	False
*Throughput:	"1"
*LandscapeOrientation: Plus90
*TTRasterizer:	Type42
*1284DeviceID: "MFG:Brother;MDL:Brother HL-5240 series;DRV:DPostscript,R0,M0,TP;"

*driverName Postscript: ""
*driverType P/PostScript: ""
*driverUrl: "http://partners.adobe.com/public/developer/ps/index_specs.html"
*driverObsolete: False
*driverManufacturerSupplied: False




*HWMargins: 18 36 18 36
*VariablePaperSize: True
*MaxMediaWidth: 100000
*MaxMediaHeight: 100000
*NonUIOrderDependency: 100 AnySetup *CustomPageSize
*CustomPageSize True: "pop pop pop
<</PageSize [ 5 -2 roll ] /ImagingBBox null>>setpagedevice"
*End
*ParamCustomPageSize Width: 1 points 36 100000
*ParamCustomPageSize Height: 2 points 36 100000
*ParamCustomPageSize Orientation: 3 int 0 0
*ParamCustomPageSize WidthOffset: 4 points 0 0
*ParamCustomPageSize HeightOffset: 5 points 0 0

*FoomaticIDs: Brother-HL-5240 Postscript
*FoomaticRIPCommandLine: "cat%A%B%Z"
*FoomaticRIPNoPageAccounting: True

*OpenGroup: General/General

*OpenUI *PageSize/Page Size: PickOne
*OrderDependency: 100 AnySetup *PageSize
*DefaultPageSize: Letter
*PageSize Letter/US Letter: "<</PageSize[612 792]/ImagingBBox null>>setpagedevice"
*PageSize A4/A4: "<</PageSize[595 842]/ImagingBBox null>>setpagedevice"
*PageSize 11x17/11x17: "<</PageSize[792 1224]/ImagingBBox null>>setpagedevice"
*PageSize A3/A3: "<</PageSize[842 1191]/ImagingBBox null>>setpagedevice"
*PageSize A5/A5: "<</PageSize[421 595]/ImagingBBox null>>setpagedevice"
*PageSize B5/B5 (JIS): "<</PageSize[516 729]/ImagingBBox null>>setpagedevice"
*PageSize Env10/Envelope #10: "<</PageSize[297 684]/ImagingBBox null>>setpagedevice"
*PageSize EnvC5/Envelope C5: "<</PageSize[459 649]/ImagingBBox null>>setpagedevice"
*PageSize EnvDL/Envelope DL: "<</PageSize[312 624]/ImagingBBox null>>setpagedevice"
*PageSize EnvISOB5/Envelope B5: "<</PageSize[499 709]/ImagingBBox null>>setpagedevice"
*PageSize EnvMonarch/Envelope Monarch: "<</PageSize[279 540]/ImagingBBox null>>setpagedevice"
*PageSize Executive/Executive: "<</PageSize[522 756]/ImagingBBox null>>setpagedevice"
*PageSize Legal/US Legal: "<</PageSize[612 1008]/ImagingBBox null>>setpagedevice"
*CloseUI: *PageSize

*OpenUI *PageRegion: PickOne
*OrderDependency: 100 AnySetup *PageRegion
*DefaultPageRegion: Letter
*PageRegion Letter/US Letter: "<</PageSize[612 792]/ImagingBBox null>>setpagedevice"
*PageRegion A4/A4: "<</PageSize[595 842]/ImagingBBox null>>setpagedevice"
*PageRegion 11x17/11x17: "<</PageSize[792 1224]/ImagingBBox null>>setpagedevice"
*PageRegion A3/A3: "<</PageSize[842 1191]/ImagingBBox null>>setpagedevice"
*PageRegion A5/A5: "<</PageSize[421 595]/ImagingBBox null>>setpagedevice"
*PageRegion B5/B5 (JIS): "<</PageSize[516 729]/ImagingBBox null>>setpagedevice"
*PageRegion Env10/Envelope #10: "<</PageSize[297 684]/ImagingBBox null>>setpagedevice"
*PageRegion EnvC5/Envelope C5: "<</PageSize[459 649]/ImagingBBox null>>setpagedevice"
*PageRegion EnvDL/Envelope DL: "<</PageSize[312 624]/ImagingBBox null>>setpagedevice"
*PageRegion EnvISOB5/Envelope B5: "<</PageSize[499 709]/ImagingBBox null>>setpagedevice"
*PageRegion EnvMonarch/Envelope Monarch: "<</PageSize[279 540]/ImagingBBox null>>setpagedevice"
*PageRegion Executive/Executive: "<</PageSize[522 756]/ImagingBBox null>>setpagedevice"
*PageRegion Legal/US Legal: "<</PageSize[612 1008]/ImagingBBox null>>setpagedevice"
*CloseUI: *PageRegion

*DefaultImageableArea: Letter
*ImageableArea Letter/US Letter: "18 36 594 756"
*ImageableArea A4/A4: "18 36 577 806"
*ImageableArea 11x17/11x17: "18 36 774 1188"
*ImageableArea A3/A3: "18 36 824 1155"
*ImageableArea A5/A5: "18 36 403 559"
*ImageableArea B5/B5 (JIS): "18 36 498 693"
*ImageableArea Env10/Envelope #10: "18 36 279 648"
*ImageableArea EnvC5/Envelope C5: "18 36 441 613"
*ImageableArea EnvDL/Envelope DL: "18 36 294 588"
*ImageableArea EnvISOB5/Envelope B5: "18 36 481 673"
*ImageableArea EnvMonarch/Envelope Monarch: "18 36 261 504"
*ImageableArea Executive/Executive: "18 36 504 720"
*ImageableArea Legal/US Legal: "18 36 594 972"

*DefaultPaperDimension: Letter
*PaperDimension Letter/US Letter: "612 792"
*PaperDimension A4/A4: "595 842"
*PaperDimension 11x17/11x17: "792 1224"
*PaperDimension A3/A3: "842 1191"
*PaperDimension A5/A5: "421 595"
*PaperDimension B5/B5 (JIS): "516 729"
*PaperDimension Env10/Envelope #10: "297 684"
*PaperDimension EnvC5/Envelope C5: "459 649"
*PaperDimension EnvDL/Envelope DL: "312 624"
*PaperDimension EnvISOB5/Envelope B5: "499 709"
*PaperDimension EnvMonarch/Envelope Monarch: "279 540"
*PaperDimension Executive/Executive: "522 756"
*PaperDimension Legal/US Legal: "612 1008"

*OpenUI *Duplex/Double-Sided Printing: PickOne
*OrderDependency: 130 AnySetup *Duplex
*DefaultDuplex: None
*Duplex DuplexNoTumble/Long Edge (Standard): "<</Duplex true /Tumble false>>setpagedevice"
*Duplex DuplexTumble/Short Edge (Flip): "<</Duplex true /Tumble true>>setpagedevice"
*Duplex None/Off: "<</Duplex false>>setpagedevice"
*CloseUI: *Duplex

*OpenUI *Resolution/Resolution: PickOne
*OrderDependency: 90 AnySetup *Resolution
*DefaultResolution: 600x600dpi
*Resolution 150x150dpi/150x150 DPI: "<</HWResolution[150 150]>>setpagedevice"
*Resolution 300x300dpi/300x300 DPI: "<</HWResolution[300 300]>>setpagedevice"
*Resolution 600x600dpi/600x600 DPI: "<</HWResolution[600 600]>>setpagedevice"
*Resolution 1200x1200dpi/1200x1200 DPI: "<</HWResolution[1200 1200]>>setpagedevice"
*CloseUI: *Resolution

*CloseGroup: General


*% Generic boilerplate PPD stuff as standard PostScript fonts and so on

*DefaultFont: Courier
*Font AvantGarde-Book: Standard "(001.006S)" Standard ROM
*Font AvantGarde-BookOblique: Standard "(001.006S)" Standard ROM
*Font AvantGarde-Demi: Standard "(001.007S)" Standard ROM
*Font AvantGarde-DemiOblique: Standard "(001.007S)" Standard ROM
*Font Bookman-Demi: Standard "(001.004S)" Standard ROM
*Font Bookman-DemiItalic: Standard "(001.004S)" Standard ROM
*Font Bookman-Light: Standard "(001.004S)" Standard ROM
*Font Bookman-LightItalic: Standard "(001.004S)" Standard ROM
*Font Courier: Standard "(002.004S)" Standard ROM
*Font Courier-Bold: Standard "(002.004S)" Standard ROM
*Font Courier-BoldOblique: Standard "(002.004S)" Standard ROM
*Font Courier-Oblique: Standard "(002.004S)" Standard ROM
*Font Helvetica: Standard "(001.006S)" Standard ROM
*Font Helvetica-Bold: Standard "(001.007S)" Standard ROM
*Font Helvetica-BoldOblique: Standard "(001.007S)" Standard ROM
*Font Helvetica-Narrow: Standard "(001.006S)" Standard ROM
*Font Helvetica-Narrow-Bold: Standard "(001.007S)" Standard ROM
*Font Helvetica-Narrow-BoldOblique: Standard "(001.007S)" Standard ROM
*Font Helvetica-Narrow-Oblique: Standard "(001.006S)" Standard ROM
*Font Helvetica-Oblique: Standard "(001.006S)" Standard ROM
*Font NewCenturySchlbk-Bold: Standard "(001.009S)" Standard ROM
*Font NewCenturySchlbk-BoldItalic: Standard "(001.007S)" Standard ROM
*Font NewCenturySchlbk-Italic: Standard "(001.006S)" Standard ROM
*Font NewCenturySchlbk-Roman: Standard "(001.007S)" Standard ROM
*Font Palatino-Bold: Standard "(001.005S)" Standard ROM
*Font Palatino-BoldItalic: Standard "(001.005S)" Standard ROM
*Font Palatino-Italic: Standard "(001.005S)" Standard ROM
*Font Palatino-Roman: Standard "(001.005S)" Standard ROM
*Font Symbol: Special "(001.007S)" Special ROM
*Font Times-Bold: Standard "(001.007S)" Standard ROM
*Font Times-BoldItalic: Standard "(001.009S)" Standard ROM
*Font Times-Italic: Standard "(001.007S)" Standard ROM
*Font Times-Roman: Standard "(001.007S)" Standard ROM
*Font ZapfChancery-MediumItalic: Standard "(001.007S)" Standard ROM
*Font ZapfDingbats: Special "(001.004S)" Standard ROM

More information about the Pkg-cups-devel mailing list