Problems printing to remote (LPR) printer

Sat Feb 4 15:28:21 PST 2012

> Tom Watson wrote:
>
> >> Tom Watson wrote:
> >>
> >> > I have a remote printer attached to my nice router.  It has a nice
> >> > print queue, and I have been able to print to it successfully using an
> >> > older
> >> > version of CPUP (v1.1.x it says on the test page).  The printer is a
> >> > Cannon ip1600, and the URI that I use is "lpr://router/lpUSB0".  I have
> >> > done a bit of investigation, and using TCPDUMP I was able to see that
> >> > the "good" instance (the actual system is a Fedora 8 Linux box) emits
> >> > about
> >> > 1.9 Mbytes of data to the printer.  The "not working" instance (CUPS
> >> > 1.5 from Fedora 16) emits around 176kbytes, and the printer swallows
> >> > the data in about 1 second or so, with no output to the printer.
> >> >
> >> > Something is not right in my neighborhood, as this DOES work with an
> >> > earlier instance of CUPS.  The only thing that I think that is
> >> > happening is that somehow the driver doesn't go through the Postscript
> >> > (Ghostscript) interpreter to get the raster data for the printer.
> >> >
> >> > Thanks for the assistance.
> >>
> >> Can you please supply an error_log (log level debug) for a test print of
> >> both the cups 1.1.x and cups 1.5.0 system?
> >>
> >> Helge
> >>
> >
> >
> > Tale of two error_log files (from directory /var/log/cups):
> > [cups 1.1.x, that's what it says on the test page, but it may be 1.3.9]
> > I [04/Feb/2012:06:08:25 -0800] [Job ???] Request file type is
> > application/postscript. I [04/Feb/2012:06:08:25 -0800] [Job 1396] Adding
> > start banner page "none". I [04/Feb/2012:06:08:25 -0800] [Job 1396] Adding
> > end banner page "none". I [04/Feb/2012:06:08:25 -0800] [Job 1396] File of
> > type application/postscript queued by "root". I [04/Feb/2012:06:08:25
> > -0800] [Job 1396] Queued on "iP1600" by "root". I [04/Feb/2012:06:08:25
> > -0800] [Job 1396] Started filter /usr/lib/cups/filter/pstops (PID 24349) I
> > [04/Feb/2012:06:08:25 -0800] [Job 1396] Started filter
> > /usr/lib/cups/filter/pstocanonij (PID 24350) I [04/Feb/2012:06:08:25
> > -0800] [Job 1396] Started backend /usr/lib/cups/backend/lpd (PID 24351) I
> > [04/Feb/2012:06:09:17 -0800] [Job 1396] Completed successfully.
> >
> > [cups 1.5.0]
> > (no error_log entries for test page)
> > [page_log]
> > ip1600 root 18 [04/Feb/2012:06:06:22 -0800] 1 1 - localhost Test Page - -
> > [access_log]
> > localhost - - [04/Feb/2012:06:06:21 -0800] "POST /printers/ip1600
> > HTTP/1.1" 200 446 Print-Job successful-ok
> >
> > Does this seem right?  Am I giving you clues?
> >
> > Thanks again.
>
> For the 1.5.0 case, please execute
> cupsctl --debug-logging
> before
> and
> cupsctl --no-debug-logging
> after printing the test page.
>
> Helge
>
OK, you asked for it.  It is quite long!
>>>>>  Log file
I [04/Feb/2012:15:15:14 -0800] Listening to [v1.::1]:631 (IPv6)
I [04/Feb/2012:15:15:14 -0800] Listening to 127.0.0.1:631 (IPv4)
I [04/Feb/2012:15:15:14 -0800] Listening to /var/run/cups/cups.sock (Domain)
W [04/Feb/2012:15:15:14 -0800] No limit for Cancel-Jobs defined in policy default - using Pause-Printer's policy.
W [04/Feb/2012:15:15:14 -0800] No limit for Cancel-My-Jobs defined in policy default - using Send-Document's policy.
W [04/Feb/2012:15:15:14 -0800] No limit for Close-Job defined in policy default - using Send-Document's policy.
W [04/Feb/2012:15:15:14 -0800] No JobPrivateAccess defined in policy default - using defaults.
W [04/Feb/2012:15:15:14 -0800] No JobPrivateValues defined in policy default - using defaults.
W [04/Feb/2012:15:15:14 -0800] No SubscriptionPrivateAccess defined in policy default - using defaults.
W [04/Feb/2012:15:15:14 -0800] No SubscriptionPrivateValues defined in policy default - using defaults.
W [04/Feb/2012:15:15:14 -0800] No limit for Cancel-Jobs defined in policy authenticated - using Pause-Printer's policy.
W [04/Feb/2012:15:15:14 -0800] No limit for Cancel-My-Jobs defined in policy authenticated - using Send-Document's policy.
W [04/Feb/2012:15:15:14 -0800] No limit for Close-Job defined in policy authenticated - using Send-Document's policy.
W [04/Feb/2012:15:15:14 -0800] No JobPrivateAccess defined in policy authenticated - using defaults.
W [04/Feb/2012:15:15:14 -0800] No JobPrivateValues defined in policy authenticated - using defaults.
W [04/Feb/2012:15:15:14 -0800] No SubscriptionPrivateAccess defined in policy authenticated - using defaults.
W [04/Feb/2012:15:15:14 -0800] No SubscriptionPrivateValues defined in policy authenticated - using defaults.
I [04/Feb/2012:15:15:14 -0800] Remote access is disabled.
D [04/Feb/2012:15:15:14 -0800] Added auto ServerAlias nancy2
I [04/Feb/2012:15:15:14 -0800] Loaded configuration file "/etc/cups/cupsd.conf"
I [04/Feb/2012:15:15:14 -0800] Using default TempDir of /var/spool/cups/tmp...
I [04/Feb/2012:15:15:14 -0800] Configured for up to 100 clients.
I [04/Feb/2012:15:15:14 -0800] Allowing up to 100 client connections per host.
I [04/Feb/2012:15:15:14 -0800] Using policy "default" as the default.
D [04/Feb/2012:15:15:14 -0800] load_ppd: Loading /var/cache/cups/deskjet.data...
D [04/Feb/2012:15:15:14 -0800] Calling FindDeviceById(cups-deskjet)
D [04/Feb/2012:15:15:14 -0800] Calling DeleteDevice(cups-deskjet)
D [04/Feb/2012:15:15:14 -0800] failed to DeleteDevice: org.freedesktop.DBus.Error.InvalidArgs:Type of message, `(s)', does not match expected type `(o)'
D [04/Feb/2012:15:15:14 -0800] Using profile id of deskjet-Gray..
D [04/Feb/2012:15:15:14 -0800] Calling CreateProfile(deskjet-Gray..,temp)
W [04/Feb/2012:15:15:14 -0800] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'deskjet-Gray..' already exists
D [04/Feb/2012:15:15:14 -0800] Using profile id of deskjet-RGB..
D [04/Feb/2012:15:15:14 -0800] Calling CreateProfile(deskjet-RGB..,temp)
W [04/Feb/2012:15:15:14 -0800] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'deskjet-RGB..' already exists
I [04/Feb/2012:15:15:14 -0800] Registering ICC color profiles for "deskjet"
D [04/Feb/2012:15:15:14 -0800] Calling CreateDevice(cups-deskjet,temp)
W [04/Feb/2012:15:15:14 -0800] failed to CreateDevice: org.freedesktop.ColorManager.AlreadyExists:device id 'cups-deskjet' already exists
D [04/Feb/2012:15:15:14 -0800] cupsdRegisterPrinter(p=0xb8910500(deskjet))
D [04/Feb/2012:15:15:14 -0800] load_ppd: Loading /var/cache/cups/HP_G85.data...
D [04/Feb/2012:15:15:14 -0800] Calling FindDeviceById(cups-HP_G85)
D [04/Feb/2012:15:15:14 -0800] Calling DeleteDevice(cups-HP_G85)
D [04/Feb/2012:15:15:14 -0800] failed to DeleteDevice: org.freedesktop.DBus.Error.InvalidArgs:Type of message, `(s)', does not match expected type `(o)'
D [04/Feb/2012:15:15:14 -0800] Using profile id of HP_G85-Gray..
D [04/Feb/2012:15:15:14 -0800] Calling CreateProfile(HP_G85-Gray..,temp)
W [04/Feb/2012:15:15:14 -0800] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'HP_G85-Gray..' already exists
D [04/Feb/2012:15:15:14 -0800] Using profile id of HP_G85-RGB..
D [04/Feb/2012:15:15:14 -0800] Calling CreateProfile(HP_G85-RGB..,temp)
W [04/Feb/2012:15:15:14 -0800] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'HP_G85-RGB..' already exists
I [04/Feb/2012:15:15:14 -0800] Registering ICC color profiles for "HP_G85"
D [04/Feb/2012:15:15:14 -0800] Calling CreateDevice(cups-HP_G85,temp)
W [04/Feb/2012:15:15:14 -0800] failed to CreateDevice: org.freedesktop.ColorManager.AlreadyExists:device id 'cups-HP_G85' already exists
D [04/Feb/2012:15:15:14 -0800] cupsdRegisterPrinter(p=0xb89f0c30(HP_G85))
D [04/Feb/2012:15:15:14 -0800] load_ppd: Loading /var/cache/cups/ip1600.data...
D [04/Feb/2012:15:15:14 -0800] Calling FindDeviceById(cups-ip1600)
D [04/Feb/2012:15:15:14 -0800] Calling DeleteDevice(cups-ip1600)
D [04/Feb/2012:15:15:14 -0800] failed to DeleteDevice: org.freedesktop.DBus.Error.InvalidArgs:Type of message, `(s)', does not match expected type `(o)'
W [04/Feb/2012:15:15:14 -0800] no access to /System/Library/ColorSync/Profiles/sRGB Profile.icc
W [04/Feb/2012:15:15:14 -0800] no access to /System/Library/ColorSync/Profiles/sRGB Profile.icc
W [04/Feb/2012:15:15:14 -0800] no access to /System/Library/ColorSync/Profiles/Generic CMYK Profile.icc
D [04/Feb/2012:15:15:14 -0800] Using profile id of ip1600-Gray..
D [04/Feb/2012:15:15:14 -0800] Calling CreateProfile(ip1600-Gray..,temp)
W [04/Feb/2012:15:15:14 -0800] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'ip1600-Gray..' already exists
D [04/Feb/2012:15:15:14 -0800] Using profile id of ip1600-RGB..
D [04/Feb/2012:15:15:14 -0800] Calling CreateProfile(ip1600-RGB..,temp)
W [04/Feb/2012:15:15:14 -0800] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'ip1600-RGB..' already exists
I [04/Feb/2012:15:15:14 -0800] Registering ICC color profiles for "ip1600"
D [04/Feb/2012:15:15:14 -0800] Calling CreateDevice(cups-ip1600,temp)
W [04/Feb/2012:15:15:14 -0800] failed to CreateDevice: org.freedesktop.ColorManager.AlreadyExists:device id 'cups-ip1600' already exists
D [04/Feb/2012:15:15:14 -0800] cupsdRegisterPrinter(p=0xb8933c40(ip1600))
D [04/Feb/2012:15:15:14 -0800] cupsdMarkDirty(---p--)
D [04/Feb/2012:15:15:14 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy"
I [04/Feb/2012:15:15:14 -0800] Partial reload complete.
D [04/Feb/2012:15:15:14 -0800] systemd_checkin: Matched existing listener /var/run/cups/cups.sock with fd 3...
D [04/Feb/2012:15:15:14 -0800] systemd_checkin: Adding new listener [v1.::] with fd 4...
E [04/Feb/2012:15:15:14 -0800] Unable to bind socket for address [v1.::1]:631 - Address already in use.
I [04/Feb/2012:15:15:14 -0800] Listening to 127.0.0.1:631 on fd 12...
I [04/Feb/2012:15:15:14 -0800] Listening to /var/run/cups/cups.sock:631 on fd 3...
I [04/Feb/2012:15:15:14 -0800] Listening to [v1.::]:631 on fd 4...
I [04/Feb/2012:15:15:14 -0800] Resuming new connection processing...
D [04/Feb/2012:15:15:14 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:14 -0800] Discarding unused server-restarted event...
D [04/Feb/2012:15:15:15 -0800] Report: clients=0
D [04/Feb/2012:15:15:15 -0800] Report: jobs=18
D [04/Feb/2012:15:15:15 -0800] Report: jobs-active=0
D [04/Feb/2012:15:15:15 -0800] Report: printers=3
D [04/Feb/2012:15:15:15 -0800] Report: printers-implicit=0
D [04/Feb/2012:15:15:15 -0800] Report: stringpool-string-count=10599
D [04/Feb/2012:15:15:15 -0800] Report: stringpool-alloc-bytes=16536
D [04/Feb/2012:15:15:15 -0800] Report: stringpool-total-bytes=196176
D [04/Feb/2012:15:15:30 -0800] cupsdAcceptClient: skipping getpeercon()
D [04/Feb/2012:15:15:30 -0800] cupsdAcceptClient: 16 from localhost (Domain)
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 1.1 CUPS-Get-Printers 1
D [04/Feb/2012:15:15:30 -0800] CUPS-Get-Printers
D [04/Feb/2012:15:15:30 -0800] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 1.1 CUPS-Get-Classes 1
D [04/Feb/2012:15:15:30 -0800] CUPS-Get-Classes
D [04/Feb/2012:15:15:30 -0800] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from localhost
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 1.1 CUPS-Get-Default 1
D [04/Feb/2012:15:15:30 -0800] CUPS-Get-Default
D [04/Feb/2012:15:15:30 -0800] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 1.1 Get-Printer-Attributes 1
D [04/Feb/2012:15:15:30 -0800] Get-Printer-Attributes ipp://localhost/printers/ip1600
D [04/Feb/2012:15:15:30 -0800] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/ip1600) from localhost
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 1.1 CUPS-Get-Default 1
D [04/Feb/2012:15:15:30 -0800] CUPS-Get-Default
D [04/Feb/2012:15:15:30 -0800] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 1.1 Get-Printer-Attributes 1
D [04/Feb/2012:15:15:30 -0800] Get-Printer-Attributes ipp://localhost/printers/ip1600
D [04/Feb/2012:15:15:30 -0800] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/ip1600) from localhost
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:30 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:15:30 -0800] cupsdReadClient: 16 1.1 CUPS-Get-Default 1
D [04/Feb/2012:15:15:30 -0800] CUPS-Get-Default
D [04/Feb/2012:15:15:30 -0800] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [04/Feb/2012:15:15:30 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:15:32 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:15:32 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:32 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:15:32 -0800] cupsdReadClient: 16 1.1 Get-Printer-Attributes 1
D [04/Feb/2012:15:15:32 -0800] Get-Printer-Attributes ipp://localhost/printers/ip1600
D [04/Feb/2012:15:15:32 -0800] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost/printers/ip1600) from localhost
D [04/Feb/2012:15:15:32 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:15:32 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:15:32 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files"
D [04/Feb/2012:15:15:32 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:15:32 -0800] cupsdReadClient: 16 1.1 CUPS-Get-Default 1
D [04/Feb/2012:15:15:32 -0800] CUPS-Get-Default
D [04/Feb/2012:15:15:32 -0800] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost
D [04/Feb/2012:15:15:32 -0800] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files"
I [04/Feb/2012:15:15:45 -0800] Generating printcap /etc/printcap...
D [04/Feb/2012:15:15:45 -0800] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
D [04/Feb/2012:15:16:39 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [04/Feb/2012:15:16:39 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:16:39 -0800] Report: clients=1
D [04/Feb/2012:15:16:39 -0800] Report: jobs=18
D [04/Feb/2012:15:16:39 -0800] Report: jobs-active=0
D [04/Feb/2012:15:16:39 -0800] Report: printers=3
D [04/Feb/2012:15:16:39 -0800] Report: printers-implicit=0
D [04/Feb/2012:15:16:39 -0800] Report: stringpool-string-count=10602
D [04/Feb/2012:15:16:39 -0800] Report: stringpool-alloc-bytes=16584
D [04/Feb/2012:15:16:39 -0800] Report: stringpool-total-bytes=196224
D [04/Feb/2012:15:16:39 -0800] cupsdReadClient: 16 1.1 Get-Jobs 1
D [04/Feb/2012:15:16:39 -0800] Get-Jobs ipp://localhost/printers/
D [04/Feb/2012:15:16:39 -0800] Returning IPP successful-ok for Get-Jobs (ipp://localhost/printers/) from localhost
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Not busy", busy="Active clients"
D [04/Feb/2012:15:16:39 -0800] cupsdReadClient: 16 POST /printers/ip1600 HTTP/1.1
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [04/Feb/2012:15:16:39 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:16:39 -0800] cupsdReadClient: 16 1.1 Print-Job 1
D [04/Feb/2012:15:16:39 -0800] Print-Job ipp://localhost/printers/ip1600
D [04/Feb/2012:15:16:39 -0800] [Job ???] Auto-typing file...
I [04/Feb/2012:15:16:39 -0800] [Job ???] Request file type is application/vnd.cups-banner.
D [04/Feb/2012:15:16:39 -0800] add_job: setting context of job to UNKNOWN SL
D [04/Feb/2012:15:16:39 -0800] cupsdMarkDirty(----J-)
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients"
D [04/Feb/2012:15:16:39 -0800] add_job: requesting-user-name="root"
D [04/Feb/2012:15:16:39 -0800] Adding default job-sheets values "none,none"...
I [04/Feb/2012:15:16:39 -0800] [Job 19] Adding start banner page "none".
D [04/Feb/2012:15:16:39 -0800] Discarding unused job-created event...
D [04/Feb/2012:15:16:39 -0800] cupsdMarkDirty(----J-)
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
I [04/Feb/2012:15:16:39 -0800] [Job 19] Adding end banner page "none".
I [04/Feb/2012:15:16:39 -0800] [Job 19] File of type application/vnd.cups-banner queued by "root".
D [04/Feb/2012:15:16:39 -0800] [Job 19] hold_until=0
I [04/Feb/2012:15:16:39 -0800] [Job 19] Queued on "ip1600" by "root".
D [04/Feb/2012:15:16:39 -0800] cupsdMarkDirty(----J-)
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:16:39 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:39 -0800] [Job 19] job-sheets=none,none
D [04/Feb/2012:15:16:39 -0800] [Job 19] argv[0]="ip1600"
D [04/Feb/2012:15:16:39 -0800] [Job 19] argv[1]="19"
D [04/Feb/2012:15:16:39 -0800] [Job 19] argv[2]="root"
D [04/Feb/2012:15:16:39 -0800] [Job 19] argv[3]="Test Page"
D [04/Feb/2012:15:16:39 -0800] [Job 19] argv[4]="1"
D [04/Feb/2012:15:16:39 -0800] [Job 19] argv[5]="job-uuid=urn:uuid:82d4e1a6-132c-3ba2-6919-d72b1812ff0d job-originating-host-name=localhost time-at-creation=1328397399 time-at-processing=1328397399 AP_D_InputSlot="
D [04/Feb/2012:15:16:39 -0800] [Job 19] argv[6]="/var/spool/cups/d00019-001"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[2]="CUPS_DOCROOT=/usr/share/cups/www"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[8]="HOME=/var/spool/cups/tmp"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[10]="SERVER_ADMIN=root at nancy2"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[11]="SOFTWARE=CUPS/1.5.0"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[13]="USER=root"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[16]="IPP_PORT=631"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[17]="CHARSET=utf-8"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[18]="LANG=en_US.UTF-8"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[19]="PPD=/etc/cups/ppd/ip1600.ppd"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[20]="RIP_MAX_CACHE=128m"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[21]="CONTENT_TYPE=application/vnd.cups-banner"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[22]="DEVICE_URI=lpd://router/lpUSB0?format=l"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[23]="PRINTER_INFO=Cannon inkjet printer"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[24]="PRINTER_LOCATION=On the right of the monitor"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[25]="PRINTER=ip1600"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[26]="PRINTER_STATE_REASONS=none"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[27]="CUPS_FILETYPE=document"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[28]="FINAL_CONTENT_TYPE=printer/ip1600"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[29]="AUTH_I****"
I [04/Feb/2012:15:16:39 -0800] [Job 19] Started filter /usr/lib/cups/filter/bannertops (PID 32019)
I [04/Feb/2012:15:16:39 -0800] [Job 19] Started filter /usr/lib/cups/filter/pstops (PID 32020)
I [04/Feb/2012:15:16:39 -0800] [Job 19] Started filter /usr/lib/cups/filter/gstoraster (PID 32021)
I [04/Feb/2012:15:16:39 -0800] [Job 19] Started filter /usr/lib/cups/filter/rastertogutenprint.5.2 (PID 32022)
I [04/Feb/2012:15:16:39 -0800] [Job 19] Started backend /usr/lib/cups/backend/lpd (PID 32023)
D [04/Feb/2012:15:16:39 -0800] Discarding unused job-state-changed event...
D [04/Feb/2012:15:16:39 -0800] Returning IPP successful-ok for Print-Job (ipp://localhost/printers/ip1600) from localhost
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files"
D [04/Feb/2012:15:16:39 -0800] cupsdReadClient: 16 POST / HTTP/1.1
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files"
D [04/Feb/2012:15:16:39 -0800] cupsdAuthorize: No authentication data provided.
D [04/Feb/2012:15:16:39 -0800] cupsdReadClient: 16 1.1 Get-Jobs 1
D [04/Feb/2012:15:16:39 -0800] Get-Jobs ipp://localhost/printers/
D [04/Feb/2012:15:16:39 -0800] Returning IPP successful-ok for Get-Jobs (ipp://localhost/printers/) from localhost
D [04/Feb/2012:15:16:39 -0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files"
D [04/Feb/2012:15:16:39 -0800] [Job 19] STATE: +connecting-to-device
D [04/Feb/2012:15:16:39 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:39 -0800] [Job 19] Looking up "router"...
D [04/Feb/2012:15:16:39 -0800] [Job 19] backendWaitLoop(snmp_fd=5, addr=0xb8f60284, side_cb=0xb771dde0)
D [04/Feb/2012:15:16:39 -0800] [Job 19] load_banner(filename="/var/spool/cups/d00019-001")
D [04/Feb/2012:15:16:39 -0800] [Job 19] 1 #CUPS-BANNER
D [04/Feb/2012:15:16:39 -0800] [Job 19] 2 Show printer-name printer-info printer-location printer-make-and-model printer-driver-name printer-driver-version paper-size imageable-area
D [04/Feb/2012:15:16:39 -0800] [Job 19] 3 Header Printer Test Page
D [04/Feb/2012:15:16:39 -0800] [Job 19] 4 Footer Printer Test Page
D [04/Feb/2012:15:16:39 -0800] [Job 19] 5 Notice CUPS 1.5.0.
D [04/Feb/2012:15:16:39 -0800] [Job 19] 6 Image images/cups.png
D [04/Feb/2012:15:16:39 -0800] [Job 19] 7 Image images/color-wheel.png
D [04/Feb/2012:15:16:39 -0800] [Job 19] Page = 612x792; 10,15 to 602,777
D [04/Feb/2012:15:16:39 -0800] [Job 19] Page = 612x792; 10,15 to 602,777
D [04/Feb/2012:15:16:39 -0800] [Job 19] slow_collate=0, slow_duplex=0, slow_order=0
D [04/Feb/2012:15:16:39 -0800] [Job 19] Before copy_comments - %!PS-Adobe-3.0
D [04/Feb/2012:15:16:39 -0800] [Job 19] %!PS-Adobe-3.0
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%BoundingBox: 10 15 602 777
D [04/Feb/2012:15:16:39 -0800] [Job 19] %cupsRotation: 0
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%Creator: bannertops/CUPS v1.5.0
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%CreationDate: Sat 04 Feb 2012 03:16:39 PM PST
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%LanguageLevel: 2
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%DocumentData: Clean7Bit
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%Title: (Test Page)
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%For: (root)
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%Pages: 1
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%DocumentSuppliedResources: font Monospace
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%+ font Monospace-Bold
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%+ font Monospace-BoldOblique
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%+ font Monospace-Oblique
D [04/Feb/2012:15:16:39 -0800] [Job 19] %%EndComments
D [04/Feb/2012:15:16:39 -0800] [Job 19] Before copy_prolog - %%BeginProlog
D [04/Feb/2012:15:16:39 -0800] [Job 19] PNG image: 128x128x8, color_type=6 (RGB+ALPHA)
D [04/Feb/2012:15:16:39 -0800] [Job 19] PNG image: 192x128x8, color_type=2 (RGB)
D [04/Feb/2012:15:16:39 -0800] [Job 19] Before copy_setup - %%Page: coverpage 1
D [04/Feb/2012:15:16:39 -0800] [Job 19] Before page loop - %%Page: coverpage 1
D [04/Feb/2012:15:16:39 -0800] [Job 19] Copying page 1...
D [04/Feb/2012:15:16:39 -0800] [Job 19] pagew = 592.0, pagel = 762.0
D [04/Feb/2012:15:16:39 -0800] [Job 19] bboxx = 0, bboxy = 0, bboxw = 612, bboxl = 792
D [04/Feb/2012:15:16:39 -0800] [Job 19] PageLeft = 10.0, PageRight = 602.0
D [04/Feb/2012:15:16:39 -0800] [Job 19] PageTop = 777.0, PageBottom = 15.0
D [04/Feb/2012:15:16:39 -0800] [Job 19] PageWidth = 612.0, PageLength = 792.0
D [04/Feb/2012:15:16:39 -0800] [Job 19] Wrote 1 pages...
D [04/Feb/2012:15:16:39 -0800] [Job 19] PPD uses qualifier 'RGB.Plain.301x300dpi'
D [04/Feb/2012:15:16:39 -0800] [Job 19] Calling FindDeviceById(ip1600)
D [04/Feb/2012:15:16:39 -0800] [Job 19] Failed to send: org.freedesktop.ColorManager.Failed:device id 'ip1600' does not exists
D [04/Feb/2012:15:16:39 -0800] [Job 19] Failed to get profile filename!
I [04/Feb/2012:15:16:39 -0800] [Job 19] found profile /System/Library/ColorSync/Profiles/sRGB Profile.icc in PPD with qualifier 'Gray..'
D [04/Feb/2012:15:16:39 -0800] [Job 19] Set job-printer-state-message to "found profile /System/Library/ColorSync/Profiles/sRGB Profile.icc in PPD with qualifier 'Gray..'", current level=INFO
I [04/Feb/2012:15:16:39 -0800] [Job 19] found profile /System/Library/ColorSync/Profiles/sRGB Profile.icc in PPD that does not exist
D [04/Feb/2012:15:16:39 -0800] [Job 19] Set job-printer-state-message to "found profile /System/Library/ColorSync/Profiles/sRGB Profile.icc in PPD that does not exist", current level=INFO
I [04/Feb/2012:15:16:39 -0800] [Job 19] found profile /System/Library/ColorSync/Profiles/sRGB Profile.icc in PPD with qualifier 'RGB..'
D [04/Feb/2012:15:16:39 -0800] [Job 19] Set job-printer-state-message to "found profile /System/Library/ColorSync/Profiles/sRGB Profile.icc in PPD with qualifier 'RGB..'", current level=INFO
I [04/Feb/2012:15:16:39 -0800] [Job 19] found profile /System/Library/ColorSync/Profiles/sRGB Profile.icc in PPD that does not exist
D [04/Feb/2012:15:16:39 -0800] [Job 19] Set job-printer-state-message to "found profile /System/Library/ColorSync/Profiles/sRGB Profile.icc in PPD that does not exist", current level=INFO
I [04/Feb/2012:15:16:39 -0800] [Job 19] found profile /System/Library/ColorSync/Profiles/Generic CMYK Profile.icc in PPD with qualifier 'CMYK..'
D [04/Feb/2012:15:16:39 -0800] [Job 19] Set job-printer-state-message to "found profile /System/Library/ColorSync/Profiles/Generic CMYK Profile.icc in PPD with qualifier 'CMYK..'", current level=INFO
I [04/Feb/2012:15:16:39 -0800] [Job 19] found profile /System/Library/ColorSync/Profiles/Generic CMYK Profile.icc in PPD that does not exist
D [04/Feb/2012:15:16:39 -0800] [Job 19] Set job-printer-state-message to "found profile /System/Library/ColorSync/Profiles/Generic CMYK Profile.icc in PPD that does not exist", current level=INFO
I [04/Feb/2012:15:16:39 -0800] [Job 19] no profiles in PPD for qualifier 'RGB.Plain.301x300dpi'
D [04/Feb/2012:15:16:39 -0800] [Job 19] Set job-printer-state-message to "no profiles in PPD for qualifier 'RGB.Plain.301x300dpi'", current level=INFO
D [04/Feb/2012:15:16:39 -0800] [Job 19] Ghostscript command line: /usr/bin/gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -sDEVICE=cups -sstdout=%stderr -sOutputFile=%stdout -I/usr/share/cups/fonts -c -f -_
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[2]="CUPS_DOCROOT=/usr/share/cups/www"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[8]="HOME=/var/spool/cups/tmp"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[10]="SERVER_ADMIN=root at nancy2"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[11]="SOFTWARE=CUPS/1.5.0"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[13]="USER=root"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[16]="IPP_PORT=631"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[17]="CHARSET=utf-8"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[18]="LANG=en_US.UTF-8"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[19]="PPD=/etc/cups/ppd/ip1600.ppd"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[20]="RIP_MAX_CACHE=128m"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[21]="CONTENT_TYPE=application/vnd.cups-banner"
D [04/Feb/2012:15:16:39 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:39 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[22]="DEVICE_URI=lpd://router/lpUSB0?format=l"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[23]="PRINTER_INFO=Cannon inkjet printer"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[24]="PRINTER_LOCATION=On the right of the monitor"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[25]="PRINTER=ip1600"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[26]="PRINTER_STATE_REASONS=none"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[27]="CUPS_FILETYPE=document"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[28]="FINAL_CONTENT_TYPE=printer/ip1600"
D [04/Feb/2012:15:16:39 -0800] [Job 19] envp[29]="AUTH_INFO_REQUIRED=none"
D [04/Feb/2012:15:16:39 -0800] PID 32020 (/usr/lib/cups/filter/pstops) exited with no errors.
D [04/Feb/2012:15:16:39 -0800] PID 32019 (/usr/lib/cups/filter/bannertops) exited with no errors.
D [04/Feb/2012:15:16:39 -0800] [Job 19] Gutenprint 5.2.7 Starting
D [04/Feb/2012:15:16:39 -0800] [Job 19] Gutenprint command line: ip1600 '19' 'root' 'Test Page' '1' <args>
D [04/Feb/2012:15:16:39 -0800] [Job 19] Gutenprint using PPD file /etc/cups/ppd/ip1600.ppd
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: CUPS option count is 5 (164 bytes)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: CUPS option 0 AP_D_InputSlot =
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: CUPS option 1 job-originating-host-name = localhost
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: CUPS option 2 job-uuid = urn:uuid:82d4e1a6-132c-3ba2-6919-d72b1812ff0d
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: CUPS option 3 time-at-creation = 1328397399
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: CUPS option 4 time-at-processing = 1328397399
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: Driver Canon PIXMA iP1600
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: Using fd 0
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: Set options:
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting PageSize to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting MediaType to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting InputSlot to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CDInnerRadius to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CDOuterDiameter to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CDInnerDiameter to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CDXAdjustment to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CDYAdjustment to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting Resolution to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Set string InkType to RGB
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Set special string InkType to RGB
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting InkChannels to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting PrintingMode to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting Duplex to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Set string Quality to Standard
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Set special string Quality to Standard
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Set string ColorCorrection to None
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Set special string ColorCorrection to None
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting ChannelBitDepth to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting InputImageType to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting STPIOutputType to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting STPIRawChannels to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting SimpleGamma to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting LinearContrast to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting LUTDumpFile to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CyanCurve to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting MagentaCurve to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting YellowCurve to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting BlackCurve to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting RedCurve to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting GreenCurve to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting BlueCurve to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting WhiteCurve to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting HueMap to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting SatMap to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting LumMap to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting GCRCurve to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh0 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh1 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh2 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh3 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh4 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh5 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh6 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh7 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh8 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh9 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh10 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh11 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh12 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh13 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh14 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh15 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh16 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh17 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh18 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh19 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh20 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh21 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh22 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh23 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh24 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh25 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh26 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh27 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh28 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh29 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh30 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting CurveCh31 to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting DitherAlgorithm to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Set string ImageType to TextGraphics
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Set special string ImageType to TextGraphics
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting JobMode to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint:   Not setting PageNumber to (null)
D [04/Feb/2012:15:16:40 -0800] [Job 19] Gutenprint: End options
I [04/Feb/2012:15:16:40 -0800] [Job 19] Start rendering...
D [04/Feb/2012:15:16:40 -0800] [Job 19] Set job-printer-state-message to "Start rendering...", current level=INFO
D [04/Feb/2012:15:16:40 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:40 -0800] Discarding unused printer-state-changed event...
I [04/Feb/2012:15:16:40 -0800] [Job 19] Processing page 1...
D [04/Feb/2012:15:16:40 -0800] [Job 19] Set job-printer-state-message to "Processing page 1...", current level=INFO
D [04/Feb/2012:15:16:40 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:40 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: About to start printing loop.
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Printing page 1
D [04/Feb/2012:15:16:41 -0800] [Job 19] PAGE: 1 1
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Initialize page
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Set special string ChannelBitDepth to 16
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Set special string PrintingMode to Color
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Set special string InputImageType to RGB
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Clear special parameter Resolution
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Set special parameter Quality to choice 1 (Standard)
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Set special string MediaType to Plain
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   PageSize = 612x792
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Using page size Letter with (792, 612)
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Set special string PageSize to Letter
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Set special string JobMode to Job
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Validating options
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Clearing string CDInnerRadius ((null))
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Clearing string Resolution ((null))
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Setting default string Resolution to 300x300dpi
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Clearing string InkType (RGB)
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Setting default string InkType to CMYK
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Clearing string Duplex ((null))
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Clearing string STPIOutputType ((null))
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Setting default string STPIOutputType to (null)
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Done validating options
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: limits w 612 l 10 r 602  h 792 t 15 b 777
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: max limits l 10 r 602 t 15 b 777
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Adjusting left margin from 10 to 10
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Adjusting right margin from 602 to 602
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Adjusting top margin from 15 to 15
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Adjusting bottom margin from 777 to 777
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   CUPS settings w 2466 (2466) l 41 r 41  h 3175 (3175) t 62 b 62
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: End initialize page
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Page data:
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   MediaClass = ""
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   MediaColor = ""
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   MediaType = "Plain"
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   OutputType = ""
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   AdvanceDistance = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   AdvanceMedia = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Collate = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   CutMedia = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Duplex = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   HWResolution = [ 300 300 ]
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   ImagingBoundingBox = [ 10 15 602 777 ]
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   InsertSheet = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Jog = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   LeadingEdge = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Margins = [ 10 15 ]
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   ManualFeed = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   MediaPosition = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   MediaWeight = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   MirrorPrint = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   NegativePrint = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   NumCopies = 1
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Orientation = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   OutputFaceUp = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   PageSize = [ 612 792 ]
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Separations = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   TraySwitch = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   Tumble = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsWidth = 2467
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsHeight = 3175
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cups->width = 2466
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cups->height = 3175
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cups->adjusted_width = 2466
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cups->adjusted_height = 3175
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsMediaType = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsBitsPerColor = 16
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsBitsPerPixel = 48
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsBytesPerLine = 14802
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsColorOrder = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsColorSpace = 1
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsCompression = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsRowCount = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsRowFeed = 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   cupsRowStep = 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_driver(v) |bjc-PIXMA-iP1600|
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_left(v) 10
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_top(v) 15
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_page_width(v) 612
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_page_height(v) 792
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   shrink page to fit 1
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string PageSize(v) |Letter| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string MediaType(v) |Plain| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string InputSlot(v) |Auto| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string CDInnerRadius(v) |NULL| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_dimension CDOuterDiameter(v) |329| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_dimension CDInnerDiameter(v) |121| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_dimension CDXAdjustment(v) |0| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_dimension CDYAdjustment(v) |0| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string Resolution(v) |300x300dpi| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string InkType(v) |CMYK| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_int InkChannels(v) |4| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string PrintingMode(v) |Color| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string Duplex(v) |NULL| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string Quality(v) |Standard| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float CyanDensity(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float MagentaDensity(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float YellowDensity(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float BlackDensity(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float LightCyanTrans(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float LightMagentaTrans(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float LightYellowTrans(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string ColorCorrection(v) |None| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string ChannelBitDepth(v) |16| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string InputImageType(v) |RGB| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string STPIOutputType(v) |NULL| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_int STPIRawChannels(v) |1| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_boolean SimpleGamma(v) |0| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float Brightness(v) |1.000| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float Contrast(v) |1.000| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_boolean LinearContrast(v) |0| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float Gamma(v) |1.667| 1
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float AppGamma(v) |1.000| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float CyanGamma(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float MagentaGamma(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float YellowGamma(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float RedGamma(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GreenGamma(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float BlueGamma(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float BlackGamma(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float CyanBalance(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float MagentaBalance(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float YellowBalance(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float Saturation(v) |1.000| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float InkLimit(v) |4.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float BlackTrans(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GCRLower(v) |0.200| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GCRUpper(v) |0.500| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh0(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh1(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh2(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh3(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh4(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh5(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh6(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh7(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh8(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh9(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh10(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh11(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh12(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh13(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh14(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh15(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh16(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh17(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh18(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh19(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh20(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh21(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh22(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh23(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh24(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh25(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh26(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh27(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh28(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh29(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh30(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float GammaCh31(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_float Density(v) |1.000| 0
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string DitherAlgorithm(v) |None| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string ImageType(v) |TextGraphics| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_string JobMode(v) |Job| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint:   stp_get_int PageNumber(v) |0| 2
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: End page data
I [04/Feb/2012:15:16:41 -0800] [Job 19] Starting page 1...
D [04/Feb/2012:15:16:41 -0800] [Job 19] Set job-printer-state-message to "Starting page 1...", current level=INFO
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:41 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Image_height 3175
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Image_width 2466
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Image_width 2466
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Image_width 2466
D [04/Feb/2012:15:16:41 -0800] [Job 19] Gutenprint: Image_width 2466
I [04/Feb/2012:15:16:41 -0800] [Job 19] Printing page 1, 1%
D [04/Feb/2012:15:16:41 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 1%", current level=INFO
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:41 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:41 -0800] [Job 19] ATTR: job-media-progress=1
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:41 -0800] [Job 19] Copying print data.
D [04/Feb/2012:15:16:41 -0800] [Job 19] Set job-printer-state-message to "Copying print data.", current level=INFO
D [04/Feb/2012:15:16:41 -0800] [Job 19] backendRunLoop(print_fd=-1, device_fd=7, snmp_fd=5, addr=0xb8f60284, use_bc=0, side_cb=0xb771dde0)
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:41 -0800] Discarding unused printer-state-changed event...
I [04/Feb/2012:15:16:41 -0800] [Job 19] Printing page 1, 2%
D [04/Feb/2012:15:16:41 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 2%", current level=INFO
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:41 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:41 -0800] [Job 19] ATTR: job-media-progress=2
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:41 -0800] [Job 19] Printing page 1, 3%
D [04/Feb/2012:15:16:41 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 3%", current level=INFO
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:41 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:41 -0800] [Job 19] ATTR: job-media-progress=3
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:41 -0800] [Job 19] Read 4096 bytes of print data...
I [04/Feb/2012:15:16:41 -0800] [Job 19] Printing page 1, 4%
D [04/Feb/2012:15:16:41 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 4%", current level=INFO
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:41 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:41 -0800] [Job 19] ATTR: job-media-progress=4
D [04/Feb/2012:15:16:41 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 5%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 5%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=5
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 6%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 6%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=6
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 7%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 7%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=7
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 8%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 8%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=8
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 9%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 9%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=9
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 10%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 10%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=10
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 11%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 11%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=11
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 12%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 12%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=12
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 13%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 13%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=13
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 14%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 14%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=14
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 15%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 15%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=15
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 16%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 16%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=16
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 17%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 17%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=17
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 18%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 18%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=18
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 19%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 19%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=19
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 20%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 20%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=20
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 21%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 21%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=21
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 22%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 22%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=22
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 23%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 23%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=23
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 24%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 24%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=24
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 25%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 25%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=25
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 26%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 26%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=26
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 27%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 27%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=27
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 28%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 28%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=28
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 29%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 29%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=29
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 30%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 30%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=30
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 31%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 31%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=31
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 32%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 32%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=32
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 33%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 33%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=33
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 34%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 34%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=34
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:42 -0800] [Job 19] Printing page 1, 35%
D [04/Feb/2012:15:16:42 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 35%", current level=INFO
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:42 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:42 -0800] [Job 19] ATTR: job-media-progress=35
D [04/Feb/2012:15:16:42 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 36%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 36%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=36
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 37%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 37%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=37
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 38%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 38%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=38
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 39%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 39%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=39
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 40%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 40%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=40
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 41%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 41%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=41
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 42%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 42%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=42
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 43%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 43%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=43
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] prtGeneralCurrentLocalization type is 5, expected 2!
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 4096 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 8192 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 44%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 44%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=44
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 45%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 45%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=45
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 46%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 46%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=46
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 47%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 47%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=47
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 48%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 48%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=48
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 49%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 49%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=49
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 50%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 50%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=50
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 51%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 51%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=51
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 52%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 52%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=52
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 53%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 53%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=53
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 54%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 54%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=54
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 55%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 55%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=55
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 56%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 56%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=56
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 57%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 57%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=57
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 58%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 58%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=58
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 59%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 59%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=59
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 60%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 60%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=60
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:43 -0800] [Job 19] Printing page 1, 61%
D [04/Feb/2012:15:16:43 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 61%", current level=INFO
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] ATTR: job-media-progress=61
D [04/Feb/2012:15:16:43 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:43 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 62%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 62%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=62
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 63%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 63%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=63
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 64%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 64%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=64
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 65%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 65%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=65
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 66%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 66%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=66
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 67%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 67%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=67
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 68%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 68%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=68
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 69%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 69%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=69
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 70%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 70%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=70
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 71%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 71%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=71
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 72%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 72%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=72
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 73%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 73%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=73
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 74%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 74%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=74
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 75%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 75%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=75
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 76%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 76%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=76
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 77%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 77%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=77
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 78%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 78%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=78
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 79%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 79%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=79
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 80%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 80%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=80
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 81%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 81%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=81
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 82%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 82%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=82
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 83%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 83%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=83
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 84%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 84%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=84
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 85%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 85%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=85
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 86%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 86%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=86
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 87%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 87%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=87
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 88%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 88%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=88
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 89%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 89%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=89
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 90%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 90%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=90
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 91%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 91%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=91
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 92%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 92%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=92
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 93%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 93%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=93
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 94%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 94%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=94
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 95%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 95%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=95
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 96%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 96%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=96
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 97%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 97%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=97
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 98%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 98%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=98
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 99%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 99%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=99
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 4096 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 4096 bytes of print data...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Processing page 2...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Processing page 2...", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Printing page 1, 100%
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Printing page 1, 100%", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] ATTR: job-media-progress=100
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Finished page 1...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Finished page 1...", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 621 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 621 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Gutenprint: Done printing page 1
I [04/Feb/2012:15:16:44 -0800] [Job 19] Rendering completed
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Rendering completed", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Gutenprint: Ending job
D [04/Feb/2012:15:16:44 -0800] [Job 19] Gutenprint: Printed total 176751 bytes
D [04/Feb/2012:15:16:44 -0800] [Job 19] Gutenprint: Used 2.070 seconds user, 0.090 seconds system, 5.385 seconds elapsed
D [04/Feb/2012:15:16:44 -0800] PID 32022 (/usr/lib/cups/filter/rastertogutenprint.5.2) exited with no errors.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Read 2 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Wrote 2 bytes of print data...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Connecting to router:515 for printer lpUSB0
I [04/Feb/2012:15:16:44 -0800] [Job 19] Connecting to printer.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Connecting to printer.", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] STATE: -connecting-to-device
I [04/Feb/2012:15:16:44 -0800] [Job 19] Connected to printer.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Connected to printer.", current level=INFO
D [04/Feb/2012:15:16:44 -0800] [Job 19] Connected to 192.168.15.29:515 (local port 1023)...
D [04/Feb/2012:15:16:44 -0800] [Job 19] lpd_command 02 lpUSB0
D [04/Feb/2012:15:16:44 -0800] [Job 19] Sending command string (8 bytes)...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Reading command status...
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] lpd_command returning 0
D [04/Feb/2012:15:16:44 -0800] [Job 19] Control file is:
D [04/Feb/2012:15:16:44 -0800] [Job 19] Hnancy2
D [04/Feb/2012:15:16:44 -0800] [Job 19] Proot
D [04/Feb/2012:15:16:44 -0800] [Job 19] JTest Page
D [04/Feb/2012:15:16:44 -0800] [Job 19] ldfA023nancy2
D [04/Feb/2012:15:16:44 -0800] [Job 19] UdfA023nancy2
D [04/Feb/2012:15:16:44 -0800] [Job 19] NTest Page
D [04/Feb/2012:15:16:44 -0800] [Job 19] lpd_command 02 64 cfA023nancy2
D [04/Feb/2012:15:16:44 -0800] [Job 19] Sending command string (17 bytes)...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Reading command status...
D [04/Feb/2012:15:16:44 -0800] PID 32021 (/usr/lib/cups/filter/gstoraster) exited with no errors.
D [04/Feb/2012:15:16:44 -0800] [Job 19] lpd_command returning 0
D [04/Feb/2012:15:16:44 -0800] [Job 19] Sending control file (64 bytes)
I [04/Feb/2012:15:16:44 -0800] [Job 19] Control file sent successfully.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Control file sent successfully.", current level=INFO
D [04/Feb/2012:15:16:44 -0800] [Job 19] lpd_command 03 176751 dfA023nancy2
D [04/Feb/2012:15:16:44 -0800] [Job 19] Sending command string (21 bytes)...
D [04/Feb/2012:15:16:44 -0800] [Job 19] Reading command status...
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:44 -0800] [Job 19] lpd_command returning 0
D [04/Feb/2012:15:16:44 -0800] [Job 19] Sending data file (176751 bytes)
I [04/Feb/2012:15:16:44 -0800] [Job 19] Spooling job, 0% complete.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Spooling job, 0% complete.", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Spooling job, 19% complete.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Spooling job, 19% complete.", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Spooling job, 37% complete.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Spooling job, 37% complete.", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Spooling job, 56% complete.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Spooling job, 56% complete.", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Spooling job, 74% complete.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Spooling job, 74% complete.", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
I [04/Feb/2012:15:16:44 -0800] [Job 19] Spooling job, 93% complete.
D [04/Feb/2012:15:16:44 -0800] [Job 19] Set job-printer-state-message to "Spooling job, 93% complete.", current level=INFO
D [04/Feb/2012:15:16:44 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:44 -0800] Discarding unused printer-state-changed event...
I [04/Feb/2012:15:16:45 -0800] [Job 19] Data file sent successfully.
D [04/Feb/2012:15:16:45 -0800] [Job 19] Set job-printer-state-message to "Data file sent successfully.", current level=INFO
D [04/Feb/2012:15:16:45 -0800] Discarding unused job-progress event...
D [04/Feb/2012:15:16:45 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:45 -0800] PID 32023 (/usr/lib/cups/backend/lpd) exited with no errors.
D [04/Feb/2012:15:16:45 -0800] Discarding unused job-completed event...
I [04/Feb/2012:15:16:45 -0800] [Job 19] Job completed.
D [04/Feb/2012:15:16:45 -0800] cupsdMarkDirty(----J-)
D [04/Feb/2012:15:16:45 -0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [04/Feb/2012:15:16:45 -0800] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
D [04/Feb/2012:15:16:45 -0800] Discarding unused printer-state-changed event...
D [04/Feb/2012:15:16:46 -0800] [Job 19] Unloading...
I [04/Feb/2012:15:17:10 -0800] Saving job.cache...
D [04/Feb/2012:15:17:10 -0800] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files"
D [04/Feb/2012:15:18:06 -0800] Report: clients=1
D [04/Feb/2012:15:18:06 -0800] Report: jobs=19
D [04/Feb/2012:15:18:06 -0800] Report: jobs-active=0
D [04/Feb/2012:15:18:06 -0800] Report: printers=3
D [04/Feb/2012:15:18:06 -0800] Report: printers-implicit=0
D [04/Feb/2012:15:18:06 -0800] Report: stringpool-string-count=10603
D [04/Feb/2012:15:18:06 -0800] Report: stringpool-alloc-bytes=16536
D [04/Feb/2012:15:18:06 -0800] Report: stringpool-total-bytes=196224
<<<<< End of log file

When you reply, I'm sure that this can be trimmed to what is necessary.  It is a quite long log file.

Thanks again for the help.  I'm sure that this will be solved soon.