I [19/Jul/2012:05:41:44 -0700] Remote access is disabled. D [19/Jul/2012:05:41:44 -0700] Added auto ServerAlias linus I [19/Jul/2012:05:41:44 -0700] Loaded configuration file "/etc/cups/cupsd.conf" I [19/Jul/2012:05:41:44 -0700] Using default TempDir of /var/spool/cups/tmp... I [19/Jul/2012:05:41:44 -0700] Configured for up to 100 clients. I [19/Jul/2012:05:41:44 -0700] Allowing up to 100 client connections per host. I [19/Jul/2012:05:41:44 -0700] Using policy "default" as the default. I [19/Jul/2012:05:41:44 -0700] Full reload is required. I [19/Jul/2012:05:41:44 -0700] Saving job.cache... D [19/Jul/2012:05:41:44 -0700] Discarding unused printer-stopped event... D [19/Jul/2012:05:41:44 -0700] cupsdMarkDirty(P-----) D [19/Jul/2012:05:41:44 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy" D [19/Jul/2012:05:41:44 -0700] Calling DeleteDevice(cups-HL-1440-series) D [19/Jul/2012:05:41:45 -0700] failed to DeleteDevice: org.freedesktop.DBus.Error.InvalidArgs:Type of message, `(s)', does not match expected type `(o)' D [19/Jul/2012:05:41:45 -0700] cupsdDeregisterPrinter(p=0xb88a9a48(HL-1440-series), removeit=1) I [19/Jul/2012:05:41:45 -0700] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 38 types, 55 filters... D [19/Jul/2012:05:41:45 -0700] Loading printer HL-1440-series... D [19/Jul/2012:05:41:45 -0700] load_ppd: Loading /var/cache/cups/HL-1440-series.data... D [19/Jul/2012:05:41:45 -0700] Calling DeleteDevice(cups-HL-1440-series) D [19/Jul/2012:05:41:45 -0700] failed to DeleteDevice: org.freedesktop.DBus.Error.InvalidArgs:Type of message, `(s)', does not match expected type `(o)' D [19/Jul/2012:05:41:45 -0700] Using profile id of HL-1440-series-Gray.. D [19/Jul/2012:05:41:45 -0700] Calling CreateProfile(HL-1440-series-Gray..,temp) W [19/Jul/2012:05:41:45 -0700] failed to CreateProfile: org.freedesktop.ColorManager.AlreadyExists:profile id 'HL-1440-series-Gray..' already exists I [19/Jul/2012:05:41:45 -0700] Registering ICC color profiles for "HL-1440-series" D [19/Jul/2012:05:41:45 -0700] Calling CreateDevice(cups-HL-1440-series,temp) W [19/Jul/2012:05:41:45 -0700] failed to CreateDevice: org.freedesktop.ColorManager.AlreadyExists:device id 'cups-HL-1440-series' already exists D [19/Jul/2012:05:41:45 -0700] cupsdRegisterPrinter(p=0xb88faca8(HL-1440-series)) D [19/Jul/2012:05:41:45 -0700] cupsdLoadRemoteCache: Not loading remote cache. I [19/Jul/2012:05:41:45 -0700] Loading job cache file "/var/cache/cups/job.cache"... D [19/Jul/2012:05:41:45 -0700] [Job 262] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 263] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 264] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 265] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 266] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 267] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 268] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 269] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 270] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 271] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 272] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 273] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 274] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 275] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 276] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 277] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 278] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 279] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 280] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 281] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 282] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 283] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 284] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 285] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 286] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 287] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 288] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 289] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 290] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 291] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 292] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 293] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 294] Loading from cache... D [19/Jul/2012:05:41:45 -0700] [Job 295] Loading from cache... D [19/Jul/2012:05:41:45 -0700] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)") I [19/Jul/2012:05:41:45 -0700] Full reload complete. I [19/Jul/2012:05:41:45 -0700] Listening to [v1.::1]:631 on fd 9... I [19/Jul/2012:05:41:45 -0700] Listening to 127.0.0.1:631 on fd 10... I [19/Jul/2012:05:41:45 -0700] Listening to /var/run/cups/cups.sock:631 on fd 11... I [19/Jul/2012:05:41:45 -0700] Resuming new connection processing... D [19/Jul/2012:05:41:45 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:41:45 -0700] Notifier dbus started - PID = 2754 D [19/Jul/2012:05:41:45 -0700] cupsdMarkDirty(-----S) D [19/Jul/2012:05:41:45 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:41:45 -0700] [Notifier] state=3 D [19/Jul/2012:05:41:45 -0700] [Notifier] Connected to D-BUS D [19/Jul/2012:05:41:45 -0700] [Notifier] ServerRestarted I [19/Jul/2012:05:42:15 -0700] Saving printers.conf... I [19/Jul/2012:05:42:16 -0700] Saving subscriptions.conf... D [19/Jul/2012:05:42:16 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files" D [19/Jul/2012:05:42:16 -0700] Report: clients=0 D [19/Jul/2012:05:42:16 -0700] Report: jobs=34 D [19/Jul/2012:05:42:16 -0700] Report: jobs-active=0 D [19/Jul/2012:05:42:16 -0700] Report: printers=1 D [19/Jul/2012:05:42:16 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:42:16 -0700] Report: stringpool-string-count=5166 D [19/Jul/2012:05:42:16 -0700] Report: stringpool-alloc-bytes=9096 D [19/Jul/2012:05:42:16 -0700] Report: stringpool-total-bytes=90624 D [19/Jul/2012:05:44:03 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:44:03 -0700] Report: clients=1 D [19/Jul/2012:05:44:03 -0700] Report: jobs=34 D [19/Jul/2012:05:44:03 -0700] Report: jobs-active=0 D [19/Jul/2012:05:44:03 -0700] Report: printers=1 D [19/Jul/2012:05:44:03 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:44:03 -0700] Report: stringpool-string-count=5166 D [19/Jul/2012:05:44:03 -0700] Report: stringpool-alloc-bytes=9096 D [19/Jul/2012:05:44:03 -0700] Report: stringpool-total-bytes=90624 D [19/Jul/2012:05:44:03 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:44:03 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:44:03 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:44:03 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:44:03 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:44:03 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:44:03 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:44:03 -0700] cupsdReadClient: 17 1.1 CUPS-Get-PPDs 1 D [19/Jul/2012:05:44:03 -0700] CUPS-Get-PPDs D [19/Jul/2012:05:44:03 -0700] [CGI] argv[0] = "/usr/lib/cups/daemon/cups-driverd" D [19/Jul/2012:05:44:03 -0700] [CGI] argv[1] = "list" D [19/Jul/2012:05:44:03 -0700] [CGI] argv[2] = "1" D [19/Jul/2012:05:44:03 -0700] [CGI] argv[3] = "0" D [19/Jul/2012:05:44:03 -0700] [CGI] argv[4] = "requested-attributes=all" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[8] = "HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[10] = "SERVER_ADMIN=root@linus" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[11] = "SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[13] = "USER=root" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[14] = "CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[15] = "CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[16] = "IPP_PORT=631" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[17] = "LANG=en_US.UTF8" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[18] = "REDIRECT_STATUS=1" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[19] = "GATEWAY_INTERFACE=CGI/1.1" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[20] = "SERVER_NAME=localhost" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[21] = "SERVER_PORT=631" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[22] = "REMOTE_ADDR=localhost" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[23] = "REMOTE_HOST=localhost" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[24] = "SCRIPT_NAME=/" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[25] = "SCRIPT_FILENAME=/usr/share/cups/doc-root/" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[26] = "SERVER_PROTOCOL=HTTP/1.1" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[27] = "HTTP_USER_AGENT=CUPS/1.5.3" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[28] = "REQUEST_METHOD=POST" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[29] = "CONTENT_LENGTH=75" D [19/Jul/2012:05:44:03 -0700] [CGI] envp[30] = "CONTENT_TYPE=application/ipp" D [19/Jul/2012:05:44:03 -0700] [CGI] Started /usr/lib/cups/daemon/cups-driverd (PID 4620) I [19/Jul/2012:05:44:03 -0700] Started "/usr/lib/cups/daemon/cups-driverd" (pid=4620) D [19/Jul/2012:05:44:03 -0700] cupsdSendCommand: 17 file=19 I [19/Jul/2012:05:44:03 -0700] [cups-driverd] Read "/var/cache/cups/ppds.dat", 1495 PPDs... I [19/Jul/2012:05:44:03 -0700] [cups-driverd] Read "/var/cache/cups/ppds.dat", 1495 PPDs... D [19/Jul/2012:05:44:03 -0700] [cups-driverd] Loading "/usr/share/cups/model"... D [19/Jul/2012:05:44:03 -0700] [cups-driverd] Loading "/usr/share/cups/drv"... D [19/Jul/2012:05:44:04 -0700] [cups-driverd] Loading "/usr/share/ppd"... D [19/Jul/2012:05:44:04 -0700] [cups-driverd] Loading "/usr/share/ppd/hplip"... D [19/Jul/2012:05:44:04 -0700] [cups-driverd] Loading "/usr/share/ppd/hplip/HP"... D [19/Jul/2012:05:44:04 -0700] [cups-driverd] Loading "/usr/share/ppd/Brother"... D [19/Jul/2012:05:44:04 -0700] [cups-driverd] Loading "/usr/share/ppd/ghostscript"... D [19/Jul/2012:05:44:04 -0700] [cups-driverd] Loading "/usr/share/ppd/ghostscript/model"... D [19/Jul/2012:05:44:04 -0700] [cups-driverd] Loading "/usr/share/ppd/cupsfilters"... D [19/Jul/2012:05:44:04 -0700] [cups-driverd] Loading "/usr/share/ppd/custom"... D [19/Jul/2012:05:44:04 -0700] [cups-driverd] ChangedPPD=1 I [19/Jul/2012:05:44:04 -0700] [cups-driverd] Wrote "/var/cache/cups/ppds.dat", 1495 PPDs... I [19/Jul/2012:05:44:04 -0700] [cups-driverd] Wrote "/var/cache/cups/ppds.dat", 1495 PPDs... D [19/Jul/2012:05:44:06 -0700] [CGI] Cannot read file /usr/share/foomatic/db/oldprinterids! D [19/Jul/2012:05:44:06 -0700] [CGI] Cannot read directory /usr/share/foomatic/db/source/driver! D [19/Jul/2012:05:44:06 -0700] [CGI] Entity: line 1: parser error : Extra content at the end of the document D [19/Jul/2012:05:44:06 -0700] [CGI] D [19/Jul/2012:05:44:06 -0700] [CGI] ^ D [19/Jul/2012:05:44:07 -0700] Script header: Content-Type: application/ipp D [19/Jul/2012:05:44:07 -0700] Script header: D [19/Jul/2012:05:44:08 -0700] PID 4620 (/usr/lib/cups/daemon/cups-driverd) exited with no errors. D [19/Jul/2012:05:44:08 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:44:08 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:44:08 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:44:08 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:44:08 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:44:08 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:44:08 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:44:08 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:44:08 -0700] cupsdReadClient: 17 1.1 Get-Printer-Attributes 1 D [19/Jul/2012:05:44:08 -0700] Get-Printer-Attributes ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:44:08 -0700] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:44:08 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:44:08 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:44:08 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:44:08 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:44:08 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:44:08 -0700] CUPS-Get-Printers D [19/Jul/2012:05:44:08 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:44:08 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:44:08 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:44:08 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:44:08 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:44:09 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:44:09 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 1.1 Get-Printer-Attributes 1 D [19/Jul/2012:05:44:09 -0700] Get-Printer-Attributes ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:44:09 -0700] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:44:09 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:44:09 -0700] CUPS-Get-Printers D [19/Jul/2012:05:44:09 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:44:09 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:44:09 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:44:09 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 1.1 Get-Printer-Attributes 1 D [19/Jul/2012:05:44:09 -0700] Get-Printer-Attributes ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:44:09 -0700] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:44:09 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:44:09 -0700] CUPS-Get-Printers D [19/Jul/2012:05:44:09 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:44:09 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:44:09 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:44:09 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:45:39 -0700] Report: clients=0 D [19/Jul/2012:05:45:39 -0700] Report: jobs=34 D [19/Jul/2012:05:45:39 -0700] Report: jobs-active=0 D [19/Jul/2012:05:45:39 -0700] Report: printers=1 D [19/Jul/2012:05:45:39 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:45:39 -0700] Report: stringpool-string-count=5166 D [19/Jul/2012:05:45:39 -0700] Report: stringpool-alloc-bytes=9096 D [19/Jul/2012:05:45:39 -0700] Report: stringpool-total-bytes=90624 D [19/Jul/2012:05:46:33 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:46:33 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:46:33 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:46:33 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:46:33 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:46:33 -0700] CUPS-Get-Printers D [19/Jul/2012:05:46:33 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:46:33 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:46:33 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:46:33 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:46:33 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:46:33 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Classes 1 D [19/Jul/2012:05:46:33 -0700] CUPS-Get-Classes D [19/Jul/2012:05:46:33 -0700] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from localhost D [19/Jul/2012:05:46:33 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:46:33 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:46:33 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:46:33 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" I [19/Jul/2012:05:48:59 -0700] Scheduler shutting down normally. D [19/Jul/2012:05:48:59 -0700] cupsdMarkDirty(-----S) D [19/Jul/2012:05:48:59 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy" I [19/Jul/2012:05:48:59 -0700] Saving subscriptions.conf... D [19/Jul/2012:05:48:59 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files" I [19/Jul/2012:05:48:59 -0700] Saving job.cache... I [19/Jul/2012:05:50:20 -0700] Remote access is disabled. D [19/Jul/2012:05:50:20 -0700] Added auto ServerAlias linus I [19/Jul/2012:05:50:20 -0700] Loaded configuration file "/etc/cups/cupsd.conf" I [19/Jul/2012:05:50:20 -0700] Using default TempDir of /var/spool/cups/tmp... I [19/Jul/2012:05:50:20 -0700] Configured for up to 100 clients. I [19/Jul/2012:05:50:20 -0700] Allowing up to 100 client connections per host. I [19/Jul/2012:05:50:20 -0700] Using policy "default" as the default. I [19/Jul/2012:05:50:20 -0700] Full reload is required. I [19/Jul/2012:05:50:20 -0700] Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 38 types, 55 filters... D [19/Jul/2012:05:50:20 -0700] Loading printer HL-1440-series... D [19/Jul/2012:05:50:20 -0700] load_ppd: Loading /var/cache/cups/HL-1440-series.data... D [19/Jul/2012:05:50:20 -0700] Calling DeleteDevice(cups-HL-1440-series) D [19/Jul/2012:05:50:20 -0700] failed to DeleteDevice: org.freedesktop.DBus.Error.InvalidArgs:Type of message, `(s)', does not match expected type `(o)' D [19/Jul/2012:05:50:20 -0700] Using profile id of HL-1440-series-Gray.. D [19/Jul/2012:05:50:20 -0700] Calling CreateProfile(HL-1440-series-Gray..,temp) D [19/Jul/2012:05:50:21 -0700] created profile /org/freedesktop/ColorManager/profiles/HL_1440_series_Gray__ I [19/Jul/2012:05:50:21 -0700] Registering ICC color profiles for "HL-1440-series" D [19/Jul/2012:05:50:21 -0700] Calling CreateDevice(cups-HL-1440-series,temp) D [19/Jul/2012:05:50:21 -0700] created device /org/freedesktop/ColorManager/devices/cups_HL_1440_series D [19/Jul/2012:05:50:21 -0700] Calling /org/freedesktop/ColorManager/devices/cups_HL_1440_series:AddProfile(/org/freedesktop/ColorManager/profiles/HL_1440_series_Gray__) [soft] D [19/Jul/2012:05:50:21 -0700] cupsdRegisterPrinter(p=0xb8d58a48(HL-1440-series)) D [19/Jul/2012:05:50:21 -0700] cupsdLoadRemoteCache: Not loading remote cache. I [19/Jul/2012:05:50:21 -0700] Loading job cache file "/var/cache/cups/job.cache"... D [19/Jul/2012:05:50:21 -0700] [Job 262] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 263] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 264] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 265] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 266] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 267] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 268] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 269] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 270] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 271] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 272] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 273] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 274] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 275] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 276] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 277] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 278] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 279] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 280] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 281] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 282] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 283] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 284] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 285] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 286] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 287] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 288] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 289] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 290] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 291] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 292] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 293] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 294] Loading from cache... D [19/Jul/2012:05:50:21 -0700] [Job 295] Loading from cache... D [19/Jul/2012:05:50:21 -0700] cupsdAddSubscription(mask=0, dest=(nil)(), job=(nil)(0), uri="(null)") I [19/Jul/2012:05:50:21 -0700] Full reload complete. D [19/Jul/2012:05:50:21 -0700] cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)") I [19/Jul/2012:05:50:21 -0700] Cleaning out old files in "/var/spool/cups/tmp"... D [19/Jul/2012:05:50:21 -0700] Removed "/var/spool/cups/tmp/cups-dbus-notifier-lockfile"... D [19/Jul/2012:05:50:21 -0700] cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp") I [19/Jul/2012:05:50:21 -0700] Cleaning out old files in "/var/cache/cups"... I [19/Jul/2012:05:50:21 -0700] Listening to [v1.::1]:631 on fd 9... I [19/Jul/2012:05:50:21 -0700] Listening to 127.0.0.1:631 on fd 10... I [19/Jul/2012:05:50:21 -0700] Listening to /var/run/cups/cups.sock:631 on fd 11... I [19/Jul/2012:05:50:21 -0700] Resuming new connection processing... D [19/Jul/2012:05:50:21 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:50:21 -0700] Notifier dbus started - PID = 6862 D [19/Jul/2012:05:50:21 -0700] cupsdMarkDirty(-----S) D [19/Jul/2012:05:50:21 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy" D [19/Jul/2012:05:50:21 -0700] [Notifier] state=3 D [19/Jul/2012:05:50:21 -0700] Report: clients=0 D [19/Jul/2012:05:50:21 -0700] Report: jobs=34 D [19/Jul/2012:05:50:21 -0700] Report: jobs-active=0 D [19/Jul/2012:05:50:21 -0700] Report: printers=1 D [19/Jul/2012:05:50:21 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:50:21 -0700] Report: stringpool-string-count=4991 D [19/Jul/2012:05:50:21 -0700] Report: stringpool-alloc-bytes=9104 D [19/Jul/2012:05:50:21 -0700] Report: stringpool-total-bytes=88648 D [19/Jul/2012:05:50:21 -0700] [Notifier] Connected to D-BUS D [19/Jul/2012:05:50:21 -0700] [Notifier] ServerStarted D [19/Jul/2012:05:50:21 -0700] cupsdAcceptClient: 16 from localhost (Domain) D [19/Jul/2012:05:50:21 -0700] cupsdReadClient: 16 WAITING Closing on EOF D [19/Jul/2012:05:50:21 -0700] cupsdCloseClient: 16 D [19/Jul/2012:05:50:21 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:50:21 -0700] cupsdAcceptClient: 16 from localhost (Domain) D [19/Jul/2012:05:50:21 -0700] cupsdReadClient: 16 POST / HTTP/1.1 D [19/Jul/2012:05:50:21 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:50:21 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:50:21 -0700] cupsdReadClient: 16 1.1 CUPS-Get-PPDs 1 D [19/Jul/2012:05:50:21 -0700] CUPS-Get-PPDs D [19/Jul/2012:05:50:21 -0700] [CGI] argv[0] = "/usr/lib/cups/daemon/cups-driverd" D [19/Jul/2012:05:50:21 -0700] [CGI] argv[1] = "list" D [19/Jul/2012:05:50:21 -0700] [CGI] argv[2] = "1" D [19/Jul/2012:05:50:21 -0700] [CGI] argv[3] = "0" D [19/Jul/2012:05:50:21 -0700] [CGI] argv[4] = "requested-attributes=all" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[8] = "HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[10] = "SERVER_ADMIN=root@linus" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[11] = "SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[13] = "USER=root" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[14] = "CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[15] = "CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[16] = "IPP_PORT=631" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[17] = "LANG=en_US.UTF8" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[18] = "REDIRECT_STATUS=1" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[19] = "GATEWAY_INTERFACE=CGI/1.1" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[20] = "SERVER_NAME=localhost" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[21] = "SERVER_PORT=631" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[22] = "REMOTE_ADDR=localhost" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[23] = "REMOTE_HOST=localhost" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[24] = "SCRIPT_NAME=/" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[25] = "SCRIPT_FILENAME=/usr/share/cups/doc-root/" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[26] = "SERVER_PROTOCOL=HTTP/1.1" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[27] = "HTTP_USER_AGENT=CUPS/1.5.3" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[28] = "REQUEST_METHOD=POST" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[29] = "CONTENT_LENGTH=75" D [19/Jul/2012:05:50:21 -0700] [CGI] envp[30] = "CONTENT_TYPE=application/ipp" D [19/Jul/2012:05:50:21 -0700] [CGI] Started /usr/lib/cups/daemon/cups-driverd (PID 6874) I [19/Jul/2012:05:50:21 -0700] Started "/usr/lib/cups/daemon/cups-driverd" (pid=6874) D [19/Jul/2012:05:50:21 -0700] cupsdSendCommand: 16 file=18 I [19/Jul/2012:05:50:22 -0700] [cups-driverd] Read "/var/cache/cups/ppds.dat", 1495 PPDs... I [19/Jul/2012:05:50:22 -0700] [cups-driverd] Read "/var/cache/cups/ppds.dat", 1495 PPDs... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/cups/model"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/cups/drv"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/ppd"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/ppd/hplip"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/ppd/hplip/HP"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/ppd/Brother"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/ppd/ghostscript"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/ppd/ghostscript/model"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/ppd/cupsfilters"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] Loading "/usr/share/ppd/custom"... D [19/Jul/2012:05:50:22 -0700] [cups-driverd] ChangedPPD=1 I [19/Jul/2012:05:50:22 -0700] [cups-driverd] Wrote "/var/cache/cups/ppds.dat", 1495 PPDs... I [19/Jul/2012:05:50:22 -0700] [cups-driverd] Wrote "/var/cache/cups/ppds.dat", 1495 PPDs... D [19/Jul/2012:05:50:25 -0700] [CGI] Cannot read file /usr/share/foomatic/db/oldprinterids! D [19/Jul/2012:05:50:25 -0700] [CGI] Cannot read directory /usr/share/foomatic/db/source/driver! D [19/Jul/2012:05:50:25 -0700] [CGI] Entity: line 1: parser error : Extra content at the end of the document D [19/Jul/2012:05:50:25 -0700] [CGI] D [19/Jul/2012:05:50:25 -0700] [CGI] ^ D [19/Jul/2012:05:50:25 -0700] Script header: Content-Type: application/ipp D [19/Jul/2012:05:50:25 -0700] Script header: D [19/Jul/2012:05:50:26 -0700] PID 6874 (/usr/lib/cups/daemon/cups-driverd) exited with no errors. D [19/Jul/2012:05:50:26 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:50:26 -0700] cupsdReadClient: 16 WAITING Closing on EOF D [19/Jul/2012:05:50:26 -0700] cupsdCloseClient: 16 D [19/Jul/2012:05:50:26 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:50:26 -0700] cupsdAcceptClient: 16 from localhost (Domain) D [19/Jul/2012:05:50:26 -0700] cupsdReadClient: 16 POST / HTTP/1.1 D [19/Jul/2012:05:50:26 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:50:26 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:50:26 -0700] cupsdReadClient: 16 1.1 Get-Printer-Attributes 1 D [19/Jul/2012:05:50:26 -0700] Get-Printer-Attributes ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:50:26 -0700] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:50:26 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:50:26 -0700] cupsdReadClient: 16 POST / HTTP/1.1 D [19/Jul/2012:05:50:26 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:50:26 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:50:26 -0700] cupsdReadClient: 16 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:50:26 -0700] CUPS-Get-Printers D [19/Jul/2012:05:50:26 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:50:26 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:50:26 -0700] cupsdReadClient: 16 WAITING Closing on EOF D [19/Jul/2012:05:50:26 -0700] cupsdCloseClient: 16 D [19/Jul/2012:05:50:26 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" I [19/Jul/2012:05:50:52 -0700] Saving subscriptions.conf... D [19/Jul/2012:05:50:52 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files" D [19/Jul/2012:05:50:53 -0700] Avahi client started I [19/Jul/2012:05:51:06 -0700] Subscription 244 has expired... D [19/Jul/2012:05:51:06 -0700] cupsdMarkDirty(-----S) D [19/Jul/2012:05:51:06 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Not busy" D [19/Jul/2012:05:51:06 -0700] [Notifier] state=-1 D [19/Jul/2012:05:51:06 -0700] [Notifier] ippReadFile() returned IPP_ERROR! D [19/Jul/2012:05:51:06 -0700] PID 6862 (/usr/lib/cups/notifier/dbus) exited with no errors. I [19/Jul/2012:05:51:37 -0700] Saving subscriptions.conf... D [19/Jul/2012:05:51:48 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files" D [19/Jul/2012:05:51:48 -0700] Report: clients=0 D [19/Jul/2012:05:51:48 -0700] Report: jobs=34 D [19/Jul/2012:05:51:48 -0700] Report: jobs-active=0 D [19/Jul/2012:05:51:48 -0700] Report: printers=1 D [19/Jul/2012:05:51:48 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:51:48 -0700] Report: stringpool-string-count=4978 D [19/Jul/2012:05:51:48 -0700] Report: stringpool-alloc-bytes=8776 D [19/Jul/2012:05:51:48 -0700] Report: stringpool-total-bytes=88408 D [19/Jul/2012:05:53:13 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:53:13 -0700] Report: clients=1 D [19/Jul/2012:05:53:13 -0700] Report: jobs=34 D [19/Jul/2012:05:53:13 -0700] Report: jobs-active=0 D [19/Jul/2012:05:53:13 -0700] Report: printers=1 D [19/Jul/2012:05:53:13 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:53:13 -0700] Report: stringpool-string-count=4978 D [19/Jul/2012:05:53:13 -0700] Report: stringpool-alloc-bytes=8776 D [19/Jul/2012:05:53:13 -0700] Report: stringpool-total-bytes=88408 D [19/Jul/2012:05:53:13 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:53:13 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:53:13 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:53:13 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Devices 1 D [19/Jul/2012:05:53:13 -0700] CUPS-Get-Devices D [19/Jul/2012:05:53:13 -0700] cupsdIsAuthorized: username="" D [19/Jul/2012:05:53:13 -0700] Returning HTTP Unauthorized for CUPS-Get-Devices (no URI) from localhost D [19/Jul/2012:05:53:13 -0700] cupsdSendHeader: 17 WWW-Authenticate: Basic realm="CUPS", trc="y" D [19/Jul/2012:05:53:13 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:53:13 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:53:13 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:53:13 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:53:13 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:53:13 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:53:13 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:53:13 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:53:13 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:53:13 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:53:13 -0700] cupsdAuthorize: Authorized as root using PeerCred D [19/Jul/2012:05:53:13 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Devices 1 D [19/Jul/2012:05:53:13 -0700] CUPS-Get-Devices D [19/Jul/2012:05:53:13 -0700] cupsdIsAuthorized: username="root" D [19/Jul/2012:05:53:13 -0700] [CGI] argv[0] = "/usr/lib/cups/daemon/cups-deviced" D [19/Jul/2012:05:53:13 -0700] [CGI] argv[1] = "1" D [19/Jul/2012:05:53:13 -0700] [CGI] argv[2] = "0" D [19/Jul/2012:05:53:13 -0700] [CGI] argv[3] = "2" D [19/Jul/2012:05:53:13 -0700] [CGI] argv[4] = "7" D [19/Jul/2012:05:53:13 -0700] [CGI] argv[5] = "requested-attributes=all exclude-schemes='beh','cups-pdf','bluetooth','dnssd','http','https','ipp','lpd','ncp','parallel','scsi','smb','snmp','socket'" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[8] = "HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[10] = "SERVER_ADMIN=root@linus" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[11] = "SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[13] = "USER=root" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[14] = "CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[15] = "CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[16] = "IPP_PORT=631" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[17] = "AUTH_TYPE=PeerCred" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[18] = "LANG=en_US.UTF8" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[19] = "REDIRECT_STATUS=1" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[20] = "GATEWAY_INTERFACE=CGI/1.1" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[21] = "SERVER_NAME=localhost" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[22] = "SERVER_PORT=631" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[23] = "REMOTE_ADDR=localhost" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[24] = "REMOTE_HOST=localhost" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[25] = "SCRIPT_NAME=/" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[26] = "SCRIPT_FILENAME=/usr/share/cups/doc-root/" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[27] = "REMOTE_USER=root" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[28] = "SERVER_PROTOCOL=HTTP/1.1" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[29] = "HTTP_USER_AGENT=CUPS/1.5.3" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[30] = "REQUEST_METHOD=POST" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[31] = "CONTENT_LENGTH=244" D [19/Jul/2012:05:53:13 -0700] [CGI] envp[32] = "CONTENT_TYPE=application/ipp" D [19/Jul/2012:05:53:13 -0700] [CGI] Started /usr/lib/cups/daemon/cups-deviced (PID 7199) I [19/Jul/2012:05:53:13 -0700] Started "/usr/lib/cups/daemon/cups-deviced" (pid=7199) D [19/Jul/2012:05:53:13 -0700] cupsdSendCommand: 18 file=17 D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/usb (PID 7200) D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/ipps (PID 7201) D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/mdns (PID 7202) D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/hpfax (PID 7203) D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/ipp14 (PID 7204) D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/hp (PID 7205) D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/serial (PID 7206) D [19/Jul/2012:05:53:13 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Found device "ipps"... D [19/Jul/2012:05:53:13 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Found device "ipp14"... D [19/Jul/2012:05:53:13 -0700] [cups-deviced] PID 7201 (ipps) exited with no errors. D [19/Jul/2012:05:53:13 -0700] [cups-deviced] PID 7202 (mdns) exited with no errors. D [19/Jul/2012:05:53:13 -0700] [cups-deviced] PID 7204 (ipp14) exited with no errors. D [19/Jul/2012:05:53:13 -0700] Script header: Content-Type: application/ipp D [19/Jul/2012:05:53:13 -0700] Script header: D [19/Jul/2012:05:53:13 -0700] [CGI] list_devices D [19/Jul/2012:05:53:13 -0700] [CGI] libusb_get_device_list=13 D [19/Jul/2012:05:53:13 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Found device "usb://Brother/HL-1440%20series"... D [19/Jul/2012:05:53:13 -0700] [cups-deviced] PID 7206 (serial) exited with no errors. D [19/Jul/2012:05:53:13 -0700] [cups-deviced] PID 7200 (usb) exited with no errors. D [19/Jul/2012:05:53:13 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:53:13 -0700] [cups-deviced] Found device "hp"... D [19/Jul/2012:05:53:13 -0700] [cups-deviced] PID 7205 (hp) exited with no errors. D [19/Jul/2012:05:53:14 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:53:14 -0700] [cups-deviced] Found device "hpfax"... D [19/Jul/2012:05:53:14 -0700] [cups-deviced] PID 7203 (hpfax) exited with no errors. D [19/Jul/2012:05:53:14 -0700] PID 7199 (/usr/lib/cups/daemon/cups-deviced) exited with no errors. D [19/Jul/2012:05:53:14 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:53:14 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:53:14 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:53:14 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:53:14 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:53:14 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:53:14 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:53:14 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:53:14 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:53:14 -0700] CUPS-Get-Printers D [19/Jul/2012:05:53:14 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:53:14 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:53:14 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:53:14 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:53:14 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:54:25 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:54:25 -0700] Report: clients=1 D [19/Jul/2012:05:54:25 -0700] Report: jobs=34 D [19/Jul/2012:05:54:25 -0700] Report: jobs-active=0 D [19/Jul/2012:05:54:25 -0700] Report: printers=1 D [19/Jul/2012:05:54:25 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:54:25 -0700] Report: stringpool-string-count=4978 D [19/Jul/2012:05:54:25 -0700] Report: stringpool-alloc-bytes=8776 D [19/Jul/2012:05:54:25 -0700] Report: stringpool-total-bytes=88408 D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:54:25 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:54:25 -0700] CUPS-Get-Printers D [19/Jul/2012:05:54:25 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:54:25 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:54:25 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 17 POST /admin/ HTTP/1.1 D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:54:25 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 17 1.1 Pause-Printer 1 D [19/Jul/2012:05:54:25 -0700] Pause-Printer ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:54:25 -0700] cupsdIsAuthorized: username="" D [19/Jul/2012:05:54:25 -0700] Returning HTTP Unauthorized for Pause-Printer (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:54:25 -0700] cupsdSendHeader: 17 WWW-Authenticate: Basic realm="CUPS", trc="y" D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:54:25 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:54:25 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:54:25 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:54:25 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 18 POST /admin/ HTTP/1.1 D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:54:25 -0700] cupsdAuthorize: Authorized as root using PeerCred D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 18 1.1 Pause-Printer 1 D [19/Jul/2012:05:54:25 -0700] Pause-Printer ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:54:25 -0700] cupsdIsAuthorized: username="root" D [19/Jul/2012:05:54:25 -0700] Discarding unused printer-stopped event... D [19/Jul/2012:05:54:25 -0700] cupsdMarkDirty(P-----) D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients" D [19/Jul/2012:05:54:25 -0700] cupsdRegisterPrinter(p=0xb8d58a48(HL-1440-series)) D [19/Jul/2012:05:54:25 -0700] cupsdMarkDirty(P-----) D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" I [19/Jul/2012:05:54:25 -0700] Printer "HL-1440-series" stopped by "root". D [19/Jul/2012:05:54:25 -0700] Returning IPP successful-ok for Pause-Printer (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:54:25 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:54:25 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:54:25 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Devices 1 D [19/Jul/2012:05:54:31 -0700] CUPS-Get-Devices D [19/Jul/2012:05:54:31 -0700] cupsdIsAuthorized: username="" D [19/Jul/2012:05:54:31 -0700] Returning HTTP Unauthorized for CUPS-Get-Devices (no URI) from localhost D [19/Jul/2012:05:54:31 -0700] cupsdSendHeader: 17 WWW-Authenticate: Basic realm="CUPS", trc="y" D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:54:31 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:54:31 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:54:31 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAuthorize: Authorized as root using PeerCred D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Devices 1 D [19/Jul/2012:05:54:31 -0700] CUPS-Get-Devices D [19/Jul/2012:05:54:31 -0700] cupsdIsAuthorized: username="root" D [19/Jul/2012:05:54:31 -0700] [CGI] argv[0] = "/usr/lib/cups/daemon/cups-deviced" D [19/Jul/2012:05:54:31 -0700] [CGI] argv[1] = "1" D [19/Jul/2012:05:54:31 -0700] [CGI] argv[2] = "0" D [19/Jul/2012:05:54:31 -0700] [CGI] argv[3] = "2" D [19/Jul/2012:05:54:31 -0700] [CGI] argv[4] = "7" D [19/Jul/2012:05:54:31 -0700] [CGI] argv[5] = "requested-attributes=all exclude-schemes='beh','cups-pdf','bluetooth','dnssd','http','https','ipp','lpd','ncp','parallel','scsi','smb','snmp','socket'" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[0] = "CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[1] = "CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[2] = "CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[3] = "CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[4] = "CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[5] = "CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[6] = "CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[7] = "CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[8] = "HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[9] = "PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[10] = "SERVER_ADMIN=root@linus" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[11] = "SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[12] = "TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[13] = "USER=root" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[14] = "CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[15] = "CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[16] = "IPP_PORT=631" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[17] = "AUTH_TYPE=PeerCred" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[18] = "LANG=en_US.UTF8" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[19] = "REDIRECT_STATUS=1" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[20] = "GATEWAY_INTERFACE=CGI/1.1" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[21] = "SERVER_NAME=localhost" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[22] = "SERVER_PORT=631" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[23] = "REMOTE_ADDR=localhost" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[24] = "REMOTE_HOST=localhost" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[25] = "SCRIPT_NAME=/" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[26] = "SCRIPT_FILENAME=/usr/share/cups/doc-root/" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[27] = "REMOTE_USER=root" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[28] = "SERVER_PROTOCOL=HTTP/1.1" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[29] = "HTTP_USER_AGENT=CUPS/1.5.3" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[30] = "REQUEST_METHOD=POST" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[31] = "CONTENT_LENGTH=244" D [19/Jul/2012:05:54:31 -0700] [CGI] envp[32] = "CONTENT_TYPE=application/ipp" D [19/Jul/2012:05:54:31 -0700] [CGI] Started /usr/lib/cups/daemon/cups-deviced (PID 7287) I [19/Jul/2012:05:54:31 -0700] Started "/usr/lib/cups/daemon/cups-deviced" (pid=7287) D [19/Jul/2012:05:54:31 -0700] cupsdSendCommand: 18 file=17 D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/usb (PID 7288) D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/ipps (PID 7289) D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/mdns (PID 7290) D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/hpfax (PID 7291) D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/ipp14 (PID 7292) D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/hp (PID 7293) D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Started backend /usr/lib/cups/backend/serial (PID 7294) D [19/Jul/2012:05:54:31 -0700] [CGI] list_devices D [19/Jul/2012:05:54:31 -0700] Script header: Content-Type: application/ipp D [19/Jul/2012:05:54:31 -0700] Script header: D [19/Jul/2012:05:54:31 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Found device "ipps"... D [19/Jul/2012:05:54:31 -0700] [cups-deviced] PID 7289 (ipps) exited with no errors. D [19/Jul/2012:05:54:31 -0700] [cups-deviced] PID 7290 (mdns) exited with no errors. D [19/Jul/2012:05:54:31 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Found device "ipp14"... D [19/Jul/2012:05:54:31 -0700] [CGI] libusb_get_device_list=13 D [19/Jul/2012:05:54:31 -0700] [cups-deviced] PID 7292 (ipp14) exited with no errors. D [19/Jul/2012:05:54:31 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Found device "hp"... D [19/Jul/2012:05:54:31 -0700] [cups-deviced] PID 7293 (hp) exited with no errors. D [19/Jul/2012:05:54:31 -0700] [cups-deviced] PID 7294 (serial) exited with no errors. D [19/Jul/2012:05:54:31 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Found device "usb://Brother/HL-1440%20series"... D [19/Jul/2012:05:54:31 -0700] [cups-deviced] PID 7288 (usb) exited with no errors. D [19/Jul/2012:05:54:31 -0700] [CGI] Flushed attributes... D [19/Jul/2012:05:54:31 -0700] [cups-deviced] Found device "hpfax"... D [19/Jul/2012:05:54:31 -0700] [cups-deviced] PID 7291 (hpfax) exited with no errors. D [19/Jul/2012:05:54:31 -0700] PID 7287 (/usr/lib/cups/daemon/cups-deviced) exited with no errors. D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:54:31 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:54:31 -0700] CUPS-Get-Printers D [19/Jul/2012:05:54:31 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:54:31 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 POST /admin/ HTTP/1.1 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 1.1 Resume-Printer 1 D [19/Jul/2012:05:54:31 -0700] Resume-Printer ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:54:31 -0700] cupsdIsAuthorized: username="" D [19/Jul/2012:05:54:31 -0700] Returning HTTP Unauthorized for Resume-Printer (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:54:31 -0700] cupsdSendHeader: 17 WWW-Authenticate: Basic realm="CUPS", trc="y" D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:54:31 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:54:31 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:54:31 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 18 POST /admin/ HTTP/1.1 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdAuthorize: Authorized as root using PeerCred D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 18 1.1 Resume-Printer 1 D [19/Jul/2012:05:54:31 -0700] Resume-Printer ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:54:31 -0700] cupsdIsAuthorized: username="root" D [19/Jul/2012:05:54:31 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:54:31 -0700] cupsdMarkDirty(P-----) D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdRegisterPrinter(p=0xb8d58a48(HL-1440-series)) D [19/Jul/2012:05:54:31 -0700] cupsdMarkDirty(P-----) D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" I [19/Jul/2012:05:54:31 -0700] Printer "HL-1440-series" started by "root". D [19/Jul/2012:05:54:31 -0700] Returning IPP successful-ok for Resume-Printer (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:54:31 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:54:31 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:54:31 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" I [19/Jul/2012:05:54:56 -0700] Saving printers.conf... D [19/Jul/2012:05:54:56 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files" D [19/Jul/2012:05:55:02 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:55:02 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:02 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:02 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Default 1 D [19/Jul/2012:05:55:02 -0700] CUPS-Get-Default D [19/Jul/2012:05:55:02 -0700] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:02 -0700] cupsdReadClient: 17 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:02 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:02 -0700] cupsdReadClient: 17 1.1 Create-Job 1 D [19/Jul/2012:05:55:02 -0700] Create-Job ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:55:02 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients" D [19/Jul/2012:05:55:02 -0700] add_job: requesting-user-name="gary" I [19/Jul/2012:05:55:02 -0700] [Job 296] Adding start banner page "none". D [19/Jul/2012:05:55:02 -0700] Discarding unused job-created event... I [19/Jul/2012:05:55:02 -0700] [Job 296] Queued on "HL-1440-series" by "gary". D [19/Jul/2012:05:55:02 -0700] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:02 -0700] cupsdReadClient: 17 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:55:02 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:02 -0700] cupsdReadClient: 17 1.1 Send-Document 1 D [19/Jul/2012:05:55:02 -0700] Send-Document ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:55:02 -0700] cupsdIsAuthorized: requesting-user-name="gary" D [19/Jul/2012:05:55:02 -0700] [Job 296] Auto-typing file... D [19/Jul/2012:05:55:02 -0700] [Job 296] Request file type is application/postscript. D [19/Jul/2012:05:55:02 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" I [19/Jul/2012:05:55:02 -0700] [Job 296] File of type application/postscript queued by "gary". I [19/Jul/2012:05:55:02 -0700] [Job 296] Adding end banner page "none". D [19/Jul/2012:05:55:02 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:02 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:02 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:55:02 -0700] [Job 296] job-sheets=none,none D [19/Jul/2012:05:55:02 -0700] [Job 296] argv[0]="HL-1440-series" D [19/Jul/2012:05:55:02 -0700] [Job 296] argv[1]="296" D [19/Jul/2012:05:55:02 -0700] [Job 296] argv[2]="gary" D [19/Jul/2012:05:55:02 -0700] [Job 296] argv[3]="(stdin)" D [19/Jul/2012:05:55:02 -0700] [Job 296] argv[4]="1" D [19/Jul/2012:05:55:02 -0700] [Job 296] argv[5]="finishings=3 number-up=1 usb-no-reattach nousb-unidir job-uuid=urn:uuid:5873d2ee-bfc8-3a5c-4e4e-80ab0f15a231 job-originating-host-name=localhost time-at-creation=1342702502 time-at-processing=1342702502" D [19/Jul/2012:05:55:02 -0700] [Job 296] argv[6]="/var/spool/cups/d00296-001" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[0]="CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[1]="CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[4]="CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[5]="CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[6]="CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[7]="CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[8]="HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[10]="SERVER_ADMIN=root@linus" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[11]="SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[12]="TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[13]="USER=root" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[15]="CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[16]="IPP_PORT=631" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[17]="CHARSET=utf-8" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[18]="LANG=en_US.UTF-8" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[19]="PPD=/etc/cups/ppd/HL-1440-series.ppd" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[20]="RIP_MAX_CACHE=128m" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[21]="CONTENT_TYPE=application/postscript" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[22]="DEVICE_URI=usb://Brother/HL-1440%20series" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[23]="PRINTER_INFO=Brother HL-1440 series" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[24]="PRINTER_LOCATION=linus" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[25]="PRINTER=HL-1440-series" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[26]="PRINTER_STATE_REASONS=none" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[27]="CUPS_FILETYPE=document" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[28]="FINAL_CONTENT_TYPE=printer/HL-1440-series" D [19/Jul/2012:05:55:02 -0700] [Job 296] envp[29]="AUTH_I****" I [19/Jul/2012:05:55:02 -0700] [Job 296] Started filter /usr/lib/cups/filter/pstopdf (PID 7303) I [19/Jul/2012:05:55:02 -0700] [Job 296] Started filter /usr/lib/cups/filter/pdftopdf (PID 7304) I [19/Jul/2012:05:55:02 -0700] [Job 296] Started filter /usr/lib/cups/filter/foomatic-rip (PID 7305) I [19/Jul/2012:05:55:02 -0700] [Job 296] Started backend /usr/lib/cups/backend/usb (PID 7306) D [19/Jul/2012:05:55:02 -0700] Discarding unused job-state-changed event... D [19/Jul/2012:05:55:02 -0700] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:02 -0700] [Job 296] Printing on printer with URI: usb://Brother/HL-1440%20series D [19/Jul/2012:05:55:02 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:55:02 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:55:02 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:02 -0700] [Job 296] libusb_get_device_list=13 D [19/Jul/2012:05:55:02 -0700] [Job 296] pstopdf 6 args: 296 gary (stdin) 1 finishings=3 number-up=1 usb-no-reattach nousb-unidir job-uuid=urn:uuid:5873d2ee-bfc8-3a5c-4e4e-80ab0f15a231 job-originating-host-name=localhost time-at-creation=1342702502 time-at-processing=1342702502 /var/spool/cups/d00296-001 D [19/Jul/2012:05:55:02 -0700] [Job 296] PPD: /etc/cups/ppd/HL-1440-series.ppd D [19/Jul/2012:05:55:02 -0700] [Job 296] Resolution: 300x300 D [19/Jul/2012:05:55:02 -0700] [Job 296] Page size: Letter D [19/Jul/2012:05:55:02 -0700] [Job 296] Width: 612, height: 792, absolute margins: 18, 36, 594, 756 D [19/Jul/2012:05:55:02 -0700] [Job 296] Getting input from file D [19/Jul/2012:05:55:02 -0700] [Job 296] foomatic-rip version 4.0.16.253 running... D [19/Jul/2012:05:55:02 -0700] [Job 296] Parsing PPD file ... D [19/Jul/2012:05:55:02 -0700] [Job 296] Added option ColorSpace D [19/Jul/2012:05:55:02 -0700] [Job 296] Added option PageSize D [19/Jul/2012:05:55:02 -0700] [Job 296] Added option ImageableArea D [19/Jul/2012:05:55:02 -0700] [Job 296] Added option PaperDimension D [19/Jul/2012:05:55:02 -0700] [Job 296] Added option MediaType D [19/Jul/2012:05:55:02 -0700] [Job 296] Added option EconoMode D [19/Jul/2012:05:55:02 -0700] [Job 296] Added option InputSlot D [19/Jul/2012:05:55:02 -0700] [Job 296] Added option Resolution D [19/Jul/2012:05:55:02 -0700] [Job 296] Added option Font D [19/Jul/2012:05:55:02 -0700] [Job 296] D [19/Jul/2012:05:55:02 -0700] [Job 296] Parameter Summary D [19/Jul/2012:05:55:02 -0700] [Job 296] ----------------- D [19/Jul/2012:05:55:02 -0700] [Job 296] D [19/Jul/2012:05:55:02 -0700] [Job 296] Spooler: cups D [19/Jul/2012:05:55:02 -0700] [Job 296] Printer: HL-1440-series D [19/Jul/2012:05:55:02 -0700] [Job 296] Shell: /bin/bash D [19/Jul/2012:05:55:02 -0700] [Job 296] PPD file: /etc/cups/ppd/HL-1440-series.ppd D [19/Jul/2012:05:55:02 -0700] [Job 296] ATTR file: D [19/Jul/2012:05:55:02 -0700] [Job 296] Printer model: Brother HL-1440 Foomatic/hl1250 (recommended) D [19/Jul/2012:05:55:02 -0700] [Job 296] Job title: stdin D [19/Jul/2012:05:55:02 -0700] [Job 296] File(s) to be printed: D [19/Jul/2012:05:55:02 -0700] [Job 296] D [19/Jul/2012:05:55:02 -0700] [Job 296] D [19/Jul/2012:05:55:02 -0700] [Job 296] Ghostscript extra search path ('GS_LIB'): /usr/share/cups/fonts D [19/Jul/2012:05:55:02 -0700] [Job 296] Printing system options: D [19/Jul/2012:05:55:02 -0700] [Job 296] Pondering option 'finishings=3' D [19/Jul/2012:05:55:02 -0700] [Job 296] Unknown option finishings=3. D [19/Jul/2012:05:55:02 -0700] [Job 296] Pondering option 'number-up=1' D [19/Jul/2012:05:55:02 -0700] [Job 296] Unknown option number-up=1. D [19/Jul/2012:05:55:02 -0700] [Job 296] Pondering option 'usb-no-reattach' D [19/Jul/2012:05:55:02 -0700] [Job 296] Unknown boolean option "usb-no-reattach". D [19/Jul/2012:05:55:02 -0700] [Job 296] Pondering option 'nousb-unidir' D [19/Jul/2012:05:55:02 -0700] [Job 296] Unknown boolean option "nousb-unidir". D [19/Jul/2012:05:55:02 -0700] [Job 296] Pondering option 'job-uuid=urn:uuid:5873d2ee-bfc8-3a5c-4e4e-80ab0f15a231' D [19/Jul/2012:05:55:02 -0700] [Job 296] Unknown option job-uuid=urn:uuid:5873d2ee-bfc8-3a5c-4e4e-80ab0f15a231. D [19/Jul/2012:05:55:02 -0700] [Job 296] Pondering option 'job-originating-host-name=localhost' D [19/Jul/2012:05:55:02 -0700] [Job 296] Unknown option job-originating-host-name=localhost. D [19/Jul/2012:05:55:02 -0700] [Job 296] Pondering option 'time-at-creation=1342702502' D [19/Jul/2012:05:55:02 -0700] [Job 296] Unknown option time-at-creation=1342702502. D [19/Jul/2012:05:55:02 -0700] [Job 296] Pondering option 'time-at-processing=1342702502' D [19/Jul/2012:05:55:02 -0700] [Job 296] Unknown option time-at-processing=1342702502. D [19/Jul/2012:05:55:02 -0700] [Job 296] Options from the PPD file: D [19/Jul/2012:05:55:02 -0700] [Job 296] D [19/Jul/2012:05:55:02 -0700] [Job 296] ================================================ D [19/Jul/2012:05:55:02 -0700] [Job 296] D [19/Jul/2012:05:55:02 -0700] [Job 296] File: D [19/Jul/2012:05:55:02 -0700] [Job 296] D [19/Jul/2012:05:55:02 -0700] [Job 296] ================================================ D [19/Jul/2012:05:55:02 -0700] [Job 296] D [19/Jul/2012:05:55:02 -0700] [Job 296] Relative margins: 18, 36, 18, 36 D [19/Jul/2012:05:55:02 -0700] [Job 296] PPD options: -r300 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 D [19/Jul/2012:05:55:02 -0700] [Job 296] PostScript to be injected: D [19/Jul/2012:05:55:02 -0700] [Job 296] STATE: +connecting-to-device D [19/Jul/2012:05:55:02 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:55:02 -0700] [Job 296] STATE: -connecting-to-device D [19/Jul/2012:05:55:02 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:55:03 -0700] [Job 296] Device protocol: 2 D [19/Jul/2012:05:55:03 -0700] [Job 296] Printer reports bi-di support but in reality works only uni-directionally D [19/Jul/2012:05:55:03 -0700] [Job 296] Uni-directional USB communication only! D [19/Jul/2012:05:55:03 -0700] [Job 296] Printer does not like usblp kernel module to be re-attached after job D [19/Jul/2012:05:55:03 -0700] [Job 296] Forced not re-attaching the usblp kernel module after the job via "usb-no-reattach" option. D [19/Jul/2012:05:55:03 -0700] [Job 296] Uni-directional device/mode, back channel deactivated. I [19/Jul/2012:05:55:03 -0700] [Job 296] Sending data to printer. D [19/Jul/2012:05:55:03 -0700] [Job 296] Set job-printer-state-message to "Sending data to printer.", current level=INFO D [19/Jul/2012:05:55:03 -0700] Discarding unused job-progress event... D [19/Jul/2012:05:55:03 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:55:03 -0700] [Job 296] Running cat | /usr/bin/gs -q -dNOPAUSE -dBATCH -sDEVICE=pdfwrite -dCompatibilityLevel=1.3 -dAutoRotatePages=/None -dAutoFilterColorImages=false -dNOPLATFONTS -dPARANOIDSAFER -dNOINTERPOLATE -sstdout=%stderr -dColorImageFilter=/FlateEncode -dPDFSETTINGS=/printer -dColorConversionStrategy=/LeaveColorUnchanged -dDoNumCopies -r300 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -sOutputFile=- -c .setpdfwrite -f - D [19/Jul/2012:05:55:04 -0700] PID 7303 (/usr/lib/cups/filter/pstopdf) exited with no errors. D [19/Jul/2012:05:55:04 -0700] [Job 296] Filetype: PDF D [19/Jul/2012:05:55:04 -0700] [Job 296] Storing temporary files in /var/spool/cups/tmp D [19/Jul/2012:05:55:04 -0700] PID 7304 (/usr/lib/cups/filter/pdftopdf) exited with no errors. D [19/Jul/2012:05:55:04 -0700] [Job 296] File contains 2 pages D [19/Jul/2012:05:55:04 -0700] [Job 296] Starting renderer with command: gs -dFirstPage=1 -q -dBATCH -dPARANOIDSAFER -dNOPAUSE -dNOINTERPOLATE -sDEVICE=hl1250 -dEconoMode=0 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -r300x300 -dSourceTray=0 -sOutputFile=- -f /var/spool/cups/tmp/foomatic-fihKWF D [19/Jul/2012:05:55:04 -0700] [Job 296] Starting process "kid3" (generation 1) D [19/Jul/2012:05:55:04 -0700] [Job 296] Starting process "kid4" (generation 2) D [19/Jul/2012:05:55:04 -0700] [Job 296] Starting process "renderer" (generation 2) D [19/Jul/2012:05:55:04 -0700] [Job 296] JCL: %-12345X@PJL D [19/Jul/2012:05:55:04 -0700] [Job 296] @PJL SET MEDIATYPE=REGULAR D [19/Jul/2012:05:55:04 -0700] [Job 296] %-12345X@PJL RESET D [19/Jul/2012:05:55:04 -0700] [Job 296] D [19/Jul/2012:05:55:04 -0700] [Job 296] D [19/Jul/2012:05:55:04 -0700] [Job 296] Read 4096 bytes of print data... D [19/Jul/2012:05:55:04 -0700] [Job 296] Wrote 4096 bytes of print data... D [19/Jul/2012:05:55:04 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:04 -0700] [Job 296] renderer exited with status 0 D [19/Jul/2012:05:55:04 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:04 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:05 -0700] [Job 296] kid4 exited with status 0 D [19/Jul/2012:05:55:05 -0700] [Job 296] kid3 finished D [19/Jul/2012:05:55:05 -0700] [Job 296] Kid3 exit status: 0 D [19/Jul/2012:05:55:05 -0700] [Job 296] D [19/Jul/2012:05:55:05 -0700] [Job 296] Closing foomatic-rip. D [19/Jul/2012:05:55:05 -0700] PID 7305 (/usr/lib/cups/filter/foomatic-rip) exited with no errors. D [19/Jul/2012:05:55:06 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:06 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:11 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:12 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:12 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Classes 1 D [19/Jul/2012:05:55:12 -0700] CUPS-Get-Classes D [19/Jul/2012:05:55:12 -0700] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from localhost D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Default 1 D [19/Jul/2012:05:55:12 -0700] CUPS-Get-Default D [19/Jul/2012:05:55:12 -0700] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 19 1.1 Create-Printer-Subscription 1 D [19/Jul/2012:05:55:12 -0700] Create-Printer-Subscription / D [19/Jul/2012:05:55:12 -0700] cupsdCreateSubscription(con=0xb8db7f78(19), uri="/") D [19/Jul/2012:05:55:12 -0700] pullmethod="ippget" D [19/Jul/2012:05:55:12 -0700] notify-lease-duration=86400 D [19/Jul/2012:05:55:12 -0700] notify-time-interval=0 D [19/Jul/2012:05:55:12 -0700] cupsdAddSubscription(mask=18f, dest=(nil)(), job=(nil)(0), uri="(null)") D [19/Jul/2012:05:55:12 -0700] Added subscription #245 for server. D [19/Jul/2012:05:55:12 -0700] cupsdMarkDirty(-----S) D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] Returning IPP successful-ok for Create-Printer-Subscription (/) from localhost D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:12 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:12 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:12 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:12 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:12 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:12 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:12 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:12 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Classes 1 D [19/Jul/2012:05:55:12 -0700] CUPS-Get-Classes D [19/Jul/2012:05:55:12 -0700] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from localhost D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:12 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:12 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Default 1 D [19/Jul/2012:05:55:12 -0700] CUPS-Get-Default D [19/Jul/2012:05:55:12 -0700] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [19/Jul/2012:05:55:12 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:12 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:12 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:12 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:12 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:12 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:12 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:13 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:13 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:13 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:13 -0700] [Job 296] Read 8192 bytes of print data... D [19/Jul/2012:05:55:13 -0700] [Job 296] Wrote 8192 bytes of print data... D [19/Jul/2012:05:55:13 -0700] [Job 296] Read 1964 bytes of print data... D [19/Jul/2012:05:55:13 -0700] [Job 296] Wrote 1964 bytes of print data... D [19/Jul/2012:05:55:13 -0700] [Job 296] Sent 128940 bytes... D [19/Jul/2012:05:55:13 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:13 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:13 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:13 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:13 -0700] cupsdReadClient: 19 1.1 Get-Notifications 1 D [19/Jul/2012:05:55:13 -0700] Get-Notifications / D [19/Jul/2012:05:55:13 -0700] cupsdIsAuthorized: requesting-user-name="gary" D [19/Jul/2012:05:55:13 -0700] Returning IPP successful-ok for Get-Notifications (/) from localhost D [19/Jul/2012:05:55:13 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:55:13 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:13 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:13 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:13 -0700] [Job 296] Resetting printer. D [19/Jul/2012:05:55:13 -0700] PID 7306 (/usr/lib/cups/backend/usb) exited with no errors. D [19/Jul/2012:05:55:13 -0700] Discarding unused job-completed event... I [19/Jul/2012:05:55:13 -0700] [Job 296] Job completed. D [19/Jul/2012:05:55:13 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:55:13 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:13 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:13 -0700] cupsdMarkDirty(-----S) D [19/Jul/2012:05:55:13 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:14 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:14 -0700] [Job 296] Unloading... D [19/Jul/2012:05:55:14 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:55:14 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:55:14 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:14 -0700] cupsdReadClient: 18 1.1 Get-Notifications 1 D [19/Jul/2012:05:55:14 -0700] Get-Notifications / D [19/Jul/2012:05:55:14 -0700] cupsdIsAuthorized: requesting-user-name="gary" D [19/Jul/2012:05:55:14 -0700] Returning IPP successful-ok for Get-Notifications (/) from localhost D [19/Jul/2012:05:55:14 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:14 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:14 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:14 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:55:14 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:14 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:55:14 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:14 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:14 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:14 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:14 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:14 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:14 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:55:14 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:14 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Classes 1 D [19/Jul/2012:05:55:14 -0700] CUPS-Get-Classes D [19/Jul/2012:05:55:14 -0700] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from localhost D [19/Jul/2012:05:55:14 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:14 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:14 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:55:14 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:14 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Default 1 D [19/Jul/2012:05:55:14 -0700] CUPS-Get-Default D [19/Jul/2012:05:55:14 -0700] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [19/Jul/2012:05:55:14 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:15 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:15 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:55:15 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:55:15 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:15 -0700] cupsdReadClient: 18 1.1 Cancel-Subscription 1 D [19/Jul/2012:05:55:15 -0700] Cancel-Subscription / D [19/Jul/2012:05:55:15 -0700] cupsdIsAuthorized: requesting-user-name="gary" D [19/Jul/2012:05:55:15 -0700] cupsdMarkDirty(-----S) D [19/Jul/2012:05:55:15 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:15 -0700] Returning IPP successful-ok for Cancel-Subscription (/) from localhost D [19/Jul/2012:05:55:15 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:55:15 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:15 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:15 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:55:16 -0700] cupsdReadClient: 17 WAITING Closing on EOF D [19/Jul/2012:05:55:16 -0700] cupsdCloseClient: 17 D [19/Jul/2012:05:55:16 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" I [19/Jul/2012:05:55:33 -0700] Saving job.cache... I [19/Jul/2012:05:55:33 -0700] Saving subscriptions.conf... D [19/Jul/2012:05:55:33 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files" D [19/Jul/2012:05:55:33 -0700] Report: clients=0 D [19/Jul/2012:05:55:33 -0700] Report: jobs=35 D [19/Jul/2012:05:55:33 -0700] Report: jobs-active=0 D [19/Jul/2012:05:55:33 -0700] Report: printers=1 D [19/Jul/2012:05:55:33 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:55:33 -0700] Report: stringpool-string-count=4981 D [19/Jul/2012:05:55:33 -0700] Report: stringpool-alloc-bytes=8816 D [19/Jul/2012:05:55:33 -0700] Report: stringpool-total-bytes=88464 D [19/Jul/2012:05:55:39 -0700] cupsdAcceptClient: 17 from localhost (Domain) D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:39 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:39 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:39 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:39 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Default 1 D [19/Jul/2012:05:55:39 -0700] CUPS-Get-Default D [19/Jul/2012:05:55:39 -0700] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:39 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:39 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:39 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 17 POST / HTTP/1.1 D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:39 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 17 1.1 CUPS-Get-Default 1 D [19/Jul/2012:05:55:39 -0700] CUPS-Get-Default D [19/Jul/2012:05:55:39 -0700] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:39 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:39 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:39 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:39 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:39 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:39 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:39 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:39 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:39 -0700] cupsdReadClient: 18 GET /printers/HL-1440-series.ppd HTTP/1.1 D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:39 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:39 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:40 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:40 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:40 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:40 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:40 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:40 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:40 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:40 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:40 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:40 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:40 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:40 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:40 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:40 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:41 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:41 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:41 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:41 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:41 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:41 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:41 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:41 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:41 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:41 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:41 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:41 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:41 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:41 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:42 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:42 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:42 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:42 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:42 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:42 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:42 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:42 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:42 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:42 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:42 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:42 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:42 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:42 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:43 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:43 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:43 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:43 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:43 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:43 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:43 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:43 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:43 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:43 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:43 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:43 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:43 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:43 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:44 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:44 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:44 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:44 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:44 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:44 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:44 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:44 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:55:44 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:55:44 -0700] CUPS-Get-Printers D [19/Jul/2012:05:55:44 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:55:44 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:55:44 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:55:44 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:56:00 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:56:00 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:56:00 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:56:00 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:56:00 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:56:00 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:56:00 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:56:00 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:00 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:56:00 -0700] CUPS-Get-Printers D [19/Jul/2012:05:56:00 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:56:00 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:56:00 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:56:00 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:56:00 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:00 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Default 1 D [19/Jul/2012:05:56:00 -0700] CUPS-Get-Default D [19/Jul/2012:05:56:00 -0700] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [19/Jul/2012:05:56:00 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:56:00 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:56:00 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:56:00 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:56:06 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:56:06 -0700] cupsdReadClient: 18 WAITING Closing on EOF D [19/Jul/2012:05:56:06 -0700] cupsdCloseClient: 18 D [19/Jul/2012:05:56:06 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy" D [19/Jul/2012:05:56:06 -0700] cupsdAcceptClient: 18 from localhost (Domain) D [19/Jul/2012:05:56:06 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:56:06 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:56:06 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:06 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:56:06 -0700] CUPS-Get-Printers D [19/Jul/2012:05:56:06 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:56:06 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:56:06 -0700] cupsdReadClient: 18 POST / HTTP/1.1 D [19/Jul/2012:05:56:06 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:56:06 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:06 -0700] cupsdReadClient: 18 1.1 CUPS-Get-Default 1 D [19/Jul/2012:05:56:06 -0700] CUPS-Get-Default D [19/Jul/2012:05:56:06 -0700] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost D [19/Jul/2012:05:56:06 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:56:16 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:16 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:56:16 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:16 -0700] cupsdReadClient: 18 1.1 Create-Job 1 D [19/Jul/2012:05:56:16 -0700] Create-Job ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:16 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:16 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients" D [19/Jul/2012:05:56:16 -0700] add_job: requesting-user-name="gary" D [19/Jul/2012:05:56:16 -0700] Adding default job-sheets values "none,none"... I [19/Jul/2012:05:56:16 -0700] [Job 297] Adding start banner page "none". D [19/Jul/2012:05:56:16 -0700] Discarding unused job-created event... I [19/Jul/2012:05:56:16 -0700] [Job 297] Queued on "HL-1440-series" by "gary". D [19/Jul/2012:05:56:16 -0700] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:16 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:16 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:16 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:56:16 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:16 -0700] cupsdReadClient: 18 1.1 Send-Document 1 D [19/Jul/2012:05:56:16 -0700] Send-Document ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:16 -0700] cupsdIsAuthorized: requesting-user-name="gary" D [19/Jul/2012:05:56:16 -0700] [Job 297] Auto-typing file... D [19/Jul/2012:05:56:16 -0700] [Job 297] Request file type is application/pdf. D [19/Jul/2012:05:56:16 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:16 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" I [19/Jul/2012:05:56:16 -0700] [Job 297] File of type application/pdf queued by "gary". I [19/Jul/2012:05:56:16 -0700] [Job 297] Adding end banner page "none". D [19/Jul/2012:05:56:16 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:16 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:16 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:16 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:16 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:16 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:16 -0700] [Job 297] job-sheets=none,none D [19/Jul/2012:05:56:16 -0700] [Job 297] argv[0]="HL-1440-series" D [19/Jul/2012:05:56:16 -0700] [Job 297] argv[1]="297" D [19/Jul/2012:05:56:16 -0700] [Job 297] argv[2]="gary" D [19/Jul/2012:05:56:16 -0700] [Job 297] argv[3]="Green Eyes in Africa" D [19/Jul/2012:05:56:16 -0700] [Job 297] argv[4]="1" D [19/Jul/2012:05:56:16 -0700] [Job 297] argv[5]="InputSlot=auto PageSize=Letter job-uuid=urn:uuid:c1e28719-75e0-3388-4744-41654c3e73ff usb-no-reattach nousb-unidir job-originating-host-name=localhost time-at-creation=1342702576 time-at-processing=1342702576" D [19/Jul/2012:05:56:16 -0700] [Job 297] argv[6]="/var/spool/cups/d00297-001" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[0]="CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[1]="CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[4]="CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[5]="CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[6]="CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[7]="CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[8]="HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[10]="SERVER_ADMIN=root@linus" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[11]="SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[12]="TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[13]="USER=root" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[15]="CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[16]="IPP_PORT=631" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[17]="CHARSET=utf-8" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[18]="LANG=en_US.UTF-8" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[19]="PPD=/etc/cups/ppd/HL-1440-series.ppd" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[20]="RIP_MAX_CACHE=128m" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[21]="CONTENT_TYPE=application/pdf" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[22]="DEVICE_URI=usb://Brother/HL-1440%20series" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[23]="PRINTER_INFO=Brother HL-1440 series" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[24]="PRINTER_LOCATION=linus" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[25]="PRINTER=HL-1440-series" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[26]="PRINTER_STATE_REASONS=none" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[27]="CUPS_FILETYPE=document" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[28]="FINAL_CONTENT_TYPE=printer/HL-1440-series" D [19/Jul/2012:05:56:16 -0700] [Job 297] envp[29]="AUTH_I****" I [19/Jul/2012:05:56:16 -0700] [Job 297] Started filter /usr/lib/cups/filter/pdftopdf (PID 7408) I [19/Jul/2012:05:56:16 -0700] [Job 297] Started filter /usr/lib/cups/filter/foomatic-rip (PID 7409) I [19/Jul/2012:05:56:16 -0700] [Job 297] Started backend /usr/lib/cups/backend/usb (PID 7410) D [19/Jul/2012:05:56:16 -0700] Discarding unused job-state-changed event... D [19/Jul/2012:05:56:16 -0700] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:16 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:16 -0700] [Job 297] Printing on printer with URI: usb://Brother/HL-1440%20series D [19/Jul/2012:05:56:16 -0700] [Job 297] Getting input from file D [19/Jul/2012:05:56:16 -0700] [Job 297] foomatic-rip version 4.0.16.253 running... D [19/Jul/2012:05:56:16 -0700] [Job 297] Parsing PPD file ... D [19/Jul/2012:05:56:16 -0700] [Job 297] Added option ColorSpace D [19/Jul/2012:05:56:16 -0700] [Job 297] Added option PageSize D [19/Jul/2012:05:56:16 -0700] [Job 297] Added option ImageableArea D [19/Jul/2012:05:56:16 -0700] [Job 297] Added option PaperDimension D [19/Jul/2012:05:56:16 -0700] [Job 297] Added option MediaType D [19/Jul/2012:05:56:16 -0700] [Job 297] Added option EconoMode D [19/Jul/2012:05:56:16 -0700] [Job 297] libusb_get_device_list=13 D [19/Jul/2012:05:56:16 -0700] [Job 297] Added option InputSlot D [19/Jul/2012:05:56:16 -0700] [Job 297] Added option Resolution D [19/Jul/2012:05:56:16 -0700] [Job 297] Added option Font D [19/Jul/2012:05:56:16 -0700] [Job 297] D [19/Jul/2012:05:56:16 -0700] [Job 297] Parameter Summary D [19/Jul/2012:05:56:16 -0700] [Job 297] ----------------- D [19/Jul/2012:05:56:16 -0700] [Job 297] D [19/Jul/2012:05:56:16 -0700] [Job 297] Spooler: cups D [19/Jul/2012:05:56:16 -0700] [Job 297] Printer: HL-1440-series D [19/Jul/2012:05:56:16 -0700] [Job 297] Shell: /bin/bash D [19/Jul/2012:05:56:16 -0700] [Job 297] PPD file: /etc/cups/ppd/HL-1440-series.ppd D [19/Jul/2012:05:56:16 -0700] [Job 297] ATTR file: D [19/Jul/2012:05:56:16 -0700] [Job 297] Printer model: Brother HL-1440 Foomatic/hl1250 (recommended) D [19/Jul/2012:05:56:16 -0700] [Job 297] Job title: Green Eyes in Africa D [19/Jul/2012:05:56:16 -0700] [Job 297] File(s) to be printed: D [19/Jul/2012:05:56:16 -0700] [Job 297] D [19/Jul/2012:05:56:16 -0700] [Job 297] D [19/Jul/2012:05:56:16 -0700] [Job 297] Ghostscript extra search path ('GS_LIB'): /usr/share/cups/fonts D [19/Jul/2012:05:56:16 -0700] [Job 297] Printing system options: D [19/Jul/2012:05:56:16 -0700] [Job 297] Pondering option 'job-uuid=urn:uuid:c1e28719-75e0-3388-4744-41654c3e73ff' D [19/Jul/2012:05:56:16 -0700] [Job 297] Unknown option job-uuid=urn:uuid:c1e28719-75e0-3388-4744-41654c3e73ff. D [19/Jul/2012:05:56:16 -0700] [Job 297] Pondering option 'usb-no-reattach' D [19/Jul/2012:05:56:16 -0700] [Job 297] Unknown boolean option "usb-no-reattach". D [19/Jul/2012:05:56:16 -0700] [Job 297] Pondering option 'nousb-unidir' D [19/Jul/2012:05:56:16 -0700] [Job 297] Unknown boolean option "nousb-unidir". D [19/Jul/2012:05:56:16 -0700] [Job 297] Pondering option 'job-originating-host-name=localhost' D [19/Jul/2012:05:56:16 -0700] [Job 297] Unknown option job-originating-host-name=localhost. D [19/Jul/2012:05:56:16 -0700] [Job 297] Pondering option 'time-at-creation=1342702576' D [19/Jul/2012:05:56:16 -0700] [Job 297] Unknown option time-at-creation=1342702576. D [19/Jul/2012:05:56:16 -0700] [Job 297] Pondering option 'time-at-processing=1342702576' D [19/Jul/2012:05:56:16 -0700] [Job 297] Unknown option time-at-processing=1342702576. D [19/Jul/2012:05:56:16 -0700] [Job 297] Options from the PPD file: D [19/Jul/2012:05:56:16 -0700] [Job 297] Pondering option 'InputSlot=auto' D [19/Jul/2012:05:56:16 -0700] [Job 297] Pondering option 'PageSize=Letter' D [19/Jul/2012:05:56:16 -0700] [Job 297] D [19/Jul/2012:05:56:16 -0700] [Job 297] ================================================ D [19/Jul/2012:05:56:16 -0700] [Job 297] D [19/Jul/2012:05:56:16 -0700] [Job 297] File: D [19/Jul/2012:05:56:16 -0700] [Job 297] D [19/Jul/2012:05:56:16 -0700] [Job 297] ================================================ D [19/Jul/2012:05:56:16 -0700] [Job 297] D [19/Jul/2012:05:56:16 -0700] [Job 297] Filetype: PDF D [19/Jul/2012:05:56:16 -0700] [Job 297] Storing temporary files in /var/spool/cups/tmp D [19/Jul/2012:05:56:16 -0700] PID 7408 (/usr/lib/cups/filter/pdftopdf) exited with no errors. D [19/Jul/2012:05:56:17 -0700] [Job 297] File contains 1 pages D [19/Jul/2012:05:56:17 -0700] [Job 297] Starting renderer with command: gs -dFirstPage=1 -q -dBATCH -dPARANOIDSAFER -dNOPAUSE -dNOINTERPOLATE -sDEVICE=hl1250 -dEconoMode=0 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -r300x300 -dSourceTray=0 -sOutputFile=- -f /var/spool/cups/tmp/foomatic-do2yQG D [19/Jul/2012:05:56:17 -0700] [Job 297] Starting process "kid3" (generation 1) D [19/Jul/2012:05:56:17 -0700] [Job 297] Starting process "kid4" (generation 2) D [19/Jul/2012:05:56:17 -0700] [Job 297] Starting process "renderer" (generation 2) D [19/Jul/2012:05:56:17 -0700] [Job 297] JCL: %-12345X@PJL D [19/Jul/2012:05:56:17 -0700] [Job 297] @PJL SET MEDIATYPE=REGULAR D [19/Jul/2012:05:56:17 -0700] [Job 297] %-12345X@PJL RESET D [19/Jul/2012:05:56:17 -0700] [Job 297] D [19/Jul/2012:05:56:17 -0700] [Job 297] D [19/Jul/2012:05:56:17 -0700] [Job 297] STATE: +connecting-to-device D [19/Jul/2012:05:56:17 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:17 -0700] [Job 297] STATE: -connecting-to-device D [19/Jul/2012:05:56:17 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:17 -0700] [Job 297] Device protocol: 2 D [19/Jul/2012:05:56:17 -0700] [Job 297] Printer reports bi-di support but in reality works only uni-directionally D [19/Jul/2012:05:56:17 -0700] [Job 297] Uni-directional USB communication only! D [19/Jul/2012:05:56:17 -0700] [Job 297] Printer does not like usblp kernel module to be re-attached after job D [19/Jul/2012:05:56:17 -0700] [Job 297] Forced not re-attaching the usblp kernel module after the job via "usb-no-reattach" option. D [19/Jul/2012:05:56:17 -0700] [Job 297] Uni-directional device/mode, back channel deactivated. I [19/Jul/2012:05:56:17 -0700] [Job 297] Sending data to printer. D [19/Jul/2012:05:56:17 -0700] [Job 297] Set job-printer-state-message to "Sending data to printer.", current level=INFO D [19/Jul/2012:05:56:17 -0700] Discarding unused job-progress event... D [19/Jul/2012:05:56:17 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:17 -0700] [Job 297] Read 8192 bytes of print data... D [19/Jul/2012:05:56:17 -0700] [Job 297] renderer exited with status 0 D [19/Jul/2012:05:56:17 -0700] [Job 297] kid4 exited with status 0 D [19/Jul/2012:05:56:17 -0700] [Job 297] kid3 finished D [19/Jul/2012:05:56:17 -0700] [Job 297] Kid3 exit status: 0 D [19/Jul/2012:05:56:17 -0700] [Job 297] D [19/Jul/2012:05:56:17 -0700] [Job 297] Closing foomatic-rip. D [19/Jul/2012:05:56:17 -0700] PID 7409 (/usr/lib/cups/filter/foomatic-rip) exited with no errors. D [19/Jul/2012:05:56:17 -0700] [Job 297] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:17 -0700] [Job 297] Read 8192 bytes of print data... D [19/Jul/2012:05:56:17 -0700] [Job 297] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:17 -0700] [Job 297] Read 8192 bytes of print data... D [19/Jul/2012:05:56:17 -0700] [Job 297] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:17 -0700] [Job 297] Read 8192 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Read 8192 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Read 8192 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Read 8192 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Read 6067 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Wrote 6067 bytes of print data... D [19/Jul/2012:05:56:18 -0700] [Job 297] Sent 63411 bytes... D [19/Jul/2012:05:56:18 -0700] [Job 297] Resetting printer. D [19/Jul/2012:05:56:18 -0700] PID 7410 (/usr/lib/cups/backend/usb) exited with no errors. D [19/Jul/2012:05:56:18 -0700] Discarding unused job-completed event... I [19/Jul/2012:05:56:18 -0700] [Job 297] Job completed. D [19/Jul/2012:05:56:18 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:18 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:18 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:18 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:19 -0700] [Job 297] Unloading... D [19/Jul/2012:05:56:26 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:26 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:26 -0700] cupsdReadClient: 18 1.1 Create-Job 1 D [19/Jul/2012:05:56:26 -0700] Create-Job ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:26 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:26 -0700] add_job: requesting-user-name="gary" D [19/Jul/2012:05:56:26 -0700] Adding default job-sheets values "none,none"... I [19/Jul/2012:05:56:26 -0700] [Job 298] Adding start banner page "none". D [19/Jul/2012:05:56:26 -0700] Discarding unused job-created event... I [19/Jul/2012:05:56:26 -0700] [Job 298] Queued on "HL-1440-series" by "gary". D [19/Jul/2012:05:56:26 -0700] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:26 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:56:26 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:26 -0700] cupsdReadClient: 18 1.1 Send-Document 1 D [19/Jul/2012:05:56:26 -0700] Send-Document ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:26 -0700] cupsdIsAuthorized: requesting-user-name="gary" D [19/Jul/2012:05:56:26 -0700] [Job 298] Auto-typing file... D [19/Jul/2012:05:56:26 -0700] [Job 298] Request file type is application/pdf. D [19/Jul/2012:05:56:26 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" I [19/Jul/2012:05:56:26 -0700] [Job 298] File of type application/pdf queued by "gary". I [19/Jul/2012:05:56:26 -0700] [Job 298] Adding end banner page "none". D [19/Jul/2012:05:56:26 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:26 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:26 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:26 -0700] [Job 298] job-sheets=none,none D [19/Jul/2012:05:56:26 -0700] [Job 298] argv[0]="HL-1440-series" D [19/Jul/2012:05:56:26 -0700] [Job 298] argv[1]="298" D [19/Jul/2012:05:56:26 -0700] [Job 298] argv[2]="gary" D [19/Jul/2012:05:56:26 -0700] [Job 298] argv[3]="Green Eyes in Africa" D [19/Jul/2012:05:56:26 -0700] [Job 298] argv[4]="1" D [19/Jul/2012:05:56:26 -0700] [Job 298] argv[5]="InputSlot=auto PageSize=Letter job-uuid=urn:uuid:2d7075dd-ed69-33d9-6dac-42a808dcbc90 usb-no-reattach nousb-unidir job-originating-host-name=localhost time-at-creation=1342702586 time-at-processing=1342702586" D [19/Jul/2012:05:56:26 -0700] [Job 298] argv[6]="/var/spool/cups/d00298-001" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[0]="CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[1]="CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[4]="CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[5]="CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[6]="CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[7]="CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[8]="HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[10]="SERVER_ADMIN=root@linus" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[11]="SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[12]="TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[13]="USER=root" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[15]="CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[16]="IPP_PORT=631" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[17]="CHARSET=utf-8" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[18]="LANG=en_US.UTF-8" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[19]="PPD=/etc/cups/ppd/HL-1440-series.ppd" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[20]="RIP_MAX_CACHE=128m" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[21]="CONTENT_TYPE=application/pdf" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[22]="DEVICE_URI=usb://Brother/HL-1440%20series" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[23]="PRINTER_INFO=Brother HL-1440 series" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[24]="PRINTER_LOCATION=linus" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[25]="PRINTER=HL-1440-series" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[26]="PRINTER_STATE_REASONS=none" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[27]="CUPS_FILETYPE=document" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[28]="FINAL_CONTENT_TYPE=printer/HL-1440-series" D [19/Jul/2012:05:56:26 -0700] [Job 298] envp[29]="AUTH_I****" I [19/Jul/2012:05:56:26 -0700] [Job 298] Started filter /usr/lib/cups/filter/pdftopdf (PID 7418) I [19/Jul/2012:05:56:26 -0700] [Job 298] Started filter /usr/lib/cups/filter/foomatic-rip (PID 7419) I [19/Jul/2012:05:56:26 -0700] [Job 298] Started backend /usr/lib/cups/backend/usb (PID 7420) D [19/Jul/2012:05:56:26 -0700] Discarding unused job-state-changed event... D [19/Jul/2012:05:56:26 -0700] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:26 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:26 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:26 -0700] cupsdReadClient: 18 1.1 Create-Job 1 D [19/Jul/2012:05:56:26 -0700] Create-Job ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:26 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:56:26 -0700] add_job: requesting-user-name="gary" I [19/Jul/2012:05:56:26 -0700] [Job 299] Adding start banner page "none". D [19/Jul/2012:05:56:26 -0700] Discarding unused job-created event... I [19/Jul/2012:05:56:26 -0700] [Job 299] Queued on "HL-1440-series" by "gary". D [19/Jul/2012:05:56:26 -0700] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:56:26 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:26 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:26 -0700] cupsdReadClient: 18 1.1 Send-Document 1 D [19/Jul/2012:05:56:26 -0700] Send-Document ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:26 -0700] cupsdIsAuthorized: requesting-user-name="gary" D [19/Jul/2012:05:56:26 -0700] [Job 299] Auto-typing file... D [19/Jul/2012:05:56:26 -0700] [Job 299] Request file type is application/pdf. D [19/Jul/2012:05:56:26 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files" I [19/Jul/2012:05:56:26 -0700] [Job 299] File of type application/pdf queued by "gary". D [19/Jul/2012:05:56:26 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:56:26 -0700] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:26 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:56:26 -0700] [Job 298] Getting input from file D [19/Jul/2012:05:56:26 -0700] [Job 298] foomatic-rip version 4.0.16.253 running... D [19/Jul/2012:05:56:26 -0700] [Job 298] Parsing PPD file ... D [19/Jul/2012:05:56:26 -0700] [Job 298] Added option ColorSpace D [19/Jul/2012:05:56:26 -0700] [Job 298] Added option PageSize D [19/Jul/2012:05:56:26 -0700] [Job 298] Added option ImageableArea D [19/Jul/2012:05:56:26 -0700] [Job 298] Added option PaperDimension D [19/Jul/2012:05:56:26 -0700] [Job 298] Printing on printer with URI: usb://Brother/HL-1440%20series D [19/Jul/2012:05:56:26 -0700] [Job 298] Added option MediaType D [19/Jul/2012:05:56:26 -0700] [Job 298] Added option EconoMode D [19/Jul/2012:05:56:26 -0700] [Job 298] libusb_get_device_list=13 D [19/Jul/2012:05:56:26 -0700] [Job 298] Added option InputSlot D [19/Jul/2012:05:56:26 -0700] [Job 298] Added option Resolution D [19/Jul/2012:05:56:26 -0700] [Job 298] Added option Font D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] Parameter Summary D [19/Jul/2012:05:56:26 -0700] [Job 298] ----------------- D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] Spooler: cups D [19/Jul/2012:05:56:26 -0700] [Job 298] Printer: HL-1440-series D [19/Jul/2012:05:56:26 -0700] [Job 298] Shell: /bin/bash D [19/Jul/2012:05:56:26 -0700] [Job 298] PPD file: /etc/cups/ppd/HL-1440-series.ppd D [19/Jul/2012:05:56:26 -0700] [Job 298] ATTR file: D [19/Jul/2012:05:56:26 -0700] [Job 298] Printer model: Brother HL-1440 Foomatic/hl1250 (recommended) D [19/Jul/2012:05:56:26 -0700] [Job 298] Job title: Green Eyes in Africa D [19/Jul/2012:05:56:26 -0700] [Job 298] File(s) to be printed: D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] Ghostscript extra search path ('GS_LIB'): /usr/share/cups/fonts D [19/Jul/2012:05:56:26 -0700] [Job 298] Printing system options: D [19/Jul/2012:05:56:26 -0700] [Job 298] Pondering option 'job-uuid=urn:uuid:2d7075dd-ed69-33d9-6dac-42a808dcbc90' D [19/Jul/2012:05:56:26 -0700] [Job 298] Unknown option job-uuid=urn:uuid:2d7075dd-ed69-33d9-6dac-42a808dcbc90. D [19/Jul/2012:05:56:26 -0700] [Job 298] Pondering option 'usb-no-reattach' D [19/Jul/2012:05:56:26 -0700] [Job 298] Unknown boolean option "usb-no-reattach". D [19/Jul/2012:05:56:26 -0700] [Job 298] Pondering option 'nousb-unidir' D [19/Jul/2012:05:56:26 -0700] [Job 298] Unknown boolean option "nousb-unidir". D [19/Jul/2012:05:56:26 -0700] [Job 298] Pondering option 'job-originating-host-name=localhost' D [19/Jul/2012:05:56:26 -0700] [Job 298] Unknown option job-originating-host-name=localhost. D [19/Jul/2012:05:56:26 -0700] [Job 298] Pondering option 'time-at-creation=1342702586' D [19/Jul/2012:05:56:26 -0700] [Job 298] Unknown option time-at-creation=1342702586. D [19/Jul/2012:05:56:26 -0700] [Job 298] Pondering option 'time-at-processing=1342702586' D [19/Jul/2012:05:56:26 -0700] [Job 298] Unknown option time-at-processing=1342702586. D [19/Jul/2012:05:56:26 -0700] [Job 298] Options from the PPD file: D [19/Jul/2012:05:56:26 -0700] [Job 298] Pondering option 'InputSlot=auto' D [19/Jul/2012:05:56:26 -0700] [Job 298] Pondering option 'PageSize=Letter' D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] ================================================ D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] File: D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] ================================================ D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] Filetype: PDF D [19/Jul/2012:05:56:26 -0700] [Job 298] Storing temporary files in /var/spool/cups/tmp D [19/Jul/2012:05:56:26 -0700] PID 7418 (/usr/lib/cups/filter/pdftopdf) exited with no errors. D [19/Jul/2012:05:56:26 -0700] [Job 298] File contains 1 pages D [19/Jul/2012:05:56:26 -0700] [Job 298] Starting renderer with command: gs -dFirstPage=1 -q -dBATCH -dPARANOIDSAFER -dNOPAUSE -dNOINTERPOLATE -sDEVICE=hl1250 -dEconoMode=0 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -r300x300 -dSourceTray=0 -sOutputFile=- -f /var/spool/cups/tmp/foomatic-rd3Sy9 D [19/Jul/2012:05:56:26 -0700] [Job 298] Starting process "kid3" (generation 1) D [19/Jul/2012:05:56:26 -0700] [Job 298] Starting process "kid4" (generation 2) D [19/Jul/2012:05:56:26 -0700] [Job 298] Starting process "renderer" (generation 2) D [19/Jul/2012:05:56:26 -0700] [Job 298] JCL: %-12345X@PJL D [19/Jul/2012:05:56:26 -0700] [Job 298] @PJL SET MEDIATYPE=REGULAR D [19/Jul/2012:05:56:26 -0700] [Job 298] %-12345X@PJL RESET D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] STATE: +connecting-to-device D [19/Jul/2012:05:56:26 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:26 -0700] [Job 298] STATE: -connecting-to-device D [19/Jul/2012:05:56:26 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:26 -0700] [Job 298] Device protocol: 2 D [19/Jul/2012:05:56:26 -0700] [Job 298] Printer reports bi-di support but in reality works only uni-directionally D [19/Jul/2012:05:56:26 -0700] [Job 298] Uni-directional USB communication only! D [19/Jul/2012:05:56:26 -0700] [Job 298] Printer does not like usblp kernel module to be re-attached after job D [19/Jul/2012:05:56:26 -0700] [Job 298] Forced not re-attaching the usblp kernel module after the job via "usb-no-reattach" option. D [19/Jul/2012:05:56:26 -0700] [Job 298] Uni-directional device/mode, back channel deactivated. I [19/Jul/2012:05:56:26 -0700] [Job 298] Sending data to printer. D [19/Jul/2012:05:56:26 -0700] [Job 298] Set job-printer-state-message to "Sending data to printer.", current level=INFO D [19/Jul/2012:05:56:26 -0700] Discarding unused job-progress event... D [19/Jul/2012:05:56:26 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:26 -0700] [Job 298] Read 8192 bytes of print data... D [19/Jul/2012:05:56:26 -0700] [Job 298] renderer exited with status 0 D [19/Jul/2012:05:56:26 -0700] [Job 298] kid4 exited with status 0 D [19/Jul/2012:05:56:26 -0700] [Job 298] kid3 finished D [19/Jul/2012:05:56:26 -0700] [Job 298] Kid3 exit status: 0 D [19/Jul/2012:05:56:26 -0700] [Job 298] D [19/Jul/2012:05:56:26 -0700] [Job 298] Closing foomatic-rip. D [19/Jul/2012:05:56:26 -0700] PID 7419 (/usr/lib/cups/filter/foomatic-rip) exited with no errors. D [19/Jul/2012:05:56:28 -0700] [Job 298] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:28 -0700] [Job 298] Read 8192 bytes of print data... D [19/Jul/2012:05:56:28 -0700] [Job 298] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:28 -0700] [Job 298] Read 8192 bytes of print data... D [19/Jul/2012:05:56:28 -0700] [Job 298] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:28 -0700] [Job 298] Read 8192 bytes of print data... D [19/Jul/2012:05:56:28 -0700] [Job 298] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:28 -0700] [Job 298] Read 8192 bytes of print data... D [19/Jul/2012:05:56:29 -0700] [Job 298] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:29 -0700] [Job 298] Read 8192 bytes of print data... D [19/Jul/2012:05:56:29 -0700] [Job 298] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:29 -0700] [Job 298] Read 8192 bytes of print data... D [19/Jul/2012:05:56:29 -0700] [Job 298] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:29 -0700] [Job 298] Read 6067 bytes of print data... D [19/Jul/2012:05:56:29 -0700] [Job 298] Wrote 6067 bytes of print data... D [19/Jul/2012:05:56:29 -0700] [Job 298] Sent 63411 bytes... D [19/Jul/2012:05:56:29 -0700] [Job 298] Resetting printer. D [19/Jul/2012:05:56:29 -0700] PID 7420 (/usr/lib/cups/backend/usb) exited with no errors. D [19/Jul/2012:05:56:29 -0700] Discarding unused job-completed event... I [19/Jul/2012:05:56:29 -0700] [Job 298] Job completed. D [19/Jul/2012:05:56:29 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:29 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:29 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:29 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:29 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:29 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:29 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:56:29 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:29 -0700] [Job 299] job-sheets=none D [19/Jul/2012:05:56:29 -0700] [Job 299] argv[0]="HL-1440-series" D [19/Jul/2012:05:56:29 -0700] [Job 299] argv[1]="299" D [19/Jul/2012:05:56:29 -0700] [Job 299] argv[2]="gary" D [19/Jul/2012:05:56:29 -0700] [Job 299] argv[3]="Green Eyes in Africa 1" D [19/Jul/2012:05:56:29 -0700] [Job 299] argv[4]="1" D [19/Jul/2012:05:56:29 -0700] [Job 299] argv[5]="InputSlot=auto PageSize=Letter job-uuid=urn:uuid:ee3c72d8-4986-3db1-6521-ae908abdbbb9 usb-no-reattach nousb-unidir job-originating-host-name=localhost time-at-creation=1342702586 time-at-processing=1342702589" D [19/Jul/2012:05:56:29 -0700] [Job 299] argv[6]="/var/spool/cups/d00299-001" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[0]="CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[1]="CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[4]="CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[5]="CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[6]="CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[7]="CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[8]="HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[10]="SERVER_ADMIN=root@linus" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[11]="SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[12]="TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[13]="USER=root" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[15]="CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[16]="IPP_PORT=631" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[17]="CHARSET=utf-8" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[18]="LANG=en_US.UTF-8" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[19]="PPD=/etc/cups/ppd/HL-1440-series.ppd" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[20]="RIP_MAX_CACHE=128m" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[21]="CONTENT_TYPE=application/pdf" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[22]="DEVICE_URI=usb://Brother/HL-1440%20series" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[23]="PRINTER_INFO=Brother HL-1440 series" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[24]="PRINTER_LOCATION=linus" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[25]="PRINTER=HL-1440-series" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[26]="PRINTER_STATE_REASONS=none" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[27]="CUPS_FILETYPE=document" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[28]="FINAL_CONTENT_TYPE=printer/HL-1440-series" D [19/Jul/2012:05:56:29 -0700] [Job 299] envp[29]="AUTH_I****" I [19/Jul/2012:05:56:29 -0700] [Job 299] Started filter /usr/lib/cups/filter/pdftopdf (PID 7427) I [19/Jul/2012:05:56:29 -0700] [Job 299] Started filter /usr/lib/cups/filter/foomatic-rip (PID 7428) I [19/Jul/2012:05:56:29 -0700] [Job 299] Started backend /usr/lib/cups/backend/usb (PID 7429) D [19/Jul/2012:05:56:29 -0700] Discarding unused job-state-changed event... D [19/Jul/2012:05:56:29 -0700] [Job 299] Getting input from file D [19/Jul/2012:05:56:29 -0700] [Job 299] foomatic-rip version 4.0.16.253 running... D [19/Jul/2012:05:56:29 -0700] [Job 299] Parsing PPD file ... D [19/Jul/2012:05:56:29 -0700] [Job 299] Added option ColorSpace D [19/Jul/2012:05:56:29 -0700] [Job 299] Added option PageSize D [19/Jul/2012:05:56:29 -0700] [Job 299] Printing on printer with URI: usb://Brother/HL-1440%20series D [19/Jul/2012:05:56:29 -0700] [Job 299] libusb_get_device_list=13 D [19/Jul/2012:05:56:29 -0700] [Job 299] Added option ImageableArea D [19/Jul/2012:05:56:29 -0700] [Job 299] Added option PaperDimension D [19/Jul/2012:05:56:29 -0700] [Job 299] Added option MediaType D [19/Jul/2012:05:56:29 -0700] [Job 299] Added option EconoMode D [19/Jul/2012:05:56:29 -0700] [Job 299] Added option InputSlot D [19/Jul/2012:05:56:29 -0700] [Job 299] Added option Resolution D [19/Jul/2012:05:56:29 -0700] [Job 299] Added option Font D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:29 -0700] [Job 299] Parameter Summary D [19/Jul/2012:05:56:29 -0700] [Job 299] ----------------- D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:29 -0700] [Job 299] Spooler: cups D [19/Jul/2012:05:56:29 -0700] [Job 299] Printer: HL-1440-series D [19/Jul/2012:05:56:29 -0700] [Job 299] Shell: /bin/bash D [19/Jul/2012:05:56:29 -0700] [Job 299] PPD file: /etc/cups/ppd/HL-1440-series.ppd D [19/Jul/2012:05:56:29 -0700] [Job 299] ATTR file: D [19/Jul/2012:05:56:29 -0700] [Job 299] Printer model: Brother HL-1440 Foomatic/hl1250 (recommended) D [19/Jul/2012:05:56:29 -0700] [Job 299] Job title: Green Eyes in Africa 1 D [19/Jul/2012:05:56:29 -0700] [Job 299] File(s) to be printed: D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:29 -0700] [Job 299] Ghostscript extra search path ('GS_LIB'): /usr/share/cups/fonts D [19/Jul/2012:05:56:29 -0700] [Job 299] Printing system options: D [19/Jul/2012:05:56:29 -0700] [Job 299] Pondering option 'job-uuid=urn:uuid:ee3c72d8-4986-3db1-6521-ae908abdbbb9' D [19/Jul/2012:05:56:29 -0700] [Job 299] Unknown option job-uuid=urn:uuid:ee3c72d8-4986-3db1-6521-ae908abdbbb9. D [19/Jul/2012:05:56:29 -0700] [Job 299] Pondering option 'usb-no-reattach' D [19/Jul/2012:05:56:29 -0700] [Job 299] Unknown boolean option "usb-no-reattach". D [19/Jul/2012:05:56:29 -0700] [Job 299] Pondering option 'nousb-unidir' D [19/Jul/2012:05:56:29 -0700] [Job 299] Unknown boolean option "nousb-unidir". D [19/Jul/2012:05:56:29 -0700] [Job 299] Pondering option 'job-originating-host-name=localhost' D [19/Jul/2012:05:56:29 -0700] [Job 299] Unknown option job-originating-host-name=localhost. D [19/Jul/2012:05:56:29 -0700] [Job 299] Pondering option 'time-at-creation=1342702586' D [19/Jul/2012:05:56:29 -0700] [Job 299] Unknown option time-at-creation=1342702586. D [19/Jul/2012:05:56:29 -0700] [Job 299] Pondering option 'time-at-processing=1342702589' D [19/Jul/2012:05:56:29 -0700] [Job 299] Unknown option time-at-processing=1342702589. D [19/Jul/2012:05:56:29 -0700] [Job 299] Options from the PPD file: D [19/Jul/2012:05:56:29 -0700] [Job 299] Pondering option 'InputSlot=auto' D [19/Jul/2012:05:56:29 -0700] [Job 299] Pondering option 'PageSize=Letter' D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:29 -0700] [Job 299] ================================================ D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:29 -0700] [Job 299] File: D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:29 -0700] [Job 299] ================================================ D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:29 -0700] [Job 299] Filetype: PDF D [19/Jul/2012:05:56:29 -0700] [Job 299] Storing temporary files in /var/spool/cups/tmp D [19/Jul/2012:05:56:29 -0700] PID 7427 (/usr/lib/cups/filter/pdftopdf) exited with no errors. D [19/Jul/2012:05:56:29 -0700] [Job 299] File contains 1 pages D [19/Jul/2012:05:56:29 -0700] [Job 299] Starting renderer with command: gs -dFirstPage=1 -q -dBATCH -dPARANOIDSAFER -dNOPAUSE -dNOINTERPOLATE -sDEVICE=hl1250 -dEconoMode=0 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -r300x300 -dSourceTray=0 -sOutputFile=- -f /var/spool/cups/tmp/foomatic-TTQ1Q3 D [19/Jul/2012:05:56:29 -0700] [Job 299] Starting process "kid3" (generation 1) D [19/Jul/2012:05:56:29 -0700] [Job 299] Starting process "kid4" (generation 2) D [19/Jul/2012:05:56:29 -0700] [Job 299] Starting process "renderer" (generation 2) D [19/Jul/2012:05:56:29 -0700] [Job 299] JCL: %-12345X@PJL D [19/Jul/2012:05:56:29 -0700] [Job 299] @PJL SET MEDIATYPE=REGULAR D [19/Jul/2012:05:56:29 -0700] [Job 299] %-12345X@PJL RESET D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:29 -0700] [Job 299] D [19/Jul/2012:05:56:30 -0700] [Job 299] STATE: +connecting-to-device D [19/Jul/2012:05:56:30 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:30 -0700] [Job 298] Unloading... D [19/Jul/2012:05:56:30 -0700] [Job 299] STATE: -connecting-to-device D [19/Jul/2012:05:56:30 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:30 -0700] [Job 299] renderer exited with status 0 D [19/Jul/2012:05:56:30 -0700] [Job 299] kid4 exited with status 0 D [19/Jul/2012:05:56:30 -0700] [Job 299] kid3 finished D [19/Jul/2012:05:56:30 -0700] [Job 299] Kid3 exit status: 0 D [19/Jul/2012:05:56:30 -0700] [Job 299] D [19/Jul/2012:05:56:30 -0700] [Job 299] Closing foomatic-rip. D [19/Jul/2012:05:56:30 -0700] PID 7428 (/usr/lib/cups/filter/foomatic-rip) exited with no errors. D [19/Jul/2012:05:56:30 -0700] [Job 299] Device protocol: 2 D [19/Jul/2012:05:56:30 -0700] [Job 299] Printer reports bi-di support but in reality works only uni-directionally D [19/Jul/2012:05:56:30 -0700] [Job 299] Uni-directional USB communication only! D [19/Jul/2012:05:56:30 -0700] [Job 299] Printer does not like usblp kernel module to be re-attached after job D [19/Jul/2012:05:56:30 -0700] [Job 299] Forced not re-attaching the usblp kernel module after the job via "usb-no-reattach" option. D [19/Jul/2012:05:56:30 -0700] [Job 299] Uni-directional device/mode, back channel deactivated. I [19/Jul/2012:05:56:30 -0700] [Job 299] Sending data to printer. D [19/Jul/2012:05:56:30 -0700] [Job 299] Set job-printer-state-message to "Sending data to printer.", current level=INFO D [19/Jul/2012:05:56:30 -0700] [Job 299] Read 8192 bytes of print data... D [19/Jul/2012:05:56:30 -0700] Discarding unused job-progress event... D [19/Jul/2012:05:56:30 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:33 -0700] [Job 299] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:33 -0700] Report: clients=2 D [19/Jul/2012:05:56:33 -0700] Report: jobs=38 D [19/Jul/2012:05:56:33 -0700] Report: jobs-active=1 D [19/Jul/2012:05:56:33 -0700] Report: printers=1 D [19/Jul/2012:05:56:33 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:56:33 -0700] Report: stringpool-string-count=5027 D [19/Jul/2012:05:56:33 -0700] Report: stringpool-alloc-bytes=9584 D [19/Jul/2012:05:56:33 -0700] Report: stringpool-total-bytes=89344 D [19/Jul/2012:05:56:33 -0700] [Job 299] Read 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Read 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Read 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Read 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Read 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:34 -0700] [Job 299] Read 8192 bytes of print data... D [19/Jul/2012:05:56:35 -0700] [Job 299] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:35 -0700] [Job 299] Read 6067 bytes of print data... D [19/Jul/2012:05:56:35 -0700] [Job 299] Wrote 6067 bytes of print data... D [19/Jul/2012:05:56:35 -0700] [Job 299] Sent 63411 bytes... D [19/Jul/2012:05:56:35 -0700] [Job 299] Resetting printer. D [19/Jul/2012:05:56:35 -0700] PID 7429 (/usr/lib/cups/backend/usb) exited with no errors. D [19/Jul/2012:05:56:35 -0700] Discarding unused job-completed event... I [19/Jul/2012:05:56:35 -0700] [Job 299] Job completed. D [19/Jul/2012:05:56:35 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:35 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files" D [19/Jul/2012:05:56:35 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:35 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:36 -0700] [Job 299] Unloading... I [19/Jul/2012:05:56:47 -0700] Saving job.cache... D [19/Jul/2012:05:56:47 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:50 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:56:50 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:50 -0700] cupsdReadClient: 18 1.1 Create-Job 1 D [19/Jul/2012:05:56:50 -0700] Create-Job ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:50 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients" D [19/Jul/2012:05:56:50 -0700] add_job: requesting-user-name="gary" D [19/Jul/2012:05:56:50 -0700] Adding default job-sheets values "none,none"... I [19/Jul/2012:05:56:50 -0700] [Job 300] Adding start banner page "none". D [19/Jul/2012:05:56:50 -0700] Discarding unused job-created event... I [19/Jul/2012:05:56:50 -0700] [Job 300] Queued on "HL-1440-series" by "gary". D [19/Jul/2012:05:56:50 -0700] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:50 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Dirty files" D [19/Jul/2012:05:56:50 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:50 -0700] cupsdReadClient: 18 1.1 Send-Document 1 D [19/Jul/2012:05:56:50 -0700] Send-Document ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:50 -0700] cupsdIsAuthorized: requesting-user-name="gary" D [19/Jul/2012:05:56:50 -0700] [Job 300] Auto-typing file... D [19/Jul/2012:05:56:50 -0700] [Job 300] Request file type is application/pdf. D [19/Jul/2012:05:56:50 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" I [19/Jul/2012:05:56:50 -0700] [Job 300] File of type application/pdf queued by "gary". I [19/Jul/2012:05:56:50 -0700] [Job 300] Adding end banner page "none". D [19/Jul/2012:05:56:50 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:50 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:50 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:50 -0700] [Job 300] job-sheets=none,none D [19/Jul/2012:05:56:50 -0700] [Job 300] argv[0]="HL-1440-series" D [19/Jul/2012:05:56:50 -0700] [Job 300] argv[1]="300" D [19/Jul/2012:05:56:50 -0700] [Job 300] argv[2]="gary" D [19/Jul/2012:05:56:50 -0700] [Job 300] argv[3]="CALPIRG" D [19/Jul/2012:05:56:50 -0700] [Job 300] argv[4]="1" D [19/Jul/2012:05:56:50 -0700] [Job 300] argv[5]="InputSlot=auto PageSize=Letter job-uuid=urn:uuid:b625b496-ec04-3466-40d3-7a39ed4dcdc1 usb-no-reattach nousb-unidir job-originating-host-name=localhost time-at-creation=1342702610 time-at-processing=1342702610" D [19/Jul/2012:05:56:50 -0700] [Job 300] argv[6]="/var/spool/cups/d00300-001" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[0]="CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[1]="CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[4]="CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[5]="CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[6]="CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[7]="CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[8]="HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[10]="SERVER_ADMIN=root@linus" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[11]="SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[12]="TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[13]="USER=root" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[15]="CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[16]="IPP_PORT=631" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[17]="CHARSET=utf-8" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[18]="LANG=en_US.UTF-8" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[19]="PPD=/etc/cups/ppd/HL-1440-series.ppd" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[20]="RIP_MAX_CACHE=128m" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[21]="CONTENT_TYPE=application/pdf" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[22]="DEVICE_URI=usb://Brother/HL-1440%20series" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[23]="PRINTER_INFO=Brother HL-1440 series" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[24]="PRINTER_LOCATION=linus" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[25]="PRINTER=HL-1440-series" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[26]="PRINTER_STATE_REASONS=none" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[27]="CUPS_FILETYPE=document" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[28]="FINAL_CONTENT_TYPE=printer/HL-1440-series" D [19/Jul/2012:05:56:50 -0700] [Job 300] envp[29]="AUTH_I****" I [19/Jul/2012:05:56:50 -0700] [Job 300] Started filter /usr/lib/cups/filter/pdftopdf (PID 7438) I [19/Jul/2012:05:56:50 -0700] [Job 300] Started filter /usr/lib/cups/filter/foomatic-rip (PID 7439) I [19/Jul/2012:05:56:50 -0700] [Job 300] Started backend /usr/lib/cups/backend/usb (PID 7440) D [19/Jul/2012:05:56:50 -0700] Discarding unused job-state-changed event... D [19/Jul/2012:05:56:50 -0700] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients and dirty files" D [19/Jul/2012:05:56:50 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:50 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:50 -0700] cupsdReadClient: 18 1.1 Create-Job 1 D [19/Jul/2012:05:56:50 -0700] Create-Job ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:50 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:56:50 -0700] add_job: requesting-user-name="gary" I [19/Jul/2012:05:56:50 -0700] [Job 301] Adding start banner page "none". D [19/Jul/2012:05:56:50 -0700] Discarding unused job-created event... I [19/Jul/2012:05:56:50 -0700] [Job 301] Queued on "HL-1440-series" by "gary". D [19/Jul/2012:05:56:50 -0700] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:56:50 -0700] cupsdReadClient: 18 POST /printers/HL-1440-series HTTP/1.1 D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:50 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:56:50 -0700] cupsdReadClient: 18 1.1 Send-Document 1 D [19/Jul/2012:05:56:50 -0700] Send-Document ipp://localhost:631/printers/HL-1440-series D [19/Jul/2012:05:56:50 -0700] cupsdIsAuthorized: requesting-user-name="gary" D [19/Jul/2012:05:56:50 -0700] [Job 301] Auto-typing file... D [19/Jul/2012:05:56:50 -0700] [Job 301] Request file type is application/pdf. D [19/Jul/2012:05:56:50 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files" I [19/Jul/2012:05:56:50 -0700] [Job 301] File of type application/pdf queued by "gary". D [19/Jul/2012:05:56:50 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Active clients, printing jobs, and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:56:50 -0700] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/HL-1440-series) from localhost D [19/Jul/2012:05:56:50 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Active clients, printing jobs, and dirty files" D [19/Jul/2012:05:56:50 -0700] [Job 300] Printing on printer with URI: usb://Brother/HL-1440%20series D [19/Jul/2012:05:56:50 -0700] [Job 300] Getting input from file D [19/Jul/2012:05:56:50 -0700] [Job 300] foomatic-rip version 4.0.16.253 running... D [19/Jul/2012:05:56:50 -0700] [Job 300] Parsing PPD file ... D [19/Jul/2012:05:56:50 -0700] [Job 300] Added option ColorSpace D [19/Jul/2012:05:56:50 -0700] [Job 300] Added option PageSize D [19/Jul/2012:05:56:50 -0700] [Job 300] libusb_get_device_list=13 D [19/Jul/2012:05:56:50 -0700] [Job 300] Added option ImageableArea D [19/Jul/2012:05:56:50 -0700] PID 7438 (/usr/lib/cups/filter/pdftopdf) exited with no errors. D [19/Jul/2012:05:56:50 -0700] [Job 300] Added option PaperDimension D [19/Jul/2012:05:56:50 -0700] [Job 300] Added option MediaType D [19/Jul/2012:05:56:50 -0700] [Job 300] Added option EconoMode D [19/Jul/2012:05:56:50 -0700] [Job 300] Added option InputSlot D [19/Jul/2012:05:56:50 -0700] [Job 300] Added option Resolution D [19/Jul/2012:05:56:50 -0700] [Job 300] Added option Font D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] Parameter Summary D [19/Jul/2012:05:56:50 -0700] [Job 300] ----------------- D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] Spooler: cups D [19/Jul/2012:05:56:50 -0700] [Job 300] Printer: HL-1440-series D [19/Jul/2012:05:56:50 -0700] [Job 300] Shell: /bin/bash D [19/Jul/2012:05:56:50 -0700] [Job 300] PPD file: /etc/cups/ppd/HL-1440-series.ppd D [19/Jul/2012:05:56:50 -0700] [Job 300] ATTR file: D [19/Jul/2012:05:56:50 -0700] [Job 300] Printer model: Brother HL-1440 Foomatic/hl1250 (recommended) D [19/Jul/2012:05:56:50 -0700] [Job 300] Job title: CALPIRG D [19/Jul/2012:05:56:50 -0700] [Job 300] File(s) to be printed: D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] Ghostscript extra search path ('GS_LIB'): /usr/share/cups/fonts D [19/Jul/2012:05:56:50 -0700] [Job 300] Printing system options: D [19/Jul/2012:05:56:50 -0700] [Job 300] Pondering option 'job-uuid=urn:uuid:b625b496-ec04-3466-40d3-7a39ed4dcdc1' D [19/Jul/2012:05:56:50 -0700] [Job 300] Unknown option job-uuid=urn:uuid:b625b496-ec04-3466-40d3-7a39ed4dcdc1. D [19/Jul/2012:05:56:50 -0700] [Job 300] Pondering option 'usb-no-reattach' D [19/Jul/2012:05:56:50 -0700] [Job 300] Unknown boolean option "usb-no-reattach". D [19/Jul/2012:05:56:50 -0700] [Job 300] Pondering option 'nousb-unidir' D [19/Jul/2012:05:56:50 -0700] [Job 300] Unknown boolean option "nousb-unidir". D [19/Jul/2012:05:56:50 -0700] [Job 300] Pondering option 'job-originating-host-name=localhost' D [19/Jul/2012:05:56:50 -0700] [Job 300] Unknown option job-originating-host-name=localhost. D [19/Jul/2012:05:56:50 -0700] [Job 300] Pondering option 'time-at-creation=1342702610' D [19/Jul/2012:05:56:50 -0700] [Job 300] Unknown option time-at-creation=1342702610. D [19/Jul/2012:05:56:50 -0700] [Job 300] Pondering option 'time-at-processing=1342702610' D [19/Jul/2012:05:56:50 -0700] [Job 300] Unknown option time-at-processing=1342702610. D [19/Jul/2012:05:56:50 -0700] [Job 300] Options from the PPD file: D [19/Jul/2012:05:56:50 -0700] [Job 300] Pondering option 'InputSlot=auto' D [19/Jul/2012:05:56:50 -0700] [Job 300] Pondering option 'PageSize=Letter' D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] ================================================ D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] File: D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] ================================================ D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] Filetype: PDF D [19/Jul/2012:05:56:50 -0700] [Job 300] Storing temporary files in /var/spool/cups/tmp D [19/Jul/2012:05:56:50 -0700] [Job 300] File contains 1 pages D [19/Jul/2012:05:56:50 -0700] [Job 300] Starting renderer with command: gs -dFirstPage=1 -q -dBATCH -dPARANOIDSAFER -dNOPAUSE -dNOINTERPOLATE -sDEVICE=hl1250 -dEconoMode=0 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -r300x300 -dSourceTray=0 -sOutputFile=- -f /var/spool/cups/tmp/foomatic-loeNkR D [19/Jul/2012:05:56:50 -0700] [Job 300] Starting process "kid3" (generation 1) D [19/Jul/2012:05:56:50 -0700] [Job 300] Starting process "kid4" (generation 2) D [19/Jul/2012:05:56:50 -0700] [Job 300] Starting process "renderer" (generation 2) D [19/Jul/2012:05:56:50 -0700] [Job 300] JCL: %-12345X@PJL D [19/Jul/2012:05:56:50 -0700] [Job 300] @PJL SET MEDIATYPE=REGULAR D [19/Jul/2012:05:56:50 -0700] [Job 300] %-12345X@PJL RESET D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] STATE: +connecting-to-device D [19/Jul/2012:05:56:50 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:50 -0700] [Job 300] STATE: -connecting-to-device D [19/Jul/2012:05:56:50 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:50 -0700] [Job 300] Device protocol: 2 D [19/Jul/2012:05:56:50 -0700] [Job 300] Printer reports bi-di support but in reality works only uni-directionally D [19/Jul/2012:05:56:50 -0700] [Job 300] Uni-directional USB communication only! D [19/Jul/2012:05:56:50 -0700] [Job 300] Printer does not like usblp kernel module to be re-attached after job D [19/Jul/2012:05:56:50 -0700] [Job 300] Forced not re-attaching the usblp kernel module after the job via "usb-no-reattach" option. D [19/Jul/2012:05:56:50 -0700] [Job 300] Uni-directional device/mode, back channel deactivated. I [19/Jul/2012:05:56:50 -0700] [Job 300] Sending data to printer. D [19/Jul/2012:05:56:50 -0700] [Job 300] Set job-printer-state-message to "Sending data to printer.", current level=INFO D [19/Jul/2012:05:56:50 -0700] Discarding unused job-progress event... D [19/Jul/2012:05:56:50 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:50 -0700] [Job 300] Read 8192 bytes of print data... D [19/Jul/2012:05:56:50 -0700] [Job 300] renderer exited with status 0 D [19/Jul/2012:05:56:50 -0700] [Job 300] kid4 exited with status 0 D [19/Jul/2012:05:56:50 -0700] [Job 300] kid3 finished D [19/Jul/2012:05:56:50 -0700] [Job 300] Kid3 exit status: 0 D [19/Jul/2012:05:56:50 -0700] [Job 300] D [19/Jul/2012:05:56:50 -0700] [Job 300] Closing foomatic-rip. D [19/Jul/2012:05:56:50 -0700] PID 7439 (/usr/lib/cups/filter/foomatic-rip) exited with no errors. D [19/Jul/2012:05:56:50 -0700] [Job 300] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:50 -0700] [Job 300] Read 8192 bytes of print data... D [19/Jul/2012:05:56:50 -0700] [Job 300] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:50 -0700] [Job 300] Read 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Read 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Read 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Read 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Read 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Wrote 8192 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Read 4451 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Wrote 4451 bytes of print data... D [19/Jul/2012:05:56:51 -0700] [Job 300] Sent 61795 bytes... D [19/Jul/2012:05:56:52 -0700] [Job 300] Resetting printer. D [19/Jul/2012:05:56:52 -0700] PID 7440 (/usr/lib/cups/backend/usb) exited with no errors. D [19/Jul/2012:05:56:52 -0700] Discarding unused job-completed event... I [19/Jul/2012:05:56:52 -0700] [Job 300] Job completed. D [19/Jul/2012:05:56:52 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:52 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:52 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:52 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:52 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:56:52 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:56:52 -0700] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files" D [19/Jul/2012:05:56:52 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:52 -0700] [Job 301] job-sheets=none D [19/Jul/2012:05:56:52 -0700] [Job 301] argv[0]="HL-1440-series" D [19/Jul/2012:05:56:52 -0700] [Job 301] argv[1]="301" D [19/Jul/2012:05:56:52 -0700] [Job 301] argv[2]="gary" D [19/Jul/2012:05:56:52 -0700] [Job 301] argv[3]="CALPIRG 1" D [19/Jul/2012:05:56:52 -0700] [Job 301] argv[4]="1" D [19/Jul/2012:05:56:52 -0700] [Job 301] argv[5]="InputSlot=auto PageSize=Letter job-uuid=urn:uuid:7df36255-adc1-30de-50bb-d95b602d8013 usb-no-reattach nousb-unidir job-originating-host-name=localhost time-at-creation=1342702610 time-at-processing=1342702612" D [19/Jul/2012:05:56:52 -0700] [Job 301] argv[6]="/var/spool/cups/d00301-001" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[0]="CUPS_CACHEDIR=/var/cache/cups" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[1]="CUPS_DATADIR=/usr/share/cups" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[4]="CUPS_REQUESTROOT=/var/spool/cups" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[5]="CUPS_SERVERBIN=/usr/lib/cups" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[6]="CUPS_SERVERROOT=/etc/cups" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[7]="CUPS_STATEDIR=/var/run/cups" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[8]="HOME=/var/spool/cups/tmp" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[10]="SERVER_ADMIN=root@linus" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[11]="SOFTWARE=CUPS/1.5.3" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[12]="TMPDIR=/var/spool/cups/tmp" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[13]="USER=root" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[15]="CUPS_ENCRYPTION=IfRequested" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[16]="IPP_PORT=631" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[17]="CHARSET=utf-8" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[18]="LANG=en_US.UTF-8" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[19]="PPD=/etc/cups/ppd/HL-1440-series.ppd" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[20]="RIP_MAX_CACHE=128m" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[21]="CONTENT_TYPE=application/pdf" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[22]="DEVICE_URI=usb://Brother/HL-1440%20series" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[23]="PRINTER_INFO=Brother HL-1440 series" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[24]="PRINTER_LOCATION=linus" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[25]="PRINTER=HL-1440-series" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[26]="PRINTER_STATE_REASONS=none" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[27]="CUPS_FILETYPE=document" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[28]="FINAL_CONTENT_TYPE=printer/HL-1440-series" D [19/Jul/2012:05:56:52 -0700] [Job 301] envp[29]="AUTH_I****" I [19/Jul/2012:05:56:52 -0700] [Job 301] Started filter /usr/lib/cups/filter/pdftopdf (PID 7447) I [19/Jul/2012:05:56:52 -0700] [Job 301] Started filter /usr/lib/cups/filter/foomatic-rip (PID 7448) I [19/Jul/2012:05:56:52 -0700] [Job 301] Started backend /usr/lib/cups/backend/usb (PID 7449) D [19/Jul/2012:05:56:52 -0700] Discarding unused job-state-changed event... D [19/Jul/2012:05:56:52 -0700] [Job 301] Printing on printer with URI: usb://Brother/HL-1440%20series D [19/Jul/2012:05:56:52 -0700] [Job 301] libusb_get_device_list=13 D [19/Jul/2012:05:56:52 -0700] [Job 301] Getting input from file D [19/Jul/2012:05:56:52 -0700] [Job 301] foomatic-rip version 4.0.16.253 running... D [19/Jul/2012:05:56:52 -0700] [Job 301] Parsing PPD file ... D [19/Jul/2012:05:56:52 -0700] [Job 301] Added option ColorSpace D [19/Jul/2012:05:56:52 -0700] [Job 301] Added option PageSize D [19/Jul/2012:05:56:52 -0700] [Job 301] Added option ImageableArea D [19/Jul/2012:05:56:52 -0700] [Job 301] Added option PaperDimension D [19/Jul/2012:05:56:52 -0700] [Job 301] Added option MediaType D [19/Jul/2012:05:56:52 -0700] [Job 301] Added option EconoMode D [19/Jul/2012:05:56:52 -0700] [Job 301] Added option InputSlot D [19/Jul/2012:05:56:52 -0700] [Job 301] Added option Resolution D [19/Jul/2012:05:56:52 -0700] [Job 301] Added option Font D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] Parameter Summary D [19/Jul/2012:05:56:52 -0700] [Job 301] ----------------- D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] Spooler: cups D [19/Jul/2012:05:56:52 -0700] [Job 301] Printer: HL-1440-series D [19/Jul/2012:05:56:52 -0700] [Job 301] Shell: /bin/bash D [19/Jul/2012:05:56:52 -0700] [Job 301] PPD file: /etc/cups/ppd/HL-1440-series.ppd D [19/Jul/2012:05:56:52 -0700] [Job 301] ATTR file: D [19/Jul/2012:05:56:52 -0700] [Job 301] Printer model: Brother HL-1440 Foomatic/hl1250 (recommended) D [19/Jul/2012:05:56:52 -0700] [Job 301] Job title: CALPIRG 1 D [19/Jul/2012:05:56:52 -0700] [Job 301] File(s) to be printed: D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] Ghostscript extra search path ('GS_LIB'): /usr/share/cups/fonts D [19/Jul/2012:05:56:52 -0700] [Job 301] Printing system options: D [19/Jul/2012:05:56:52 -0700] [Job 301] Pondering option 'job-uuid=urn:uuid:7df36255-adc1-30de-50bb-d95b602d8013' D [19/Jul/2012:05:56:52 -0700] [Job 301] Unknown option job-uuid=urn:uuid:7df36255-adc1-30de-50bb-d95b602d8013. D [19/Jul/2012:05:56:52 -0700] [Job 301] Pondering option 'usb-no-reattach' D [19/Jul/2012:05:56:52 -0700] [Job 301] Unknown boolean option "usb-no-reattach". D [19/Jul/2012:05:56:52 -0700] [Job 301] Pondering option 'nousb-unidir' D [19/Jul/2012:05:56:52 -0700] [Job 301] Unknown boolean option "nousb-unidir". D [19/Jul/2012:05:56:52 -0700] [Job 301] Pondering option 'job-originating-host-name=localhost' D [19/Jul/2012:05:56:52 -0700] [Job 301] Unknown option job-originating-host-name=localhost. D [19/Jul/2012:05:56:52 -0700] [Job 301] Pondering option 'time-at-creation=1342702610' D [19/Jul/2012:05:56:52 -0700] [Job 301] Unknown option time-at-creation=1342702610. D [19/Jul/2012:05:56:52 -0700] [Job 301] Pondering option 'time-at-processing=1342702612' D [19/Jul/2012:05:56:52 -0700] [Job 301] Unknown option time-at-processing=1342702612. D [19/Jul/2012:05:56:52 -0700] [Job 301] Options from the PPD file: D [19/Jul/2012:05:56:52 -0700] [Job 301] Pondering option 'InputSlot=auto' D [19/Jul/2012:05:56:52 -0700] [Job 301] Pondering option 'PageSize=Letter' D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] ================================================ D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] File: D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] ================================================ D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] STATE: +connecting-to-device D [19/Jul/2012:05:56:52 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:52 -0700] [Job 301] STATE: -connecting-to-device D [19/Jul/2012:05:56:52 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:52 -0700] [Job 301] Filetype: PDF D [19/Jul/2012:05:56:52 -0700] [Job 301] Storing temporary files in /var/spool/cups/tmp D [19/Jul/2012:05:56:52 -0700] PID 7447 (/usr/lib/cups/filter/pdftopdf) exited with no errors. D [19/Jul/2012:05:56:52 -0700] [Job 301] Device protocol: 2 D [19/Jul/2012:05:56:52 -0700] [Job 301] Printer reports bi-di support but in reality works only uni-directionally D [19/Jul/2012:05:56:52 -0700] [Job 301] Uni-directional USB communication only! D [19/Jul/2012:05:56:52 -0700] [Job 301] Printer does not like usblp kernel module to be re-attached after job D [19/Jul/2012:05:56:52 -0700] [Job 301] Forced not re-attaching the usblp kernel module after the job via "usb-no-reattach" option. D [19/Jul/2012:05:56:52 -0700] [Job 301] Uni-directional device/mode, back channel deactivated. I [19/Jul/2012:05:56:52 -0700] [Job 301] Sending data to printer. D [19/Jul/2012:05:56:52 -0700] [Job 301] Set job-printer-state-message to "Sending data to printer.", current level=INFO D [19/Jul/2012:05:56:52 -0700] Discarding unused job-progress event... D [19/Jul/2012:05:56:52 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:56:52 -0700] [Job 301] File contains 1 pages D [19/Jul/2012:05:56:52 -0700] [Job 301] Starting renderer with command: gs -dFirstPage=1 -q -dBATCH -dPARANOIDSAFER -dNOPAUSE -dNOINTERPOLATE -sDEVICE=hl1250 -dEconoMode=0 -dDEVICEWIDTHPOINTS=612 -dDEVICEHEIGHTPOINTS=792 -r300x300 -dSourceTray=0 -sOutputFile=- -f /var/spool/cups/tmp/foomatic-MjAwPZ D [19/Jul/2012:05:56:52 -0700] [Job 301] Starting process "kid3" (generation 1) D [19/Jul/2012:05:56:52 -0700] [Job 301] Starting process "kid4" (generation 2) D [19/Jul/2012:05:56:52 -0700] [Job 301] Starting process "renderer" (generation 2) D [19/Jul/2012:05:56:52 -0700] [Job 301] JCL: %-12345X@PJL D [19/Jul/2012:05:56:52 -0700] [Job 301] @PJL SET MEDIATYPE=REGULAR D [19/Jul/2012:05:56:52 -0700] [Job 301] %-12345X@PJL RESET D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] Read 8192 bytes of print data... D [19/Jul/2012:05:56:52 -0700] [Job 301] renderer exited with status 0 D [19/Jul/2012:05:56:52 -0700] [Job 301] kid4 exited with status 0 D [19/Jul/2012:05:56:52 -0700] [Job 301] kid3 finished D [19/Jul/2012:05:56:52 -0700] [Job 301] Kid3 exit status: 0 D [19/Jul/2012:05:56:52 -0700] [Job 301] D [19/Jul/2012:05:56:52 -0700] [Job 301] Closing foomatic-rip. D [19/Jul/2012:05:56:52 -0700] PID 7448 (/usr/lib/cups/filter/foomatic-rip) exited with no errors. D [19/Jul/2012:05:56:53 -0700] [Job 300] Unloading... D [19/Jul/2012:05:57:01 -0700] [Job 301] Wrote 8192 bytes of print data... D [19/Jul/2012:05:57:01 -0700] [Job 301] Read 8192 bytes of print data... D [19/Jul/2012:05:57:01 -0700] [Job 301] Wrote 8192 bytes of print data... D [19/Jul/2012:05:57:01 -0700] [Job 301] Read 8192 bytes of print data... D [19/Jul/2012:05:57:01 -0700] [Job 301] Wrote 8192 bytes of print data... D [19/Jul/2012:05:57:01 -0700] [Job 301] Read 8192 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Wrote 8192 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Read 8192 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Wrote 8192 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Read 8192 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Wrote 8192 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Read 8192 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Wrote 8192 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Read 4451 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Wrote 4451 bytes of print data... D [19/Jul/2012:05:57:02 -0700] [Job 301] Sent 61795 bytes... D [19/Jul/2012:05:57:03 -0700] [Job 301] Resetting printer. D [19/Jul/2012:05:57:03 -0700] PID 7449 (/usr/lib/cups/backend/usb) exited with no errors. D [19/Jul/2012:05:57:03 -0700] Discarding unused job-completed event... I [19/Jul/2012:05:57:03 -0700] [Job 301] Job completed. D [19/Jul/2012:05:57:03 -0700] cupsdMarkDirty(----J-) D [19/Jul/2012:05:57:03 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Dirty files" D [19/Jul/2012:05:57:03 -0700] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files" D [19/Jul/2012:05:57:03 -0700] Discarding unused printer-state-changed event... D [19/Jul/2012:05:57:04 -0700] [Job 301] Unloading... I [19/Jul/2012:05:57:21 -0700] Saving job.cache... D [19/Jul/2012:05:57:21 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files" D [19/Jul/2012:05:58:13 -0700] Report: clients=2 D [19/Jul/2012:05:58:13 -0700] Report: jobs=40 D [19/Jul/2012:05:58:13 -0700] Report: jobs-active=0 D [19/Jul/2012:05:58:13 -0700] Report: printers=1 D [19/Jul/2012:05:58:13 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:58:13 -0700] Report: stringpool-string-count=4991 D [19/Jul/2012:05:58:13 -0700] Report: stringpool-alloc-bytes=8816 D [19/Jul/2012:05:58:13 -0700] Report: stringpool-total-bytes=88584 D [19/Jul/2012:05:59:34 -0700] cupsdAcceptClient: 19 from localhost (Domain) D [19/Jul/2012:05:59:34 -0700] Report: clients=3 D [19/Jul/2012:05:59:34 -0700] Report: jobs=40 D [19/Jul/2012:05:59:34 -0700] Report: jobs-active=0 D [19/Jul/2012:05:59:34 -0700] Report: printers=1 D [19/Jul/2012:05:59:34 -0700] Report: printers-implicit=0 D [19/Jul/2012:05:59:34 -0700] Report: stringpool-string-count=4991 D [19/Jul/2012:05:59:34 -0700] Report: stringpool-alloc-bytes=8816 D [19/Jul/2012:05:59:34 -0700] Report: stringpool-total-bytes=88584 D [19/Jul/2012:05:59:34 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:59:34 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:59:34 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:59:34 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Printers 1 D [19/Jul/2012:05:59:34 -0700] CUPS-Get-Printers D [19/Jul/2012:05:59:34 -0700] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost D [19/Jul/2012:05:59:34 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:59:34 -0700] cupsdReadClient: 19 POST / HTTP/1.1 D [19/Jul/2012:05:59:34 -0700] cupsdSetBusyState: newbusy="Active clients", busy="Not busy" D [19/Jul/2012:05:59:34 -0700] cupsdAuthorize: No authentication data provided. D [19/Jul/2012:05:59:34 -0700] cupsdReadClient: 19 1.1 CUPS-Get-Classes 1 D [19/Jul/2012:05:59:34 -0700] CUPS-Get-Classes D [19/Jul/2012:05:59:34 -0700] Returning IPP successful-ok for CUPS-Get-Classes (no URI) from localhost D [19/Jul/2012:05:59:34 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Active clients" D [19/Jul/2012:05:59:34 -0700] cupsdReadClient: 19 WAITING Closing on EOF D [19/Jul/2012:05:59:34 -0700] cupsdCloseClient: 19 D [19/Jul/2012:05:59:34 -0700] cupsdSetBusyState: newbusy="Not busy", busy="Not busy"