Job NOT being filtered
Stefan Adams
stefan at borgia.com
Wed May 23 06:20:58 PDT 2007
It's possible to filter a job of text sent from the command line, right?
Like this:
# echo hi | lpr
# cat /etc/cups/*.{types,convs}
text/hi printable(0,1024) + string(0,hi)
text/hi application/vnd.cups-postscript 3 skeleton
# ls -l /usr/lib/cups/filter/skeleton
-rwxr-xr-x 1 root root 3522 May 22 20:01 /usr/lib/cups/filter/skeleton*
# cat /usr/lib/cups/filter/skeleton
#!/usr/bin/perl
$|=1;
open TMP, ">/tmp/skeleton.tmp";
print TMP qx{date};
close TMP;
exit 0;
The output of the error_log with debug2 is below. My 'echo hi | lpr' is clearly being recognized as type text/hi. But it's not even trying to execute the filter. It just sends 'hi' to the printer. Any ideas why?
d [23/May/2007:08:18:16 -0500] cupsdAcceptClient(lis=0x809ff28) 2 Clients = 0
D [23/May/2007:08:18:16 -0500] cupsdAcceptClient: 8 from localhost:631 (IPv4)
d [23/May/2007:08:18:16 -0500] cupsdAcceptClient: 8 connected to server on localhost:631
d [23/May/2007:08:18:16 -0500] cupsdAcceptClient: Adding fd 8 to InputSet...
d [23/May/2007:08:18:16 -0500] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0
d [23/May/2007:08:18:16 -0500] stringpool: 321 strings, 5008 allocated, 6376 total bytes
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=0, file=-1 state=0
D [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 POST / HTTP/1.1
d [23/May/2007:08:18:16 -0500] cupsdFindBest: uri = "/"...
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location /admin Limit 7f
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location / Limit 7f
d [23/May/2007:08:18:16 -0500] cupsdFindBest: best = /
d [23/May/2007:08:18:16 -0500] cupsdAuthorize: con->uri="/", con->best=0x80a00b0(/)
d [23/May/2007:08:18:16 -0500] cupsdAuthorize: Authorization=""
D [23/May/2007:08:18:16 -0500] cupsdAuthorize: No authentication data provided.
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: con->uri="/", con->best=0x80a00b0(/)
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [23/May/2007:08:18:16 -0500] POST /
d [23/May/2007:08:18:16 -0500] CONTENT_TYPE = application/ipp
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=351, con->file=-1
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=343, file=-1 state=6
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=343, con->file=-1
d [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest(0x80b5038[8]): operation_id = 4002
D [23/May/2007:08:18:16 -0500] CUPS-Get-Printers
d [23/May/2007:08:18:16 -0500] get_printers(0x80b5038[8], 0)
d [23/May/2007:08:18:16 -0500] cupsdFindPolicyOp(p=0x8099dc8, op=4002(CUPS-Get-Printers))
d [23/May/2007:08:18:16 -0500] cupsdFindPolicyOp: Found wildcard match...
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: con->uri="/", con->best=0x809af90((null))
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: op=0(unknown-0000)
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [23/May/2007:08:18:16 -0500] add_printer_state_reasons(0x80b5038[8], 0x809b0d8[HP3550])
d [23/May/2007:08:18:16 -0500] copy_attrs(to=0x80ac1d0, from=0x80a37b8, ra=0x80ac888, group=0, quickcopy=0)
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a38c8[printer-name,4,42])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2718[printer-info,4,41])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a28e8[printer-make-and-model,4,41])
d [23/May/2007:08:18:16 -0500] copy_attrs(to=0x80ac1d0, from=0x809b9c0, ra=0x80ac888, group=0, quickcopy=-2147483648)
D [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
d [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest: Adding fd 8 to OutputSet...
d [23/May/2007:08:18:16 -0500] select_timeout: 14 seconds to send browse update
d [23/May/2007:08:18:16 -0500] cupsdWriteClient: 8 bytes < 0
d [23/May/2007:08:18:16 -0500] cupsdWriteClient: Removing fd 8 from OutputSet...
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=0, file=-1 state=0
D [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 POST / HTTP/1.1
d [23/May/2007:08:18:16 -0500] cupsdFindBest: uri = "/"...
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location /admin Limit 7f
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location / Limit 7f
d [23/May/2007:08:18:16 -0500] cupsdFindBest: best = /
d [23/May/2007:08:18:16 -0500] cupsdAuthorize: con->uri="/", con->best=0x80a00b0(/)
d [23/May/2007:08:18:16 -0500] cupsdAuthorize: Authorization=""
D [23/May/2007:08:18:16 -0500] cupsdAuthorize: No authentication data provided.
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: con->uri="/", con->best=0x80a00b0(/)
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [23/May/2007:08:18:16 -0500] POST /
d [23/May/2007:08:18:16 -0500] CONTENT_TYPE = application/ipp
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=351, con->file=-1
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=343, file=-1 state=6
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=343, con->file=-1
d [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest(0x80b5038[8]): operation_id = 4005
D [23/May/2007:08:18:16 -0500] CUPS-Get-Classes
d [23/May/2007:08:18:16 -0500] get_printers(0x80b5038[8], 1)
d [23/May/2007:08:18:16 -0500] cupsdFindPolicyOp(p=0x8099dc8, op=4005(CUPS-Get-Classes))
d [23/May/2007:08:18:16 -0500] cupsdFindPolicyOp: Found wildcard match...
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: con->uri="/", con->best=0x809af90((null))
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: op=0(unknown-0000)
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: auth=AUTH_ALLOW...
D [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
d [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest: Adding fd 8 to OutputSet...
d [23/May/2007:08:18:16 -0500] select_timeout: 14 seconds to send browse update
d [23/May/2007:08:18:16 -0500] cupsdWriteClient: 8 bytes < 0
d [23/May/2007:08:18:16 -0500] cupsdWriteClient: Removing fd 8 from OutputSet...
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=0, file=-1 state=0
D [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 POST / HTTP/1.1
d [23/May/2007:08:18:16 -0500] cupsdFindBest: uri = "/"...
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location /admin Limit 7f
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location / Limit 7f
d [23/May/2007:08:18:16 -0500] cupsdFindBest: best = /
d [23/May/2007:08:18:16 -0500] cupsdAuthorize: con->uri="/", con->best=0x80a00b0(/)
d [23/May/2007:08:18:16 -0500] cupsdAuthorize: Authorization=""
D [23/May/2007:08:18:16 -0500] cupsdAuthorize: No authentication data provided.
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: con->uri="/", con->best=0x80a00b0(/)
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [23/May/2007:08:18:16 -0500] POST /
d [23/May/2007:08:18:16 -0500] CONTENT_TYPE = application/ipp
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=80, con->file=-1
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=72, file=-1 state=6
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=72, con->file=-1
d [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest(0x80b5038[8]): operation_id = 4001
D [23/May/2007:08:18:16 -0500] CUPS-Get-Default
d [23/May/2007:08:18:16 -0500] get_default(0x80b5038[8])
d [23/May/2007:08:18:16 -0500] cupsdFindPolicyOp(p=0x8099dc8, op=4001(CUPS-Get-Default))
d [23/May/2007:08:18:16 -0500] cupsdFindPolicyOp: Found wildcard match...
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: con->uri="/", con->best=0x809af90((null))
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: op=0(unknown-0000)
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [23/May/2007:08:18:16 -0500] add_printer_state_reasons(0x80b5038[8], 0x809b0d8[HP3550])
d [23/May/2007:08:18:16 -0500] printer-uri-supported="ipp://localhost:631/printers/HP3550"
d [23/May/2007:08:18:16 -0500] add_queued_job_count(0x80b5038[8], 0x809b0d8[HP3550])
d [23/May/2007:08:18:16 -0500] copy_attrs(to=0x80ac1d0, from=0x80a37b8, ra=(nil), group=0, quickcopy=0)
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a37e0[uri-authentication-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3870[uri-security-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a38c8[printer-name,4,42])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3918[printer-location,4,41])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2718[printer-info,4,41])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2768[printer-more-info,4,45])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a27b8[job-quota-period,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2808[job-k-limit,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2850[job-page-limit,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a28a0[device-uri,4,45])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a28e8[printer-make-and-model,4,41])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3dd8[finishings-supported,4,23])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3e30[finishings-default,4,23])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3ec0[document-format-supported,4,80000049])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3f20[copies-default,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3f70[job-hold-until-default,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3fc8[job-priority-default,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a4020[number-up-default,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a4070[orientation-requested-default,4,23])
d [23/May/2007:08:18:16 -0500] copy_attrs(to=0x80ac1d0, from=0x809b9c0, ra=(nil), group=0, quickcopy=-2147483648)
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3760[charset-configured,4,47])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a49c8[charset-supported,4,47])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2978[compression-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a36f8[copies-supported,4,33])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3628[document-format-default,4,49])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a35d0[generated-natural-language-supported,4,48])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a29f8[ipp-versions-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2610[job-hold-until-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a35a8[job-priority-supported,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3288[job-sheets-supported,4,42])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2570[multiple-document-handling-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2d90[multiple-document-jobs-supported,4,22])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2cd8[multiple-operation-time-out,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2d10[natural-language-configured,4,48])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a36a8[notify-attributes-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2cb0[notify-lease-duration-default,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2b18[notify-lease-duration-supported,4,33])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2a60[notify-max-events-supported,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2a98[notify-events-default,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2e10[notify-events-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2a38[notify-pull-method-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x809b9e8[notify-schemes-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3308[number-up-supported,4,21])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a3390[operations-supported,4,23])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a4960[orientation-requested-supported,4,23])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a25c8[page-ranges-supported,4,22])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2348[pdl-override-supported,4,44])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a2408[printer-error-policy-supported,4,42])
d [23/May/2007:08:18:16 -0500] copy_attribute(0x80ac1d0, 0x80a24d0[printer-op-policy-supported,4,42])
D [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
d [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest: Adding fd 8 to OutputSet...
d [23/May/2007:08:18:16 -0500] select_timeout: 14 seconds to send browse update
d [23/May/2007:08:18:16 -0500] cupsdWriteClient: 8 bytes < 0
d [23/May/2007:08:18:16 -0500] cupsdWriteClient: Removing fd 8 from OutputSet...
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=0, file=-1 state=0
d [23/May/2007:08:18:16 -0500] cupsdReadClient: httpGets returned EOF...
D [23/May/2007:08:18:16 -0500] cupsdCloseClient: 8
d [23/May/2007:08:18:16 -0500] cupsdCloseClient: Removing fd 8 from InputSet and OutputSet...
d [23/May/2007:08:18:16 -0500] cupsdAcceptClient(lis=0x809ff28) 2 Clients = 0
D [23/May/2007:08:18:16 -0500] cupsdAcceptClient: 8 from localhost:631 (IPv4)
d [23/May/2007:08:18:16 -0500] cupsdAcceptClient: 8 connected to server on localhost:631
d [23/May/2007:08:18:16 -0500] cupsdAcceptClient: Adding fd 8 to InputSet...
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=0, file=-1 state=0
D [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 POST /printers/HP3550 HTTP/1.1
d [23/May/2007:08:18:16 -0500] cupsdFindBest: uri = "/printers/HP3550"...
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location /admin Limit 7f
d [23/May/2007:08:18:16 -0500] cupsdFindBest: Location / Limit 7f
d [23/May/2007:08:18:16 -0500] cupsdFindBest: best = /
d [23/May/2007:08:18:16 -0500] cupsdAuthorize: con->uri="/printers/HP3550", con->best=0x80a00b0(/)
d [23/May/2007:08:18:16 -0500] cupsdAuthorize: Authorization=""
D [23/May/2007:08:18:16 -0500] cupsdAuthorize: No authentication data provided.
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: con->uri="/printers/HP3550", con->best=0x80a00b0(/)
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [23/May/2007:08:18:16 -0500] POST /printers/HP3550
d [23/May/2007:08:18:16 -0500] CONTENT_TYPE = application/ipp
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=221, con->file=-1
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=210, file=-1 state=6
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=213, con->file=-1
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 REQUEST /var/spool/cups/00000002=9
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 writing 3 bytes to 9
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8 Closing data file 9, size=3.
d [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest(0x80b5038[8]): operation_id = 0002
D [23/May/2007:08:18:16 -0500] Print-Job ipp://localhost/printers/HP3550
d [23/May/2007:08:18:16 -0500] print_job(0x80b5038[8], ipp://localhost/printers/HP3550)
D [23/May/2007:08:18:16 -0500] print_job: auto-typing file...
D [23/May/2007:08:18:16 -0500] print_job: request file type is text/hi.
d [23/May/2007:08:18:16 -0500] add_job(0x80b5038[8], ipp://localhost/printers/HP3550)
d [23/May/2007:08:18:16 -0500] cupsdFindPolicyOp(p=0x8099dc8, op=2(Print-Job))
d [23/May/2007:08:18:16 -0500] cupsdFindPolicyOp: Found wildcard match...
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: con->uri="/printers/HP3550", con->best=0x809af90((null))
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: op=0(unknown-0000)
d [23/May/2007:08:18:16 -0500] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [23/May/2007:08:18:16 -0500] check_quotas(0x80b5038[8], 0x809b0d8[HP3550])
D [23/May/2007:08:18:16 -0500] add_job: requesting-user-name="root"
D [23/May/2007:08:18:16 -0500] Adding default job-sheets values "none,none"...
I [23/May/2007:08:18:16 -0500] Adding start banner page "none" to job 31.
d [23/May/2007:08:18:16 -0500] copy_banner(0x80b5038[8], 0x80af0f0[31], none)
d [23/May/2007:08:18:16 -0500] add_job_state_reasons(0x80b5038[8], 31)
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=job-created, dest=0x809b0d8(HP3550), job=0x80af0f0(31), text="Job created.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused job-created event...
d [23/May/2007:08:18:16 -0500] add_file(con=0x80b5038[8], job=31, filetype=text/hi, compression=0)
I [23/May/2007:08:18:16 -0500] Adding end banner page "none" to job 31.
d [23/May/2007:08:18:16 -0500] copy_banner(0x80b5038[8], 0x80af0f0[31], none)
I [23/May/2007:08:18:16 -0500] Job 31 queued on "HP3550" by "root".
D [23/May/2007:08:18:16 -0500] Job 31 hold_until = 0
d [23/May/2007:08:18:16 -0500] cupsdSaveJob(job=0x80af0f0(31)): job->attrs=0x80ae390
d [23/May/2007:08:18:16 -0500] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [23/May/2007:08:18:16 -0500] cupsdCheckJobs: Job 31: state_value=3, loaded=yes
d [23/May/2007:08:18:16 -0500] start_job: id = 31, file = 0/1
D [23/May/2007:08:18:16 -0500] [Job 31] Sending job to queue tagged as raw...
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="%s "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
D [23/May/2007:08:18:16 -0500] job-sheets=none,none
D [23/May/2007:08:18:16 -0500] banner_page = 0
D [23/May/2007:08:18:16 -0500] [Job 31] argv[0]="HP3550"
D [23/May/2007:08:18:16 -0500] [Job 31] argv[1]="31"
D [23/May/2007:08:18:16 -0500] [Job 31] argv[2]="root"
D [23/May/2007:08:18:16 -0500] [Job 31] argv[3]="STDIN"
D [23/May/2007:08:18:16 -0500] [Job 31] argv[4]="1"
D [23/May/2007:08:18:16 -0500] [Job 31] argv[5]="job-uuid=urn:uuid:303d646b-c373-38cd-44d6-05719156a33d"
D [23/May/2007:08:18:16 -0500] [Job 31] argv[6]="/var/spool/cups/d00031-001"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[8]="NLSPATH=/usr/share/locale/%l/%N"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[10]="SERVER_ADMIN=root at localhost"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[11]="SOFTWARE=CUPS/1.2.11"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[13]="USER=root"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[14]="CUPS_SERVER=localhost"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[16]="IPP_PORT=631"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[17]="CHARSET=iso-8859-1"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[18]="LANG=en_US"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[19]="PPD=/etc/cups/ppd/HP3550.ppd"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[20]="RIP_MAX_CACHE=8m"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[21]="CONTENT_TYPE=text/hi"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[22]="DEVICE_URI=socket://192.168.0.148"
D [23/May/2007:08:18:16 -0500] [Job 31] envp[23]="PRINTER=HP3550"
d [23/May/2007:08:18:16 -0500] start_job: status_pipes = [ 11 12 ]
d [23/May/2007:08:18:16 -0500] start_job: backend="/usr/lib/cups/backend/socket"
d [23/May/2007:08:18:16 -0500] start_job: filterfds[0] = [ -1 -1 ]
d [23/May/2007:08:18:16 -0500] cupsdStartProcess("/usr/lib/cups/backend/socket", 0x80ac818, 0xbfbae95c, -1, -1, 12)
I [23/May/2007:08:18:16 -0500] Started backend /usr/lib/cups/backend/socket (PID 5429) for job 31.
d [23/May/2007:08:18:16 -0500] start_job: Closing print pipes [ -1 -1 ]...
d [23/May/2007:08:18:16 -0500] start_job: Closing back pipes [ 9 10 ]...
d [23/May/2007:08:18:16 -0500] start_job: Closing status output pipe 12...
d [23/May/2007:08:18:16 -0500] start_job: Closing filter pipes for slot 0 [ -1 -1 ]...
d [23/May/2007:08:18:16 -0500] start_job: Adding fd 11 to InputSet...
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=job-state, dest=0x809b0d8(HP3550), job=0x80af0f0(31), text="Job #%d started.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused job-state event...
D [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
d [23/May/2007:08:18:16 -0500] cupsdProcessIPPRequest: Adding fd 8 to OutputSet...
d [23/May/2007:08:18:16 -0500] select_timeout: 1 seconds to send browse update
I [23/May/2007:08:18:16 -0500] [Job 31] Attempting to connect to host 192.168.0.148 on port 9100
d [23/May/2007:08:18:16 -0500] [Job 31] STATE: +connecting-to-device
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
d [23/May/2007:08:18:16 -0500] cupsdWriteClient: 8 bytes < 0
d [23/May/2007:08:18:16 -0500] cupsdWriteClient: Removing fd 8 from OutputSet...
d [23/May/2007:08:18:16 -0500] cupsdReadClient: 8, used=0, file=-1 state=0
d [23/May/2007:08:18:16 -0500] cupsdReadClient: httpGets returned EOF...
D [23/May/2007:08:18:16 -0500] cupsdCloseClient: 8
d [23/May/2007:08:18:16 -0500] cupsdCloseClient: Removing fd 8 from InputSet and OutputSet...
d [23/May/2007:08:18:16 -0500] [Job 31] STATE: -connecting-to-device
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
I [23/May/2007:08:18:16 -0500] [Job 31] Connected to 192.168.0.148...
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
D [23/May/2007:08:18:16 -0500] [Job 31] Connected to 192.168.0.148:9100 (IPv4)...
d [23/May/2007:08:18:16 -0500] [Job 31] PAGE: 1 1
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=job-progress, dest=0x809b0d8(HP3550), job=0x80af0f0(31), text="Printed %d page(s).", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused job-progress event...
D [23/May/2007:08:18:16 -0500] [Job 31] backendRunLoop(print_fd=4, device_fd=5, use_bc=1)
D [23/May/2007:08:18:16 -0500] [Job 31] Read 3 bytes of print data...
d [23/May/2007:08:18:16 -0500] [Job 31] STATE: -media-empty-error
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
d [23/May/2007:08:18:16 -0500] [Job 31] STATE: -offline-error
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
I [23/May/2007:08:18:16 -0500] [Job 31] Printer is now on-line.
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
D [23/May/2007:08:18:16 -0500] [Job 31] Wrote 3 bytes of print data...
I [23/May/2007:08:18:16 -0500] [Job 31] Sent print file, 3 bytes...
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
I [23/May/2007:08:18:16 -0500] [Job 31] Print file sent, waiting for printer to finish...
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
I [23/May/2007:08:18:16 -0500] [Job 31] Ready to print.
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
d [23/May/2007:08:18:16 -0500] process_children()
D [23/May/2007:08:18:16 -0500] PID 5429 (/usr/lib/cups/backend/socket) exited with no errors.
D [23/May/2007:08:18:16 -0500] [Job 31] File 0 is complete.
d [23/May/2007:08:18:16 -0500] cupsdFinishJob: job->status is 0
d [23/May/2007:08:18:16 -0500] cupsdFinishJob: Removing fd 11 from InputSet...
d [23/May/2007:08:18:16 -0500] cupsdFinishJob: Closing status pipes [ 11 -1 ]...
d [23/May/2007:08:18:16 -0500] cupsdCancelJob: id = 31
d [23/May/2007:08:18:16 -0500] cupsdStopJob: id = 31, force = 0
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=printer-state-changed, dest=0x809b0d8(HP3550), job=(nil)(0), text="%s "%s" state changed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused printer-state-changed event...
d [23/May/2007:08:18:16 -0500] cupsdStopJob: Closing print pipes [ -1 -1 ]...
d [23/May/2007:08:18:16 -0500] cupsdStopJob: Closing back pipes [ -1 -1 ]...
d [23/May/2007:08:18:16 -0500] cupsdAddEvent(event=job-completed, dest=0x809b0d8(HP3550), job=0x80af0f0(31), text="Job completed.", ...)
D [23/May/2007:08:18:16 -0500] Discarding unused job-completed event...
d [23/May/2007:08:18:16 -0500] cupsdSaveJob(job=0x80af0f0(31)): job->attrs=0x80ae390
d [23/May/2007:08:18:16 -0500] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0
D [23/May/2007:08:18:17 -0500] Unloading job 31...
D [23/May/2007:08:18:17 -0500] cupsdNetIFUpdate: "lo" = localhost...
D [23/May/2007:08:18:17 -0500] cupsdNetIFUpdate: "eth1" = 192.168.0.147...
D [23/May/2007:08:18:17 -0500] cupsdNetIFUpdate: "lo" = localhost...
D [23/May/2007:08:18:17 -0500] cupsdNetIFUpdate: "eth1" = fe80::20c:f1ff:fe34:38a8%eth1...
d [23/May/2007:08:18:17 -0500] cupsdSendBrowseList: (120 bytes to "eth1") 20006 3 ipp://192.168.0.147:631/printers/HP3550 "" "HP3550" "Local Raw Printer" job-sheets=none,none lease-duration=300
d [23/May/2007:08:18:17 -0500] select_timeout: 31 seconds to send browse update
d [23/May/2007:08:18:17 -0500] cupsdUpdateCUPSBrowse: (120 bytes from 192.168.0.147) 20006 3 ipp://192.168.0.147:631/printers/HP3550 "" "HP3550" "Local Raw Printer" job-sheets=none,none lease-duration=300
d [23/May/2007:08:18:18 -0500] select_timeout: 30 seconds to send browse update
More information about the cups
mailing list