Output being sent to printer in PS format instead of raster

Tim Keenan tim at thekeenans.us
Wed Nov 5 14:18:31 PST 2008


Page printed by printer starts with %!PS-Adobe-3.0 %%BoundingBox...
Have turned-on debug, but log looks fine.

PPD file is HP-DeskJet_6940-hpijs.ppd

Any help will be greatly appreciated...

Log File Contents

d [05/Nov/2008:16:52:42 -0500] AcceptClient(lis=0x80823c8) 0 NumClients = 0
D [05/Nov/2008:16:52:42 -0500] AcceptClient: 7 from localhost:631.
d [05/Nov/2008:16:52:42 -0500] AcceptClient: Adding fd 7 to InputSet...
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
D [05/Nov/2008:16:52:42 -0500] ReadClient: 7 POST /admin/ HTTP/1.1
d [05/Nov/2008:16:52:42 -0500] decode_auth(0x403d8008): Authorization string = ""
d [05/Nov/2008:16:52:42 -0500] decode_auth: 7 username=""
d [05/Nov/2008:16:52:42 -0500] IsAuthorized: con->uri = "/admin/"
d [05/Nov/2008:16:52:42 -0500] FindBest: uri = "/admin/"...
d [05/Nov/2008:16:52:42 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: best = "/admin"
d [05/Nov/2008:16:52:42 -0500] IsAuthorized: auth = 0, satisfy=0...
d [05/Nov/2008:16:52:42 -0500] POST /admin/
d [05/Nov/2008:16:52:42 -0500] CONTENT_TYPE = application/ipp
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 121, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 113, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 84, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 47, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 1, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest(0x403d8008[7]): operation_id = 4004
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: URI="ipp://localhost/printers/rsipq"
d [05/Nov/2008:16:52:42 -0500] delete_printer(0x403d8008[7], ipp://localhost/printers/rsipq)
I [05/Nov/2008:16:52:42 -0500] Printer 'rsipq' deleted by ''.
I [05/Nov/2008:16:52:42 -0500] Saving printers.conf...
D [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: 7 status_code=0
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: Adding fd 7 to OutputSet...
d [05/Nov/2008:16:52:42 -0500] WriteClient: Removing fd 7 from OutputSet...
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: httpGets returned EOF...
D [05/Nov/2008:16:52:42 -0500] CloseClient: 7
d [05/Nov/2008:16:52:42 -0500] CloseClient: Removing fd 7 from InputSet and OutputSet...
d [05/Nov/2008:16:52:42 -0500] AcceptClient(lis=0x80823c8) 0 NumClients = 0
D [05/Nov/2008:16:52:42 -0500] AcceptClient: 7 from localhost:631.
d [05/Nov/2008:16:52:42 -0500] AcceptClient: Adding fd 7 to InputSet...
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
D [05/Nov/2008:16:52:42 -0500] ReadClient: 7 POST /admin/ HTTP/1.1
d [05/Nov/2008:16:52:42 -0500] decode_auth(0x403d8008): Authorization string = ""
d [05/Nov/2008:16:52:42 -0500] decode_auth: 7 username=""
d [05/Nov/2008:16:52:42 -0500] IsAuthorized: con->uri = "/admin/"
d [05/Nov/2008:16:52:42 -0500] FindBest: uri = "/admin/"...
d [05/Nov/2008:16:52:42 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: best = "/admin"
d [05/Nov/2008:16:52:42 -0500] IsAuthorized: auth = 0, satisfy=0...
d [05/Nov/2008:16:52:42 -0500] POST /admin/
d [05/Nov/2008:16:52:42 -0500] CONTENT_TYPE = application/ipp
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 175, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 167, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 138, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 101, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 55, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 32, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 1, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest(0x403d8008[7]): operation_id = 4003
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: URI="ipp://localhost/printers/rsipq"
d [05/Nov/2008:16:52:42 -0500] add_printer(0x403d8008[7], ipp://localhost/printers/rsipq)
d [05/Nov/2008:16:52:42 -0500] AddPrinter("rsipq")
I [05/Nov/2008:16:52:42 -0500] Setting rsipq printer-is-accepting-jobs to 1 (was 0.)
I [05/Nov/2008:16:52:42 -0500] Setting rsipq printer-state to 3 (was 5.)
d [05/Nov/2008:16:52:42 -0500] Adding filter application/vnd.cups-raw printer/rsipq 0 -
d [05/Nov/2008:16:52:42 -0500] FindBest: uri = "/printers/rsipq"...
d [05/Nov/2008:16:52:42 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: best = "/"
I [05/Nov/2008:16:52:42 -0500] Saving printers.conf...
I [05/Nov/2008:16:52:42 -0500] New printer 'rsipq' added by ''.
D [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: 7 status_code=0
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: Adding fd 7 to OutputSet...
d [05/Nov/2008:16:52:42 -0500] WriteClient: Removing fd 7 from OutputSet...
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
D [05/Nov/2008:16:52:42 -0500] ReadClient: 7 POST /admin/ HTTP/1.1
d [05/Nov/2008:16:52:42 -0500] decode_auth(0x403d8008): Authorization string = ""
d [05/Nov/2008:16:52:42 -0500] decode_auth: 7 username=""
d [05/Nov/2008:16:52:42 -0500] IsAuthorized: con->uri = "/admin/"
d [05/Nov/2008:16:52:42 -0500] FindBest: uri = "/admin/"...
d [05/Nov/2008:16:52:42 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: best = "/admin"
d [05/Nov/2008:16:52:42 -0500] IsAuthorized: auth = 0, satisfy=0...
d [05/Nov/2008:16:52:42 -0500] POST /admin/
d [05/Nov/2008:16:52:42 -0500] CONTENT_TYPE = application/ipp
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 174, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest(0x403d8008[7]): operation_id = 4003
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: URI="ipp://localhost/printers/rsipq"
d [05/Nov/2008:16:52:42 -0500] add_printer(0x403d8008[7], ipp://localhost/printers/rsipq)
I [05/Nov/2008:16:52:42 -0500] Setting rsipq device-uri to "beh:/1/1/0/socket://192.168.5.79:9100" (was "file:/dev/null".)
d [05/Nov/2008:16:52:42 -0500] Adding filter application/vnd.cups-raw printer/rsipq 0 -
d [05/Nov/2008:16:52:42 -0500] FindBest: uri = "/printers/rsipq"...
d [05/Nov/2008:16:52:42 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: best = "/"
I [05/Nov/2008:16:52:42 -0500] Saving printers.conf...
I [05/Nov/2008:16:52:42 -0500] Printer 'rsipq' modified by ''.
D [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: 7 status_code=0
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: Adding fd 7 to OutputSet...
d [05/Nov/2008:16:52:42 -0500] WriteClient: Removing fd 7 from OutputSet...
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
D [05/Nov/2008:16:52:42 -0500] ReadClient: 7 POST /admin/ HTTP/1.1
d [05/Nov/2008:16:52:42 -0500] decode_auth(0x403d8008): Authorization string = ""
d [05/Nov/2008:16:52:42 -0500] decode_auth: 7 username=""
d [05/Nov/2008:16:52:42 -0500] IsAuthorized: con->uri = "/admin/"
d [05/Nov/2008:16:52:42 -0500] FindBest: uri = "/admin/"...
d [05/Nov/2008:16:52:42 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: best = "/admin"
d [05/Nov/2008:16:52:42 -0500] IsAuthorized: auth = 0, satisfy=0...
d [05/Nov/2008:16:52:42 -0500] POST /admin/
d [05/Nov/2008:16:52:42 -0500] CONTENT_TYPE = application/ipp
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 159, con->file = -1
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest(0x403d8008[7]): operation_id = 4003
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: URI="ipp://localhost/printers/rsipq"
d [05/Nov/2008:16:52:42 -0500] add_printer(0x403d8008[7], ipp://localhost/printers/rsipq)
d [05/Nov/2008:16:52:42 -0500] copy_model("/usr/share/cups/model/HP-DeskJet_6940-hpijs.ppd", "/etc/cups/ppd/rsipq.ppd")
D [05/Nov/2008:16:52:42 -0500] add_printer: Copied PPD file successfully!
d [05/Nov/2008:16:52:42 -0500] Adding filter application/vnd.cups-raw printer/rsipq 0 -
d [05/Nov/2008:16:52:42 -0500] FindBest: uri = "/printers/rsipq"...
d [05/Nov/2008:16:52:42 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:52:42 -0500] FindBest: best = "/"
d [05/Nov/2008:16:52:42 -0500] Adding filter application/vnd.cups-postscript printer/rsipq 0 foomatic-rip
I [05/Nov/2008:16:52:42 -0500] Saving printers.conf...
I [05/Nov/2008:16:52:42 -0500] Printer 'rsipq' modified by ''.
D [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: 7 status_code=0
d [05/Nov/2008:16:52:42 -0500] ProcessIPPRequest: Adding fd 7 to OutputSet...
d [05/Nov/2008:16:52:42 -0500] WriteClient: Removing fd 7 from OutputSet...
d [05/Nov/2008:16:52:42 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:52:42 -0500] ReadClient: httpGets returned EOF...
D [05/Nov/2008:16:52:42 -0500] CloseClient: 7
d [05/Nov/2008:16:52:42 -0500] CloseClient: Removing fd 7 from InputSet and OutputSet...
d [05/Nov/2008:16:52:43 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:53:14 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:53:19 -0500] AcceptClient(lis=0x80823c8) 0 NumClients = 0
D [05/Nov/2008:16:53:19 -0500] AcceptClient: 7 from localhost:631.
d [05/Nov/2008:16:53:19 -0500] AcceptClient: Adding fd 7 to InputSet...
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7, used=0, file=-1
D [05/Nov/2008:16:53:19 -0500] ReadClient: 7 POST / HTTP/1.1
d [05/Nov/2008:16:53:19 -0500] decode_auth(0x403d8008): Authorization string = ""
d [05/Nov/2008:16:53:19 -0500] decode_auth: 7 username=""
d [05/Nov/2008:16:53:19 -0500] IsAuthorized: con->uri = "/"
d [05/Nov/2008:16:53:19 -0500] FindBest: uri = "/"...
d [05/Nov/2008:16:53:19 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:53:19 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:53:19 -0500] FindBest: best = "/"
d [05/Nov/2008:16:53:19 -0500] IsAuthorized: auth = 0, satisfy=0...
d [05/Nov/2008:16:53:19 -0500] POST /
d [05/Nov/2008:16:53:19 -0500] CONTENT_TYPE = application/ipp
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 135, con->file = -1
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 127, con->file = -1
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 98, con->file = -1
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 61, con->file = -1
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7, used=23, file=-1
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 24, con->file = -1
d [05/Nov/2008:16:53:19 -0500] ProcessIPPRequest(0x403d8008[7]): operation_id = 4002
d [05/Nov/2008:16:53:19 -0500] get_printers(0x403d8008[7], 0)
d [05/Nov/2008:16:53:19 -0500] add_printer_state_reasons(0x403d8008[7], 0x8094090[rsipq])
d [05/Nov/2008:16:53:19 -0500] add_queued_job_count(0x403d8008[7], 0x8094090[rsipq])
d [05/Nov/2008:16:53:19 -0500] copy_attrs(0x8094030, 0x8099e88, 0x809d720, 0)
d [05/Nov/2008:16:53:19 -0500] copy_attribute(0x8094030, 0x808b980[printer-name,4,42])
d [05/Nov/2008:16:53:19 -0500] copy_attribute(0x8094030, 0x8092498[job-sheets-default,4,42])
d [05/Nov/2008:16:53:19 -0500] copy_attrs(0x8094030, 0x8088f18, 0x809d720, 0)
D [05/Nov/2008:16:53:19 -0500] ProcessIPPRequest: 7 status_code=1
d [05/Nov/2008:16:53:19 -0500] ProcessIPPRequest: Adding fd 7 to OutputSet...
d [05/Nov/2008:16:53:19 -0500] select_timeout: 26 seconds to send browse update
d [05/Nov/2008:16:53:19 -0500] WriteClient: Removing fd 7 from OutputSet...
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7, used=0, file=-1
D [05/Nov/2008:16:53:19 -0500] ReadClient: 7 POST / HTTP/1.1
d [05/Nov/2008:16:53:19 -0500] decode_auth(0x403d8008): Authorization string = ""
d [05/Nov/2008:16:53:19 -0500] decode_auth: 7 username=""
d [05/Nov/2008:16:53:19 -0500] IsAuthorized: con->uri = "/"
d [05/Nov/2008:16:53:19 -0500] FindBest: uri = "/"...
d [05/Nov/2008:16:53:19 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:53:19 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:53:19 -0500] FindBest: best = "/"
d [05/Nov/2008:16:53:19 -0500] IsAuthorized: auth = 0, satisfy=0...
d [05/Nov/2008:16:53:19 -0500] POST /
d [05/Nov/2008:16:53:19 -0500] CONTENT_TYPE = application/ipp
d [05/Nov/2008:16:53:19 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 135, con->file = -1
d [05/Nov/2008:16:53:19 -0500] ProcessIPPRequest(0x403d8008[7]): operation_id = 4005
d [05/Nov/2008:16:53:19 -0500] get_printers(0x403d8008[7], 1)
D [05/Nov/2008:16:53:19 -0500] ProcessIPPRequest: 7 status_code=1
d [05/Nov/2008:16:53:19 -0500] ProcessIPPRequest: Adding fd 7 to OutputSet...
d [05/Nov/2008:16:53:19 -0500] WriteClient: Removing fd 7 from OutputSet...
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
D [05/Nov/2008:16:53:20 -0500] ReadClient: 7 POST / HTTP/1.1
d [05/Nov/2008:16:53:20 -0500] decode_auth(0x403d8008): Authorization string = ""
d [05/Nov/2008:16:53:20 -0500] decode_auth: 7 username=""
d [05/Nov/2008:16:53:20 -0500] IsAuthorized: con->uri = "/"
d [05/Nov/2008:16:53:20 -0500] FindBest: uri = "/"...
d [05/Nov/2008:16:53:20 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:53:20 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:53:20 -0500] FindBest: best = "/"
d [05/Nov/2008:16:53:20 -0500] IsAuthorized: auth = 0, satisfy=0...
d [05/Nov/2008:16:53:20 -0500] POST /
d [05/Nov/2008:16:53:20 -0500] CONTENT_TYPE = application/ipp
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 75, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ProcessIPPRequest(0x403d8008[7]): operation_id = 4001
d [05/Nov/2008:16:53:20 -0500] get_default(0x403d8008[7])
d [05/Nov/2008:16:53:20 -0500] copy_attrs(0x808acd8, 0x8099e88, (nil), 0)
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f2a8[printer-uri-supported,4,45])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8096ff8[uri-authentication-supported,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808c208[uri-security-supported,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808b980[printer-name,4,42])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8090c80[printer-location,4,41])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8090cb8[printer-info,4,41])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8090de8[printer-more-info,4,45])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8084b58[job-quota-period,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8091310[job-k-limit,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8091338[job-page-limit,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8092498[job-sheets-default,4,42])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8093ed0[device-uri,4,45])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x809e500[color-supported,4,22])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x80a6468[pages-per-minute,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x809d6c0[printer-make-and-model,4,41])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x80a72e0[media-supported,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x80a76d8[media-default,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x80a0740[sides-supported,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x80a7260[sides-default,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8094560[finishings-supported,4,23])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8091788[finishings-default,4,23])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8091128[printer-type,4,23])
d [05/Nov/2008:16:53:20 -0500] copy_attrs(0x808acd8, 0x8088f18, (nil), 0)
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f540[pdl-override-supported,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f0e0[ipp-versions-supported,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808ef48[operations-supported,4,23])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f3d0[multiple-document-jobs-supported,4,22])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f3a8[multiple-operation-time-out,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808eea0[multiple-document-handling-supported,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f260[charset-configured,4,47])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8099b88[charset-supported,4,47])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f220[natural-language-configured,4,48])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f1e0[generated-natural-language-supported,4,48])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f198[document-format-default,4,49])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8091380[document-format-supported,4,80000049])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8088f88[compression-supported,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f150[job-priority-supported,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808eee0[job-priority-default,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808ee78[copies-supported,4,33])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808ee20[copies-default,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x80886a8[page-ranges-supported,4,22])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f598[number-up-supported,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8088680[number-up-default,4,21])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f360[orientation-requested-supported,4,23])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8088558[orientation-requested-default,4,23])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808f420[job-hold-until-supported,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x8088f40[job-hold-until-default,4,44])
d [05/Nov/2008:16:53:20 -0500] copy_attribute(0x808acd8, 0x808b5a0[job-sheets-supported,4,42])
D [05/Nov/2008:16:53:20 -0500] ProcessIPPRequest: 7 status_code=0
d [05/Nov/2008:16:53:20 -0500] ProcessIPPRequest: Adding fd 7 to OutputSet...
d [05/Nov/2008:16:53:20 -0500] WriteClient: Removing fd 7 from OutputSet...
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: httpGets returned EOF...
D [05/Nov/2008:16:53:20 -0500] CloseClient: 7
d [05/Nov/2008:16:53:20 -0500] CloseClient: Removing fd 7 from InputSet and OutputSet...
d [05/Nov/2008:16:53:20 -0500] AcceptClient(lis=0x80823c8) 0 NumClients = 0
D [05/Nov/2008:16:53:20 -0500] AcceptClient: 7 from localhost:631.
d [05/Nov/2008:16:53:20 -0500] AcceptClient: Adding fd 7 to InputSet...
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
D [05/Nov/2008:16:53:20 -0500] ReadClient: 7 POST /printers/rsipq HTTP/1.1
d [05/Nov/2008:16:53:20 -0500] decode_auth(0x403d8008): Authorization string = ""
d [05/Nov/2008:16:53:20 -0500] decode_auth: 7 username=""
d [05/Nov/2008:16:53:20 -0500] IsAuthorized: con->uri = "/printers/rsipq"
d [05/Nov/2008:16:53:20 -0500] FindBest: uri = "/printers/rsipq"...
d [05/Nov/2008:16:53:20 -0500] FindBest: Location / Limit 7f
d [05/Nov/2008:16:53:20 -0500] FindBest: Location /admin Limit 7f
d [05/Nov/2008:16:53:20 -0500] FindBest: best = "/"
d [05/Nov/2008:16:53:20 -0500] IsAuthorized: auth = 0, satisfy=0...
d [05/Nov/2008:16:53:20 -0500] POST /printers/rsipq
d [05/Nov/2008:16:53:20 -0500] CONTENT_TYPE = application/ipp
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81862, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81854, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81825, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81788, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81738, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81709, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81687, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81643, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81627, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=9, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 81608, con->file = -1
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 REQUEST /var/spool/cups/0000000b=8
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 writing 32768 bytes to 8
d [05/Nov/2008:16:53:20 -0500] select_timeout: 25 seconds to send browse update
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=8
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 48830, con->file = 8
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 writing 32768 bytes to 8
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=8
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 con->data_encoding = length, con->data_remaining = 16062, con->file = 8
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 writing 16062 bytes to 8
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7 Closing data file 8, size = 81598.
d [05/Nov/2008:16:53:20 -0500] ProcessIPPRequest(0x403d8008[7]): operation_id = 0002
d [05/Nov/2008:16:53:20 -0500] ProcessIPPRequest: URI="ipp://localhost:631/printers/rsipq"
d [05/Nov/2008:16:53:20 -0500] print_job(0x403d8008[7], ipp://localhost:631/printers/rsipq)
D [05/Nov/2008:16:53:20 -0500] print_job: auto-typing file...
D [05/Nov/2008:16:53:20 -0500] print_job: request file type is image/jpeg.
d [05/Nov/2008:16:53:20 -0500] check_quotas(0x403d8008[7], 0x8094090[rsipq])
D [05/Nov/2008:16:53:20 -0500] check_quotas: requesting-user-name = 'root'
D [05/Nov/2008:16:53:20 -0500] print_job: requesting-user-name = 'root'
I [05/Nov/2008:16:53:20 -0500] Adding start banner page "none" to job 22.
d [05/Nov/2008:16:53:20 -0500] copy_banner(0x403d8008[7], 0x8093f28[22], none)
d [05/Nov/2008:16:53:20 -0500] add_file(con=0x403d8008[7], job=22, filetype=image/jpeg, compression=0)
I [05/Nov/2008:16:53:20 -0500] Adding end banner page "none" to job 22.
d [05/Nov/2008:16:53:20 -0500] copy_banner(0x403d8008[7], 0x8093f28[22], none)
I [05/Nov/2008:16:53:20 -0500] Job 22 queued on 'rsipq' by 'root'.
D [05/Nov/2008:16:53:20 -0500] Job 22 hold_until = 0
d [05/Nov/2008:16:53:20 -0500] SaveJob: Closing file 8...
D [05/Nov/2008:16:53:20 -0500] StartJob(22, 0x8094090)
D [05/Nov/2008:16:53:20 -0500] StartJob() id = 22, file = 0/1
D [05/Nov/2008:16:53:20 -0500] job-sheets=none,none
D [05/Nov/2008:16:53:20 -0500] banner_page = 0
D [05/Nov/2008:16:53:20 -0500] StartJob: argv = "rsipq","22","root","rsisc.jpg","1","landscape","/var/spool/cups/d00022-001"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[0]="PATH=/usr/lib/cups/filter:/bin:/usr/bin"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[1]="SOFTWARE=CUPS/1.1"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[2]="USER=root"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[3]="CHARSET=utf-8"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[4]="LANG=en_US"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[5]="TZ=America/New_York"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[6]="PPD=/etc/cups/ppd/rsipq.ppd"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[7]="CUPS_SERVERROOT=/etc/cups"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[8]="RIP_MAX_CACHE=8m"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[9]="TMPDIR=/var/spool/cups/tmp"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[10]="CONTENT_TYPE=image/jpeg"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[11]="DEVICE_URI=beh:/1/1/0/socket://192.168.5.79:9100"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[12]="PRINTER=rsipq"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[13]="CUPS_DATADIR=/usr/share/cups"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[14]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[15]="CUPS_SERVER=localhost"
D [05/Nov/2008:16:53:20 -0500] StartJob: envp[16]="IPP_PORT=631"
d [05/Nov/2008:16:53:20 -0500] StartJob: Allocating status buffer...
D [05/Nov/2008:16:53:20 -0500] StartJob: statusfds = [ 8 9 ]
D [05/Nov/2008:16:53:20 -0500] StartJob: filterfds[1] = [ 10 -1 ]
D [05/Nov/2008:16:53:20 -0500] StartJob: filter = "/usr/lib/cups/filter/imagetops"
D [05/Nov/2008:16:53:20 -0500] StartJob: filterfds[0] = [ 11 12 ]
D [05/Nov/2008:16:53:20 -0500] start_process("/usr/lib/cups/filter/imagetops", 0xbfff01f0, 0xbffef560, 10, 12, 9)
I [05/Nov/2008:16:53:20 -0500] Started filter /usr/lib/cups/filter/imagetops (PID 25221) for job 22.
D [05/Nov/2008:16:53:20 -0500] StartJob: filter = "/usr/lib/cups/filter/foomatic-rip"
D [05/Nov/2008:16:53:20 -0500] StartJob: filterfds[1] = [ 10 13 ]
D [05/Nov/2008:16:53:20 -0500] start_process("/usr/lib/cups/filter/foomatic-rip", 0xbfff01f0, 0xbffef560, 11, 13, 9)
I [05/Nov/2008:16:53:20 -0500] Started filter /usr/lib/cups/filter/foomatic-rip (PID 25222) for job 22.
D [05/Nov/2008:16:53:20 -0500] StartJob: backend = "/usr/lib/cups/backend/beh"
D [05/Nov/2008:16:53:20 -0500] StartJob: filterfds[0] = [ -1 11 ]
D [05/Nov/2008:16:53:20 -0500] start_process("/usr/lib/cups/backend/beh", 0xbfff01f0, 0xbffef560, 10, 11, 9)
I [05/Nov/2008:16:53:20 -0500] Started backend /usr/lib/cups/backend/beh (PID 25223) for job 22.
d [05/Nov/2008:16:53:20 -0500] StartJob: Adding fd 8 to InputSet...
d [05/Nov/2008:16:53:20 -0500] add_job_state_reasons(0x403d8008[7], 22)
D [05/Nov/2008:16:53:20 -0500] ProcessIPPRequest: 7 status_code=0
d [05/Nov/2008:16:53:20 -0500] ProcessIPPRequest: Adding fd 7 to OutputSet...
I [05/Nov/2008:16:53:20 -0500] [Job 22] rsipq 22 root rsisc.jpg 1 landscape /var/spool/cups/d00022-001
D [05/Nov/2008:16:53:20 -0500] [Job 22] ImageOpen("/var/spool/cups/d00022-001", 4, 1, 100, 0, (nil))
D [05/Nov/2008:16:53:20 -0500] [Job 22] num_components = 3
D [05/Nov/2008:16:53:20 -0500] [Job 22] jpeg_color_space = JCS_YCbCr
D [05/Nov/2008:16:53:20 -0500] [Job 22] Converting image to RGB...
D [05/Nov/2008:16:53:20 -0500] [Job 22] JPEG image 410x347x3, 128x128 PPI
D [05/Nov/2008:16:53:20 -0500] [Job 22] max_ics=10...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Creating tile array (2x2)
D [05/Nov/2008:16:53:20 -0500] [Job 22] Allocated cache tile 1 (0x404ad008)...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Clearing cache tile...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Allocated cache tile 2 (0x404de008)...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Clearing cache tile...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Allocated cache tile 3 (0x4050f008)...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Clearing cache tile...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Allocated cache tile 4 (0x40540008)...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Clearing cache tile...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Before scaling: xppi=128, yppi=128, zoom=0.00
D [05/Nov/2008:16:53:20 -0500] [Job 22] Before scaling: xprint=10.0, yprint=8.0
D [05/Nov/2008:16:53:20 -0500] [Job 22] Image size is 3.2 x 2.7 inches...
D [05/Nov/2008:16:53:20 -0500] [Job 22] xpages = 1x3.20in, ypages = 1x2.71in
D [05/Nov/2008:16:53:20 -0500] [Job 22] XPosition=0, YPosition=0, Orientation=3
D [05/Nov/2008:16:53:20 -0500] [Job 22] xprint=3, yprint=3
D [05/Nov/2008:16:53:20 -0500] [Job 22] PageLeft=18, PageRight=594, PageWidth=612
D [05/Nov/2008:16:53:20 -0500] [Job 22] PageBottom=36, PageTop=756, PageLength=792
D [05/Nov/2008:16:53:20 -0500] [Job 22] left=280.69, top=403.59
I [05/Nov/2008:16:53:20 -0500] [Job 22] Printing page 1...
d [05/Nov/2008:16:53:20 -0500] WriteClient: Removing fd 7 from OutputSet...
d [05/Nov/2008:16:53:20 -0500] ReadClient: 7, used=0, file=-1
d [05/Nov/2008:16:53:20 -0500] ReadClient: httpGets returned EOF...
D [05/Nov/2008:16:53:20 -0500] CloseClient: 7
d [05/Nov/2008:16:53:20 -0500] CloseClient: Removing fd 7 from InputSet and OutputSet...
D [05/Nov/2008:16:53:20 -0500] [Job 22] whoami: cannot find username for UID 4
D [05/Nov/2008:16:53:20 -0500] [Job 22] Freeing memory...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Freeing cache (0x404ad008, next = (nil))...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Freeing cache (0x404de008, next = 0x404de008)...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Freeing cache (0x4050f008, next = 0x4050f008)...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Freeing cache (0x40540008, next = 0x40540008)...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Freeing tiles (0x8058ed8)...
D [05/Nov/2008:16:53:20 -0500] [Job 22] Freeing tile pointers (0x8058ec8)...
d [05/Nov/2008:16:53:20 -0500] PID 25221 exited with no errors.
d [05/Nov/2008:16:53:20 -0500] PID 25222 exited with no errors.
I [05/Nov/2008:16:53:20 -0500] [Job 22] Attempting to connect to host 192.168.5.79 on port 9100
I [05/Nov/2008:16:53:20 -0500] [Job 22] Connected to host, sending print job...
I [05/Nov/2008:16:53:20 -0500] [Job 22] Sending print file, 8192 bytes...
I [05/Nov/2008:16:53:20 -0500] [Job 22] Sending print file, 16384 bytes...
I [05/Nov/2008:16:53:20 -0500] [Job 22] Sending print file, 24576 bytes...
I [05/Nov/2008:16:53:20 -0500] [Job 22] Sending print file, 32768 bytes...
I [05/Nov/2008:16:53:20 -0500] [Job 22] Sending print file, 40960 bytes...
I [05/Nov/2008:16:53:20 -0500] [Job 22] Sending print file, 49152 bytes...
d [05/Nov/2008:16:53:21 -0500] select_timeout: 11 seconds to process active jobs
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 57344 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 65536 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 73728 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 81920 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 90112 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 98304 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 106496 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 114688 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 122880 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 131072 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 139264 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 147456 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 155648 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 163840 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 172032 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 180224 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 188416 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 196608 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 204800 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 212992 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 221184 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 229376 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 237568 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 245760 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 253952 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 262144 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 270336 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 278528 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 286720 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 294912 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 303104 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 311296 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 319488 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 327680 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 335872 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 344064 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 352256 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 360448 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 368640 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 376832 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 385024 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 393216 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 401408 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 409600 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 417792 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 425984 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 434176 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 442368 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 450560 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 458752 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 466944 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 475136 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 483328 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 491520 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 499712 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 507904 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 516096 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 524288 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 532480 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 540672 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 548864 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 557056 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 565248 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 573440 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 581632 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 589824 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 598016 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 606208 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 614400 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 622592 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 630784 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 638976 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 647168 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 655360 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 663552 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 671744 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 679936 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 688128 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 696320 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 704512 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 712704 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 720896 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 729088 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 737280 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 745472 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 753664 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 761856 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 770048 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 778240 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 786432 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 794624 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 802816 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 811008 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 819200 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 827392 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 835584 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 843776 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 851968 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 860160 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Sending print file, 865511 bytes...
I [05/Nov/2008:16:53:27 -0500] [Job 22] Print file sent, waiting for printer to finish...
d [05/Nov/2008:16:53:27 -0500] PID 25223 exited with no errors.
D [05/Nov/2008:16:53:27 -0500] UpdateJob: job 22, file 0 is complete.
d [05/Nov/2008:16:53:27 -0500] UpdateJob: Removing fd 8 from InputSet...
D [05/Nov/2008:16:53:27 -0500] CancelJob: id = 22
D [05/Nov/2008:16:53:27 -0500] StopJob: id = 22, force = 0
D [05/Nov/2008:16:53:27 -0500] StopJob: printer state is 3
d [05/Nov/2008:16:53:27 -0500] StopJob: Freeing status buffer...
d [05/Nov/2008:16:53:27 -0500] SaveJob: Closing file 7...
d [05/Nov/2008:16:53:27 -0500] SaveJob: Closing file 7...
d [05/Nov/2008:16:53:28 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:53:59 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:54:30 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:55:01 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:55:32 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:56:03 -0500] select_timeout: 29 seconds to update root certificate
d [05/Nov/2008:16:56:32 -0500] DeleteCert: removing certificate for pid 0
d [05/Nov/2008:16:56:32 -0500] AddCert: adding certificate for pid 0
d [05/Nov/2008:16:56:32 -0500] select_timeout: 2 seconds to send browse update
d [05/Nov/2008:16:56:34 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:57:05 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:57:36 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:58:07 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:58:38 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:59:09 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:16:59:40 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:00:11 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:00:42 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:01:13 -0500] select_timeout: 20 seconds to update root certificate
d [05/Nov/2008:17:01:33 -0500] DeleteCert: removing certificate for pid 0
d [05/Nov/2008:17:01:33 -0500] AddCert: adding certificate for pid 0
d [05/Nov/2008:17:01:33 -0500] select_timeout: 11 seconds to send browse update
d [05/Nov/2008:17:01:44 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:02:15 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:02:46 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:03:17 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:03:48 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:04:19 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:04:50 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:05:21 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:05:52 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:06:23 -0500] select_timeout: 11 seconds to update root certificate
d [05/Nov/2008:17:06:34 -0500] DeleteCert: removing certificate for pid 0
d [05/Nov/2008:17:06:34 -0500] AddCert: adding certificate for pid 0
d [05/Nov/2008:17:06:34 -0500] select_timeout: 20 seconds to send browse update
d [05/Nov/2008:17:06:54 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:07:25 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:07:56 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:08:27 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:08:58 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:09:29 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:10:00 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:10:31 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:11:02 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:11:33 -0500] select_timeout: 2 seconds to update root certificate
d [05/Nov/2008:17:11:35 -0500] DeleteCert: removing certificate for pid 0
d [05/Nov/2008:17:11:35 -0500] AddCert: adding certificate for pid 0
d [05/Nov/2008:17:11:35 -0500] select_timeout: 29 seconds to send browse update
d [05/Nov/2008:17:12:04 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:12:35 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:13:06 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:13:37 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:14:08 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:14:39 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:15:10 -0500] select_timeout: 31 seconds to send browse update
d [05/Nov/2008:17:15:41 -0500] select_timeout: 31 seconds to send browse update

Foomatic-Rip Log

foomatic-rip version $Revision=3.0.2.136$ running...
called with arguments: '22', 'root', 'rsisc.jpg', '1', 'landscape'
Parsing PPD file ...

Parameter Summary
-----------------

Spooler: cups
Printer: rsipq
Shell: /bin/sh
PPD file: /etc/cups/ppd/rsipq.ppd
ATTR file:
Printer model: Raw queue
Options: landscape
Job title: rsisc.jpg
File(s) to be printed:
<STDIN>

GhostScript extra search path ('GS_LIB'): /usr/share/cups/fonts
Pondering option 'landscape'
Unknown boolean option "landscape".
Starting process 25228: "> /tmp/foomatic-rip.ps"
Process 25228 ending: "> /tmp/foomatic-rip.ps"

================================================

File: <STDIN>

================================================

Raw printing, executing "cat "

Starting process 25229: "cat "
Process 25229 ending: "cat "
$VAR1 = {
  'cupsfilter' => {},
  'cmd' => 'cat%A%B%C%D%E%F%G%H%I%J%K%L%M%Z',
  'args' => []
};

Closing foomatic-rip.






More information about the cups mailing list