My apologies.  I forgot to include the printer model ML3470D and append the CUPS error log:-
I [07/May/2012:14:55:02 +0100] Remote access is disabled.
D [07/May/2012:14:55:02 +0100] Added auto ServerAlias peter-Desktop
I [07/May/2012:14:55:02 +0100] Loaded configuration file "/etc/cups/cupsd.conf"
I [07/May/2012:14:55:02 +0100] Using default TempDir of /var/spool/cups/tmp...
I [07/May/2012:14:55:02 +0100] Configured for up to 100 clients.
I [07/May/2012:14:55:02 +0100] Allowing up to 100 client connections per host.
I [07/May/2012:14:55:02 +0100] Using policy "default" as the default.
D [07/May/2012:14:55:02 +0100] load_ppd: Loading /var/cache/cups/ML-3470-Series.data...
D [07/May/2012:14:55:02 +0100] Calling DeleteDevice(cups-ML-3470-Series)
D [07/May/2012:14:55:02 +0100] failed to DeleteDevice: org.freedesktop.DBus.Error.InvalidArgs:Type of message, `(s)', does not match expected type `(o)'
D [07/May/2012:14:55:02 +0100] Using profile id of ML-3470-Series-Gray..
D [07/May/2012:14:55:02 +0100] Calling CreateProfile(ML-3470-Series-Gray..,temp)
W [07/May/2012:14:55:02 +0100] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'ML-3470-Series-Gray..' already exists
I [07/May/2012:14:55:02 +0100] Registering ICC color profiles for "ML-3470-Series"
D [07/May/2012:14:55:02 +0100] Calling CreateDevice(cups-ML-3470-Series,temp)
W [07/May/2012:14:55:02 +0100] failed to CreateDevice: org.freedesktop.ColorManager.AlreadyExists:device id 'cups-ML-3470-Series' already exists
D [07/May/2012:14:55:02 +0100] cupsdRegisterPrinter(p=0xb792c2d0(ML-3470-Series))
D [07/May/2012:14:55:02 +0100] cupsdMarkDirty(---p--)
D [07/May/2012:14:55:02 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy"
I [07/May/2012:14:55:02 +0100] Partial reload complete.
I [07/May/2012:14:55:02 +0100] Listening to [v1.::1]:631 on fd 8...
I [07/May/2012:14:55:02 +0100] Listening to 127.0.0.1:631 on fd 9...
I [07/May/2012:14:55:02 +0100] Listening to /var/run/cups/cups.sock:631 on fd 10...
I [07/May/2012:14:55:02 +0100] Resuming new connection processing...
D [07/May/2012:14:55:02 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:02 +0100] Discarding unused server-restarted event...
D [07/May/2012:14:55:02 +0100] cupsdAcceptClient: 13 from localhost (Domain)
D [07/May/2012:14:55:02 +0100] Report: clients=1
D [07/May/2012:14:55:02 +0100] Report: jobs=0
D [07/May/2012:14:55:02 +0100] Report: jobs-active=0
D [07/May/2012:14:55:02 +0100] Report: printers=1
D [07/May/2012:14:55:02 +0100] Report: printers-implicit=0
D [07/May/2012:14:55:02 +0100] Report: stringpool-string-count=1077
D [07/May/2012:14:55:02 +0100] Report: stringpool-alloc-bytes=9048
D [07/May/2012:14:55:02 +0100] Report: stringpool-total-bytes=17224
D [07/May/2012:14:55:08 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:08 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:08 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:08 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:08 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:08 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:08 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:08 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 14 GET /printers/ML-3470-Series.ppd HTTP/1.1
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:08 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:08 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:08 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:08 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:08 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 14 POST / HTTP/1.1
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:08 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 14 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:08 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:08 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:08 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:08 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:08 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:09 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:09 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:09 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:09 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:09 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:09 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:09 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:09 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:09 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:09 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:09 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:09 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:09 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:09 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:10 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:10 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:10 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:10 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:10 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:10 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:10 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:10 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:10 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:10 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:10 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:10 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:10 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:10 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:11 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:11 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:11 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:11 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:11 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:11 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:11 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:11 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:11 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:11 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:11 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:11 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:11 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:11 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:12 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:12 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:12 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:12 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:12 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:12 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:12 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:12 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:12 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:12 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:12 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:12 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:12 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:12 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:12 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 14 POST /printers/ML-3470-Series HTTP/1.1
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:12 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 14 1.1 Print-Job 1
D [07/May/2012:14:55:12 +0100] Print-Job ipp://localhost:631/printers/ML-3470-Series
D [07/May/2012:14:55:12 +0100] [Job ???] Auto-typing file...
I [07/May/2012:14:55:12 +0100] [Job ???] Request file type is application/pdf.
D [07/May/2012:14:55:12 +0100] cupsdMarkDirty(----J-)
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:12 +0100] add_job: requesting-user-name="peter"
I [07/May/2012:14:55:12 +0100] [Job 4] Adding start banner page "none".
D [07/May/2012:14:55:12 +0100] Discarding unused job-created event...
D [07/May/2012:14:55:12 +0100] cupsdMarkDirty(----J-)
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [07/May/2012:14:55:12 +0100] [Job 4] Adding end banner page "none".
I [07/May/2012:14:55:12 +0100] [Job 4] File of type application/pdf queued by "peter".
D [07/May/2012:14:55:12 +0100] [Job 4] hold_until=0
I [07/May/2012:14:55:12 +0100] [Job 4] Queued on "ML-3470-Series" by "peter".
D [07/May/2012:14:55:12 +0100] cupsdMarkDirty(----J-)
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:12 +0100] cupsdMarkDirty(-----S)
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:12 +0100] [Job 4] job-sheets=none,none
D [07/May/2012:14:55:12 +0100] [Job 4] argv[0]="ML-3470-Series"
D [07/May/2012:14:55:12 +0100] [Job 4] argv[1]="4"
D [07/May/2012:14:55:12 +0100] [Job 4] argv[2]="peter"
D [07/May/2012:14:55:12 +0100] [Job 4] argv[3]="Myxoedema madness.pdf — Hypothyroidism Presenting as Psychosis: Myxedema Madness Revisited"
D [07/May/2012:14:55:12 +0100] [Job 4] argv[4]="1"
D [07/May/2012:14:55:12 +0100] [Job 4] argv[5]="number-up=1 PageSize=A4 Resolution=600x600dpi Duplex=DuplexNoTumble job-uuid=urn:uuid:c509ae6f-35b8-31c3-769c-820711db374d job-originating-host-name=localhost time-at-creation=1336398912 time-at-processing=1336398912 AP_D_InputSlot="
D [07/May/2012:14:55:12 +0100] [Job 4] argv[6]="/var/spool/cups/d00004-001"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[8]="HOME=/var/spool/cups/tmp"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[10]="SERVER_ADMIN=root@peter-Desktop"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[11]="SOFTWARE=CUPS/1.5.2"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[13]="USER=root"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[16]="IPP_PORT=631"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[17]="CHARSET=utf-8"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[18]="LANG=en_GB.UTF-8"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[19]="PPD=/etc/cups/ppd/ML-3470-Series.ppd"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[20]="RIP_MAX_CACHE=128m"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[21]="CONTENT_TYPE=application/pdf"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[22]="DEVICE_URI=usb://Samsung/ML-3470%20Series?serial=Z4ZBBABZ400502Y"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[23]="PRINTER_INFO=Samsung ML-3470 Series"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[24]="PRINTER_LOCATION=peter-Desktop"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[25]="PRINTER=ML-3470-Series"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[26]="PRINTER_STATE_REASONS=none"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[27]="CUPS_FILETYPE=document"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[28]="FINAL_CONTENT_TYPE=printer/ML-3470-Series"
D [07/May/2012:14:55:12 +0100] [Job 4] envp[29]="AUTH_I****"
I [07/May/2012:14:55:12 +0100] [Job 4] Started filter /usr/lib/cups/filter/pdftopdf (PID 5391)
I [07/May/2012:14:55:12 +0100] [Job 4] Started filter /usr/lib/cups/filter/foomatic-rip (PID 5392)
I [07/May/2012:14:55:12 +0100] [Job 4] Started backend /usr/lib/cups/backend/usb (PID 5393)
D [07/May/2012:14:55:12 +0100] Discarding unused job-state-changed event...
D [07/May/2012:14:55:12 +0100] Returning IPP successful-ok for Print-Job (ipp://localhost:631/printers/ML-3470-Series) from localhost
D [07/May/2012:14:55:12 +0100] [Job 4] print_device
D [07/May/2012:14:55:12 +0100] [Job 4] libusb_get_device_list=8
D [07/May/2012:14:55:12 +0100] [Job 4] STATE: +connecting-to-device
D [07/May/2012:14:55:12 +0100] cupsdMarkDirty(-----S)
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:12 +0100] [Job 4] Getting input from file 
D [07/May/2012:14:55:12 +0100] [Job 4] foomatic-rip version 4.0.15.251 running...
D [07/May/2012:14:55:12 +0100] [Job 4] Parsing PPD file ...
D [07/May/2012:14:55:12 +0100] [Job 4] Added option ColorSpace
D [07/May/2012:14:55:12 +0100] [Job 4] Added option PageSize
D [07/May/2012:14:55:12 +0100] [Job 4] CUPS page accounting disabled by driver.
D [07/May/2012:14:55:12 +0100] [Job 4] STATE: -connecting-to-device
D [07/May/2012:14:55:12 +0100] cupsdMarkDirty(-----S)
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files"
D [07/May/2012:14:55:12 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:12 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:12 +0100] [Job 4] Added option ImageableArea
D [07/May/2012:14:55:12 +0100] [Job 4] Added option PaperDimension
D [07/May/2012:14:55:12 +0100] [Job 4] Added option Duplex
D [07/May/2012:14:55:12 +0100] [Job 4] Added option Resolution
D [07/May/2012:14:55:12 +0100] [Job 4] Added option Font
D [07/May/2012:14:55:12 +0100] [Job 4] 
D [07/May/2012:14:55:12 +0100] [Job 4] Parameter Summary
D [07/May/2012:14:55:12 +0100] [Job 4] -----------------
D [07/May/2012:14:55:12 +0100] [Job 4] 
D [07/May/2012:14:55:12 +0100] [Job 4] Spooler: cups
D [07/May/2012:14:55:12 +0100] [Job 4] Printer: ML-3470-Series
D [07/May/2012:14:55:12 +0100] [Job 4] Shell: /bin/bash
D [07/May/2012:14:55:12 +0100] [Job 4] PPD file: /etc/cups/ppd/ML-3470-Series.ppd
D [07/May/2012:14:55:12 +0100] [Job 4] ATTR file: 
D [07/May/2012:14:55:12 +0100] [Job 4] Printer model: Samsung ML-3470D Foomatic/Postscript (recommended)
D [07/May/2012:14:55:12 +0100] [Job 4] Job title: Myxoedema madness.pdf — Hypothyroidism Presenting as Psychosis: Myxedema Madness Revisited
D [07/May/2012:14:55:12 +0100] [Job 4] File(s) to be printed:
D [07/May/2012:14:55:12 +0100] [Job 4] <STDIN>
D [07/May/2012:14:55:12 +0100] [Job 4] 
D [07/May/2012:14:55:12 +0100] [Job 4] Ghostscript extra search path ('GS_LIB'): /usr/share/cups/fonts
D [07/May/2012:14:55:12 +0100] [Job 4] Printing system options:
D [07/May/2012:14:55:12 +0100] [Job 4] Pondering option 'number-up=1'
D [07/May/2012:14:55:12 +0100] [Job 4] Unknown option number-up=1.
D [07/May/2012:14:55:12 +0100] [Job 4] Pondering option 'job-uuid=urn:uuid:c509ae6f-35b8-31c3-769c-820711db374d'
D [07/May/2012:14:55:12 +0100] [Job 4] Unknown option job-uuid=urn:uuid:c509ae6f-35b8-31c3-769c-820711db374d.
D [07/May/2012:14:55:12 +0100] [Job 4] Pondering option 'job-originating-host-name=localhost'
D [07/May/2012:14:55:12 +0100] [Job 4] Unknown option job-originating-host-name=localhost.
D [07/May/2012:14:55:12 +0100] [Job 4] Pondering option 'time-at-creation=1336398912'
D [07/May/2012:14:55:12 +0100] [Job 4] Unknown option time-at-creation=1336398912.
D [07/May/2012:14:55:12 +0100] [Job 4] Pondering option 'time-at-processing=1336398912'
D [07/May/2012:14:55:12 +0100] [Job 4] Unknown option time-at-processing=1336398912.
D [07/May/2012:14:55:12 +0100] [Job 4] Pondering option 'AP_D_InputSlot'
D [07/May/2012:14:55:12 +0100] [Job 4] Unknown boolean option "AP_D_InputSlot".
D [07/May/2012:14:55:12 +0100] [Job 4] Options from the PPD file:
D [07/May/2012:14:55:12 +0100] [Job 4] Pondering option 'PageSize=A4'
D [07/May/2012:14:55:12 +0100] [Job 4] Pondering option 'Resolution=600x600dpi'
D [07/May/2012:14:55:12 +0100] [Job 4] Pondering option 'Duplex=DuplexNoTumble'
D [07/May/2012:14:55:12 +0100] [Job 4] 
D [07/May/2012:14:55:12 +0100] [Job 4] ================================================
D [07/May/2012:14:55:12 +0100] [Job 4] 
D [07/May/2012:14:55:12 +0100] [Job 4] File: <STDIN>
D [07/May/2012:14:55:12 +0100] [Job 4] 
D [07/May/2012:14:55:12 +0100] [Job 4] ================================================
D [07/May/2012:14:55:12 +0100] [Job 4] 
I [07/May/2012:14:55:12 +0100] [Job 4] Sending data to printer.
D [07/May/2012:14:55:12 +0100] [Job 4] Set job-printer-state-message to "Sending data to printer.", current level=INFO
D [07/May/2012:14:55:12 +0100] Discarding unused job-progress event...
D [07/May/2012:14:55:12 +0100] cupsdMarkDirty(-----S)
D [07/May/2012:14:55:12 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:12 +0100] [Job 4] Filetype: PDF
D [07/May/2012:14:55:12 +0100] [Job 4] PostScript option found: PageSize=Letter: "<</PageSize[612 792]/ImagingBBox null>>setpagedevice"
D [07/May/2012:14:55:12 +0100] [Job 4] Driver does not understand PDF input, converting to PostScript
D [07/May/2012:14:55:12 +0100] [Job 4] Storing temporary files in /var/spool/cups/tmp
D [07/May/2012:14:55:12 +0100] PID 5391 (/usr/lib/cups/filter/pdftopdf) exited with no errors.
D [07/May/2012:14:55:12 +0100] [Job 4] Starting process "pdf-to-ps" (generation 1)
D [07/May/2012:14:55:12 +0100] [Job 4] Using image rendering resolution 600 dpi
D [07/May/2012:14:55:12 +0100] [Job 4] Started filter gs (PID 5397)
D [07/May/2012:14:55:12 +0100] [Job 4] Started filter pstops (PID 5398)
D [07/May/2012:14:55:13 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:13 +0100] cupsdReadClient: 14 POST / HTTP/1.1
D [07/May/2012:14:55:13 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:13 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:13 +0100] cupsdReadClient: 14 1.1 Get-Notifications 1
D [07/May/2012:14:55:13 +0100] Get-Notifications /
D [07/May/2012:14:55:13 +0100] cupsdIsAuthorized: requesting-user-name="peter"
D [07/May/2012:14:55:13 +0100] Returning IPP successful-ok for Get-Notifications (/) from localhost
D [07/May/2012:14:55:13 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [07/May/2012:14:55:13 +0100] cupsdReadClient: 14 WAITING Closing on EOF
D [07/May/2012:14:55:13 +0100] cupsdCloseClient: 14
D [07/May/2012:14:55:13 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:13 +0100] cupsdAcceptClient: 14 from localhost (Domain)
D [07/May/2012:14:55:13 +0100] cupsdReadClient: 14 POST / HTTP/1.1
D [07/May/2012:14:55:13 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:13 +0100] cupsdAuthorize: Authorized as peter using PeerCred
D [07/May/2012:14:55:13 +0100] cupsdReadClient: 14 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:13 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:13 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:13 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [07/May/2012:14:55:13 +0100] cupsdReadClient: 14 POST / HTTP/1.1
D [07/May/2012:14:55:13 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:13 +0100] cupsdAuthorize: Authorized as peter using PeerCred
D [07/May/2012:14:55:13 +0100] cupsdReadClient: 14 1.1 CUPS-Get-Classes 1
D [07/May/2012:14:55:13 +0100] CUPS-Get-Classes
D [07/May/2012:14:55:13 +0100] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from localhost
D [07/May/2012:14:55:13 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [07/May/2012:14:55:13 +0100] cupsdReadClient: 14 POST / HTTP/1.1
D [07/May/2012:14:55:13 +0100] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:13 +0100] cupsdAuthorize: Authorized as peter using PeerCred
D [07/May/2012:14:55:13 +0100] cupsdReadClient: 14 1.1 CUPS-Get-Default 1
D [07/May/2012:14:55:13 +0100] CUPS-Get-Default
D [07/May/2012:14:55:13 +0100] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [07/May/2012:14:55:13 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [07/May/2012:14:55:13 +0100] [Job 4] Page = 595x842; 18,36 to 577,806
D [07/May/2012:14:55:13 +0100] [Job 4] slow_collate=0, slow_duplex=0, slow_order=0
D [07/May/2012:14:55:13 +0100] [Job 4] Before copy_comments - %!PS-Adobe-3.0
D [07/May/2012:14:55:13 +0100] [Job 4] %!PS-Adobe-3.0
D [07/May/2012:14:55:13 +0100] [Job 4] %%BoundingBox: 0 0 595 842
D [07/May/2012:14:55:13 +0100] [Job 4] %%Creator: GPL Ghostscript 905 (ps2write)
D [07/May/2012:14:55:13 +0100] [Job 4] %%LanguageLevel: 2
D [07/May/2012:14:55:13 +0100] [Job 4] %%CreationDate: D:20120507145512+01'00'
D [07/May/2012:14:55:13 +0100] [Job 4] %%Pages: 7
D [07/May/2012:14:55:13 +0100] [Job 4] %%EndComments
D [07/May/2012:14:55:13 +0100] [Job 4] Before copy_prolog - %%BeginProlog
D [07/May/2012:14:55:13 +0100] [Job 4] Filetype: PostScript
D [07/May/2012:14:55:13 +0100] [Job 4] Reading PostScript input ...
D [07/May/2012:14:55:13 +0100] [Job 4] --> This document is DSC-conforming!
D [07/May/2012:14:55:13 +0100] [Job 4] Found %RBINumCopies: 1
D [07/May/2012:14:55:13 +0100] [Job 4] 
D [07/May/2012:14:55:13 +0100] [Job 4] -----------
D [07/May/2012:14:55:13 +0100] [Job 4] Found: %%BeginProlog
D [07/May/2012:14:55:13 +0100] [Job 4] Inserting option code into "Prolog" section.
D [07/May/2012:14:55:13 +0100] [Job 4] Before copy_setup - %%Page: 1 1
D [07/May/2012:14:55:13 +0100] [Job 4] Before page loop - %%Page: 1 1
D [07/May/2012:14:55:13 +0100] [Job 4] Copying page 1...
D [07/May/2012:14:55:13 +0100] [Job 4] pagew = 559.0, pagel = 770.0
D [07/May/2012:14:55:13 +0100] [Job 4] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [07/May/2012:14:55:13 +0100] [Job 4] PageLeft = 18.0, PageRight = 577.0
D [07/May/2012:14:55:13 +0100] [Job 4] PageTop = 806.0, PageBottom = 36.0
D [07/May/2012:14:55:13 +0100] [Job 4] PageWidth = 595.0, PageLength = 842.0
D [07/May/2012:14:55:13 +0100] [Job 4] Copying page 2...
D [07/May/2012:14:55:13 +0100] [Job 4] pagew = 559.0, pagel = 770.0
D [07/May/2012:14:55:13 +0100] [Job 4] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [07/May/2012:14:55:13 +0100] [Job 4] PageLeft = 18.0, PageRight = 577.0
D [07/May/2012:14:55:13 +0100] [Job 4] PageTop = 806.0, PageBottom = 36.0
D [07/May/2012:14:55:13 +0100] [Job 4] PageWidth = 595.0, PageLength = 842.0
D [07/May/2012:14:55:13 +0100] [Job 4] Copying page 3...
D [07/May/2012:14:55:13 +0100] [Job 4] Found: %%EndProlog
D [07/May/2012:14:55:13 +0100] [Job 4] 
D [07/May/2012:14:55:13 +0100] [Job 4] -----------
D [07/May/2012:14:55:13 +0100] [Job 4] Found: %%BeginSetup
D [07/May/2012:14:55:13 +0100] [Job 4] Found: %%BeginFeature: *Resolution 600x600dpi
D [07/May/2012:14:55:13 +0100] [Job 4] Option: Resolution=600x600dpi
D [07/May/2012:14:55:13 +0100] [Job 4] --> Option will be set by PostScript interpreter
D [07/May/2012:14:55:13 +0100] [Job 4] Found: %%BeginFeature: *PageSize A4
D [07/May/2012:14:55:13 +0100] [Job 4] Option: PageSize=A4
D [07/May/2012:14:55:13 +0100] [Job 4] --> Option will be set by PostScript interpreter
D [07/May/2012:14:55:13 +0100] [Job 4] Found: %%BeginFeature: *Duplex None
D [07/May/2012:14:55:13 +0100] [Job 4] Option: Duplex=None
D [07/May/2012:14:55:13 +0100] [Job 4] --> Option will be set by PostScript interpreter
D [07/May/2012:14:55:13 +0100] [Job 4] Found: %%EndSetup
D [07/May/2012:14:55:13 +0100] [Job 4] Inserting option code into "Setup" section.
D [07/May/2012:14:55:13 +0100] [Job 4] 
D [07/May/2012:14:55:13 +0100] [Job 4] -----------
D [07/May/2012:14:55:13 +0100] [Job 4] New page: %%Page: 1 1
D [07/May/2012:14:55:13 +0100] [Job 4] 
D [07/May/2012:14:55:13 +0100] [Job 4] Found: %%BeginPageSetup
D [07/May/2012:14:55:13 +0100] [Job 4] Inserting option code into "PageSetup" section.
D [07/May/2012:14:55:13 +0100] [Job 4] pagew = 559.0, pagel = 770.0
D [07/May/2012:14:55:13 +0100] [Job 4] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [07/May/2012:14:55:13 +0100] [Job 4] New page found but previous not printed, print it now.
D [07/May/2012:14:55:13 +0100] [Job 4] Found: %%Page: 2 2
D [07/May/2012:14:55:13 +0100] [Job 4] --> Output goes directly to the renderer now.
D [07/May/2012:14:55:13 +0100] [Job 4] 
D [07/May/2012:14:55:13 +0100] [Job 4] PageLeft = 18.0, PageRight = 577.0
D [07/May/2012:14:55:13 +0100] [Job 4] PageTop = 806.0, PageBottom = 36.0
D [07/May/2012:14:55:13 +0100] [Job 4] PageWidth = 595.0, PageLength = 842.0
D [07/May/2012:14:55:13 +0100] [Job 4] Copying page 4...
D [07/May/2012:14:55:13 +0100] [Job 4] pagew = 559.0, pagel = 770.0
D [07/May/2012:14:55:13 +0100] [Job 4] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [07/May/2012:14:55:13 +0100] [Job 4] PageLeft = 18.0, PageRight = 577.0
D [07/May/2012:14:55:13 +0100] [Job 4] PageTop = 806.0, PageBottom = 36.0
D [07/May/2012:14:55:13 +0100] [Job 4] PageWidth = 595.0, PageLength = 842.0
D [07/May/2012:14:55:13 +0100] [Job 4] 
D [07/May/2012:14:55:13 +0100] [Job 4] Starting renderer with command: "cat"
D [07/May/2012:14:55:13 +0100] [Job 4] Starting process "kid3" (generation 1)
D [07/May/2012:14:55:13 +0100] [Job 4] Starting process "kid4" (generation 2)
D [07/May/2012:14:55:13 +0100] [Job 4] Starting process "renderer" (generation 2)
D [07/May/2012:14:55:13 +0100] [Job 4] JCL: %-12345X@PJL
D [07/May/2012:14:55:13 +0100] [Job 4] <job data> 
D [07/May/2012:14:55:13 +0100] [Job 4] 
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:13 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] -----------
D [07/May/2012:14:55:14 +0100] [Job 4] New page: %%Page: 2 2
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 2 2
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes to the FIFO buffer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%BeginPageSetup
D [07/May/2012:14:55:14 +0100] [Job 4] Inserting option code into "PageSetup" section.
D [07/May/2012:14:55:14 +0100] [Job 4] Copying page 5...
D [07/May/2012:14:55:14 +0100] [Job 4] pagew = 559.0, pagel = 770.0
D [07/May/2012:14:55:14 +0100] [Job 4] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [07/May/2012:14:55:14 +0100] [Job 4] PageLeft = 18.0, PageRight = 577.0
D [07/May/2012:14:55:14 +0100] [Job 4] PageTop = 806.0, PageBottom = 36.0
D [07/May/2012:14:55:14 +0100] [Job 4] PageWidth = 595.0, PageLength = 842.0
D [07/May/2012:14:55:14 +0100] [Job 4] New page found but previous not printed, print it now.
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 3 3
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes directly to the renderer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] -----------
D [07/May/2012:14:55:14 +0100] [Job 4] New page: %%Page: 3 3
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 3 3
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes to the FIFO buffer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%BeginPageSetup
D [07/May/2012:14:55:14 +0100] [Job 4] Inserting option code into "PageSetup" section.
D [07/May/2012:14:55:14 +0100] [Job 4] New page found but previous not printed, print it now.
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 4 4
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes directly to the renderer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] Copying page 6...
D [07/May/2012:14:55:14 +0100] [Job 4] pagew = 559.0, pagel = 770.0
D [07/May/2012:14:55:14 +0100] [Job 4] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [07/May/2012:14:55:14 +0100] [Job 4] PageLeft = 18.0, PageRight = 577.0
D [07/May/2012:14:55:14 +0100] [Job 4] PageTop = 806.0, PageBottom = 36.0
D [07/May/2012:14:55:14 +0100] [Job 4] PageWidth = 595.0, PageLength = 842.0
D [07/May/2012:14:55:14 +0100] [Job 4] PID 5397 (gs) exited with no errors.
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] -----------
D [07/May/2012:14:55:14 +0100] [Job 4] New page: %%Page: 4 4
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 4 4
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes to the FIFO buffer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%BeginPageSetup
D [07/May/2012:14:55:14 +0100] [Job 4] Inserting option code into "PageSetup" section.
D [07/May/2012:14:55:14 +0100] [Job 4] Copying page 7...
D [07/May/2012:14:55:14 +0100] [Job 4] pagew = 559.0, pagel = 770.0
D [07/May/2012:14:55:14 +0100] [Job 4] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [07/May/2012:14:55:14 +0100] [Job 4] PageLeft = 18.0, PageRight = 577.0
D [07/May/2012:14:55:14 +0100] [Job 4] PageTop = 806.0, PageBottom = 36.0
D [07/May/2012:14:55:14 +0100] [Job 4] PageWidth = 595.0, PageLength = 842.0
D [07/May/2012:14:55:14 +0100] [Job 4] New page found but previous not printed, print it now.
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 5 5
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes directly to the renderer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] -----------
D [07/May/2012:14:55:14 +0100] [Job 4] New page: %%Page: 5 5
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 5 5
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes to the FIFO buffer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%BeginPageSetup
D [07/May/2012:14:55:14 +0100] [Job 4] Inserting option code into "PageSetup" section.
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 7 pages...
D [07/May/2012:14:55:14 +0100] [Job 4] PID 5398 (pstops) exited with no errors.
D [07/May/2012:14:55:14 +0100] [Job 4] New page found but previous not printed, print it now.
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 6 6
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes directly to the renderer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] -----------
D [07/May/2012:14:55:14 +0100] [Job 4] New page: %%Page: 6 6
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 6 6
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes to the FIFO buffer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%BeginPageSetup
D [07/May/2012:14:55:14 +0100] [Job 4] Inserting option code into "PageSetup" section.
D [07/May/2012:14:55:14 +0100] [Job 4] New page found but previous not printed, print it now.
D [07/May/2012:14:55:14 +0100] [Job 4] Found: %%Page: 7 7
D [07/May/2012:14:55:14 +0100] [Job 4] --> Output goes directly to the renderer now.
D [07/May/2012:14:55:14 +0100] [Job 4] 
D [07/May/2012:14:55:14 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:14 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] 
D [07/May/2012:14:55:15 +0100] [Job 4] -----------
D [07/May/2012:14:55:15 +0100] [Job 4] New page: %%Page: 7 7
D [07/May/2012:14:55:15 +0100] [Job 4] Found: %%Page: 7 7
D [07/May/2012:14:55:15 +0100] [Job 4] --> Output goes to the FIFO buffer now.
D [07/May/2012:14:55:15 +0100] [Job 4] 
D [07/May/2012:14:55:15 +0100] [Job 4] 
D [07/May/2012:14:55:15 +0100] [Job 4] Found: %%BeginPageSetup
D [07/May/2012:14:55:15 +0100] [Job 4] Inserting option code into "PageSetup" section.
D [07/May/2012:14:55:15 +0100] [Job 4] Flushing FIFO.
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] 
D [07/May/2012:14:55:15 +0100] [Job 4] Closing renderer
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:15 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] renderer exited with status 0
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] kid4 exited with status 0
D [07/May/2012:14:55:16 +0100] [Job 4] kid3 finished
D [07/May/2012:14:55:16 +0100] [Job 4] kid3 exited with status 0
D [07/May/2012:14:55:16 +0100] [Job 4] pdf-to-ps exited with status 0
D [07/May/2012:14:55:16 +0100] [Job 4] 
D [07/May/2012:14:55:16 +0100] [Job 4] Closing foomatic-rip.
D [07/May/2012:14:55:16 +0100] PID 5392 (/usr/lib/cups/filter/foomatic-rip) exited with no errors.
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:16 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Read 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Wrote 8192 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Read 4493 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Wrote 4493 bytes of print data...
D [07/May/2012:14:55:17 +0100] [Job 4] Sent 463245 bytes...
D [07/May/2012:14:55:17 +0100] [Job 4] Waiting for read thread to exit...
D [07/May/2012:14:55:24 +0100] [Job 4] Read thread still active, aborting the pending read...
D [07/May/2012:14:55:25 +0100] PID 5393 (/usr/lib/cups/backend/usb) exited with no errors.
D [07/May/2012:14:55:25 +0100] Discarding unused job-completed event...
I [07/May/2012:14:55:25 +0100] [Job 4] Job completed.
D [07/May/2012:14:55:25 +0100] cupsdMarkDirty(----J-)
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:25 +0100] cupsdMarkDirty(-----S)
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:25 +0100] cupsdAcceptClient: 17 from localhost (Domain)
D [07/May/2012:14:55:25 +0100] cupsdReadClient: 17 POST / HTTP/1.1
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Printing jobs and dirty files"
D [07/May/2012:14:55:25 +0100] cupsdAuthorize: No authentication data provided.
D [07/May/2012:14:55:25 +0100] cupsdReadClient: 17 1.1 Get-Notifications 1
D [07/May/2012:14:55:25 +0100] Get-Notifications /
D [07/May/2012:14:55:25 +0100] cupsdIsAuthorized: requesting-user-name="peter"
D [07/May/2012:14:55:25 +0100] Returning IPP successful-ok for Get-Notifications (/) from localhost
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:25 +0100] cupsdReadClient: 17 WAITING Closing on EOF
D [07/May/2012:14:55:25 +0100] cupsdCloseClient: 17
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [07/May/2012:14:55:25 +0100] cupsdReadClient: 14 POST / HTTP/1.1
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:25 +0100] cupsdAuthorize: Authorized as peter using PeerCred
D [07/May/2012:14:55:25 +0100] cupsdReadClient: 14 1.1 CUPS-Get-Printers 1
D [07/May/2012:14:55:25 +0100] CUPS-Get-Printers
D [07/May/2012:14:55:25 +0100] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:25 +0100] cupsdReadClient: 14 POST / HTTP/1.1
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:25 +0100] cupsdAuthorize: Authorized as peter using PeerCred
D [07/May/2012:14:55:25 +0100] cupsdReadClient: 14 1.1 CUPS-Get-Classes 1
D [07/May/2012:14:55:25 +0100] CUPS-Get-Classes
D [07/May/2012:14:55:25 +0100] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from localhost
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:25 +0100] cupsdReadClient: 14 POST / HTTP/1.1
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [07/May/2012:14:55:25 +0100] cupsdAuthorize: Authorized as peter using PeerCred
D [07/May/2012:14:55:25 +0100] cupsdReadClient: 14 1.1 CUPS-Get-Default 1
D [07/May/2012:14:55:25 +0100] CUPS-Get-Default
D [07/May/2012:14:55:25 +0100] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [07/May/2012:14:55:25 +0100] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [07/May/2012:14:55:26 +0100] [Job 4] Unloading...
I [07/May/2012:14:55:33 +0100] Generating printcap /var/run/cups/printcap...
I [07/May/2012:14:55:33 +0100] Saving job.cache...
I [07/May/2012:14:55:34 +0100] Saving subscriptions.conf...
D [07/May/2012:14:55:34 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"