Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 227164 - [LSPP] '/usr/lib/cups/backend/usb failed' when trying to print to an USB printer
Summary: [LSPP] '/usr/lib/cups/backend/usb failed' when trying to print to an USB printer
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: cups
Version: 5.0
Hardware: All
OS: Linux
medium
high
Target Milestone: ---
: ---
Assignee: Tim Waugh
QA Contact: David Lawrence
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2007-02-02 20:50 UTC by Klaus Heinrich Kiwi
Modified: 2007-11-30 22:07 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2007-02-07 11:39:16 UTC


Attachments (Terms of Use)

Description Klaus Heinrich Kiwi 2007-02-02 20:50:44 UTC
Description of problem:
Can't print to a USB printer. (This is affecting lspp testing, but doesn't seems
as a showstopper)
Doesn't matter if in enforcing/permissive mode.

Version-Release number of selected component (if applicable):
[root@ct cups]# rpm -qa | egrep cups|ghost
-bash: ghost: command not found
[root@ct cups]# rpm -qa | egrep 'cups|ghost'
cups-1.2.4-11.5.el5
cups-libs-1.2.4-11.5.el5
ghostscript-8.15.2-9.1.el5

How reproducible:
always

Steps to Reproduce:
1. plug-in usb printer
2. add printer with 'lpadmin -p PsPrinter -E -v usb:/dev/usb/lp0'
3. try printing a ps file with 'lpr -P PsPrinter <ps-file>'
4. Check status with 'lpq -a' and 'lpstat -p'
  
Actual results:
[root@ct usb]# lpstat -a -p
PsPrinter accepting requests since Fri 02 Feb 2007 05:57:07 PM CST
printer PsPrinter disabled since Fri 02 Feb 2007 05:57:07 PM CST -
        /usr/lib/cups/backend/usb failed
[root@ct usb]#

Expected results:
no error. Correctly printing.

Additional info:
/var/log/cups/error_log output when trying to print a job (debug2 loglevel):
----------------------------------------------------------
d [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient(lis=0x88e87b8) 3 Clients = 0
I [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: peer's pid=14476, uid=0,
gid=0, auid=502
I [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: client
context=abat_u:abat_r:abat_t:SystemLow-SystemHigh
D [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: 12 from localhost (Domain)
d [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: 12 connected to server on
localhost:0
d [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: Adding fd 12 to InputSet...
d [02/Feb/2007:18:42:46 -0600] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=-1 state=0
D [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 POST / HTTP/1.1
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: uri = "/"...
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL
Limit 0
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location /admin/conf Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location /admin Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location / Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: best = /
d [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: con->uri="/", con->best=0x88e8990(/)
d [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: Authorization=""
D [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: No authentication data provided.
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x88e8990(/)
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:18:42:46 -0600] POST /
d [02/Feb/2007:18:42:46 -0600] CONTENT_TYPE = application/ipp
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=351, con->file=-1
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=343, file=-1 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=343, con->file=-1
d [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest(0x8929c18[12]):
operation_id = 4002
D [02/Feb/2007:18:42:46 -0600] CUPS-Get-Printers
d [02/Feb/2007:18:42:46 -0600] get_printers(0x8929c18[12], 0)
d [02/Feb/2007:18:42:46 -0600] cupsdFindPolicyOp(p=0x88e8b58,
op=4002(CUPS-Get-Printers))
d [02/Feb/2007:18:42:46 -0600] cupsdFindPolicyOp: Found wildcard match...
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x88e9da8((null))
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: op=0(unknown-0000)
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:18:42:46 -0600] add_printer_state_reasons(0x8929c18[12],
0x88e2bf0[PsPrinter])
d [02/Feb/2007:18:42:46 -0600] copy_attrs(to=0x8912a18, from=0x88f3b98,
ra=0x892f298, group=0, quickcopy=0)
d [02/Feb/2007:18:42:46 -0600] copy_attribute(0x8912a18,
0x88f3ca8[printer-name,4,42])
d [02/Feb/2007:18:42:46 -0600] copy_attribute(0x8912a18,
0x88f3d68[printer-info,4,41])
d [02/Feb/2007:18:42:46 -0600] copy_attribute(0x8912a18,
0x88f3ef0[job-sheets-default,4,42])
d [02/Feb/2007:18:42:46 -0600] copy_attribute(0x8912a18,
0x88f4000[printer-make-and-model,4,41])
d [02/Feb/2007:18:42:46 -0600] copy_attrs(to=0x8912a18, from=0x88e35b0,
ra=0x892f298, group=0, quickcopy=-2147483648)
D [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest: 12 status_code=0
(successful-ok)
d [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest: Adding fd 12 to OutputSet...
d [02/Feb/2007:18:42:46 -0600] select_timeout: 301 seconds to timeout a client
connection
d [02/Feb/2007:18:42:46 -0600] cupsdWriteClient: 12 bytes < 0
d [02/Feb/2007:18:42:46 -0600] cupsdWriteClient: Removing fd 12 from OutputSet...
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=-1 state=0
D [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 POST / HTTP/1.1
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: uri = "/"...
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL
Limit 0
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location /admin/conf Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location /admin Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location / Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: best = /
d [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: con->uri="/", con->best=0x88e8990(/)
d [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: Authorization=""
D [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: No authentication data provided.
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x88e8990(/)
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:18:42:46 -0600] POST /
d [02/Feb/2007:18:42:46 -0600] CONTENT_TYPE = application/ipp
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=351, con->file=-1
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=343, file=-1 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=343, con->file=-1
d [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest(0x8929c18[12]):
operation_id = 4005
D [02/Feb/2007:18:42:46 -0600] CUPS-Get-Classes
d [02/Feb/2007:18:42:46 -0600] get_printers(0x8929c18[12], 1)
d [02/Feb/2007:18:42:46 -0600] cupsdFindPolicyOp(p=0x88e8b58,
op=4005(CUPS-Get-Classes))
d [02/Feb/2007:18:42:46 -0600] cupsdFindPolicyOp: Found wildcard match...
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x88e9da8((null))
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: op=0(unknown-0000)
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
D [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest: 12 status_code=0
(successful-ok)
d [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest: Adding fd 12 to OutputSet...
d [02/Feb/2007:18:42:46 -0600] select_timeout: 301 seconds to timeout a client
connection
d [02/Feb/2007:18:42:46 -0600] cupsdWriteClient: 12 bytes < 0
d [02/Feb/2007:18:42:46 -0600] cupsdWriteClient: Removing fd 12 from OutputSet...
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=-1 state=0
D [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 POST / HTTP/1.1
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: uri = "/"...
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL
Limit 0
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location /admin/conf Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location /admin Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location / Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: best = /
d [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: con->uri="/", con->best=0x88e8990(/)
d [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: Authorization=""
D [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: No authentication data provided.
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x88e8990(/)
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:18:42:46 -0600] POST /
d [02/Feb/2007:18:42:46 -0600] CONTENT_TYPE = application/ipp
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=75, con->file=-1
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=67, file=-1 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=67, con->file=-1
d [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest(0x8929c18[12]):
operation_id = 4001
D [02/Feb/2007:18:42:46 -0600] CUPS-Get-Default
d [02/Feb/2007:18:42:46 -0600] get_default(0x8929c18[12])
d [02/Feb/2007:18:42:46 -0600] cupsdFindPolicyOp(p=0x88e8b58,
op=4001(CUPS-Get-Default))
d [02/Feb/2007:18:42:46 -0600] cupsdFindPolicyOp: Found wildcard match...
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x88e9da8((null))
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: op=0(unknown-0000)
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
D [02/Feb/2007:18:42:46 -0600] CUPS-Get-Default client-error-not-found: No
default printer
D [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest: 12 status_code=406
(client-error-not-found)
d [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest: Adding fd 12 to OutputSet...
d [02/Feb/2007:18:42:46 -0600] select_timeout: 301 seconds to timeout a client
connection
d [02/Feb/2007:18:42:46 -0600] cupsdWriteClient: 12 bytes < 0
d [02/Feb/2007:18:42:46 -0600] cupsdWriteClient: Removing fd 12 from OutputSet...
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=-1 state=0
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: httpGets returned EOF...
D [02/Feb/2007:18:42:46 -0600] cupsdCloseClient: 12
d [02/Feb/2007:18:42:46 -0600] cupsdCloseClient: Removing fd 12 from InputSet
and OutputSet...
d [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient(lis=0x88e87b8) 3 Clients = 0
I [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: peer's pid=14476, uid=0,
gid=0, auid=502
I [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: client
context=abat_u:abat_r:abat_t:SystemLow-SystemHigh
D [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: 12 from localhost (Domain)
d [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: 12 connected to server on
localhost:0
d [02/Feb/2007:18:42:46 -0600] cupsdAcceptClient: Adding fd 12 to InputSet...
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=-1 state=0
D [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 POST /printers/PsPrinter HTTP/1.1
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: uri = "/printers/PsPrinter"...
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL
Limit 0
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location /admin/conf Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location /admin Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: Location / Limit 7f
d [02/Feb/2007:18:42:46 -0600] cupsdFindBest: best = /
d [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: con->uri="/printers/PsPrinter",
con->best=0x88e8990(/)
d [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: Authorization=""
D [02/Feb/2007:18:42:46 -0600] cupsdAuthorize: No authentication data provided.
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized:
con->uri="/printers/PsPrinter", con->best=0x88e8990(/)
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:18:42:46 -0600] POST /printers/PsPrinter
d [02/Feb/2007:18:42:46 -0600] CONTENT_TYPE = application/ipp
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=364246, con->file=-1
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=245, file=-1 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=364238, con->file=-1
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 REQUEST
/var/spool/cups/00000002=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: /var/spool/cups/00000002 set to
system_u:object_r:print_spool_t:SystemLow
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] select_timeout: 301 seconds to timeout a client
connection
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=347865, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=331737, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=331225, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=315097, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=298969, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=298457, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=282329, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=266201, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=265689, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=249561, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=233433, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=232921, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=216793, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=200665, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=200153, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=184025, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=167897, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=167385, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=151257, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=135129, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=134617, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=118489, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=102361, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=101849, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=85721, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=69593, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=69081, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=52953, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=36825, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=36313, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=20185, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 16128 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=4057, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 512 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=15 state=6
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=3545, con->file=15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 writing 3545 bytes to 15
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12 Closing data file 15,
size=363993.
d [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest(0x8929c18[12]):
operation_id = 0002
D [02/Feb/2007:18:42:46 -0600] Print-Job ipp://localhost/printers/PsPrinter
d [02/Feb/2007:18:42:46 -0600] print_job(0x8929c18[12],
ipp://localhost/printers/PsPrinter)
D [02/Feb/2007:18:42:46 -0600] print_job: auto-typing file...
D [02/Feb/2007:18:42:46 -0600] print_job: request file type is
application/unrenderedps.
d [02/Feb/2007:18:42:46 -0600] add_job(0x8929c18[12],
ipp://localhost/printers/PsPrinter)
d [02/Feb/2007:18:42:46 -0600] cupsdFindPolicyOp(p=0x88e8b58, op=2(Print-Job))
d [02/Feb/2007:18:42:46 -0600] cupsdFindPolicyOp: Found wildcard match...
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized:
con->uri="/printers/PsPrinter", con->best=0x88e9da8((null))
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: op=0(unknown-0000)
d [02/Feb/2007:18:42:46 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:18:42:46 -0600] check_quotas(0x8929c18[12], 0x88e2bf0[PsPrinter])
D [02/Feb/2007:18:42:46 -0600] add_job: Attempting an access check on printer
device /dev/usb/lp0
D [02/Feb/2007:18:42:46 -0600] add_job: printer context
system_u:object_r:printer_device_t:SystemLow client context
abat_u:abat_r:abat_t:SystemLow-SystemHigh
D [02/Feb/2007:18:42:46 -0600] add_job: requesting-user-name="root"
I [02/Feb/2007:18:42:46 -0600] Classification="mls", ClassifyOverride=0
I [02/Feb/2007:18:42:46 -0600] Adding start banner page "mls" to job 4.
d [02/Feb/2007:18:42:46 -0600] copy_banner(0x8929c18[12], 0x8934d28[4], mls)
d [02/Feb/2007:18:42:46 -0600] add_file(con=0x8929c18[12], job=4,
filetype=application/unrenderedps, compression=0)
d [02/Feb/2007:18:42:46 -0600] copy_banner: /var/spool/cups/d00004-001 set to
system_u:object_r:print_spool_t:SystemLow
d [02/Feb/2007:18:42:46 -0600] add_job_state_reasons(0x8929c18[12], 4)
d [02/Feb/2007:18:42:46 -0600] cupsdAddEvent(event=job-created,
dest=0x88e2bf0(PsPrinter), job=0x8934d28(4), text="Job created.", ...)
D [02/Feb/2007:18:42:46 -0600] Discarding unused job-created event...
d [02/Feb/2007:18:42:46 -0600] add_file(con=0x8929c18[12], job=4,
filetype=application/unrenderedps, compression=0)
I [02/Feb/2007:18:42:46 -0600] Adding end banner page "mls" to job 4.
d [02/Feb/2007:18:42:46 -0600] copy_banner(0x8929c18[12], 0x8934d28[4], mls)
d [02/Feb/2007:18:42:46 -0600] add_file(con=0x8929c18[12], job=4,
filetype=application/unrenderedps, compression=0)
d [02/Feb/2007:18:42:46 -0600] copy_banner: /var/spool/cups/d00004-003 set to
system_u:object_r:print_spool_t:SystemLow
I [02/Feb/2007:18:42:46 -0600] Job 4 queued on "PsPrinter" by "root".
D [02/Feb/2007:18:42:46 -0600] Job 4 hold_until = 0
d [02/Feb/2007:18:42:46 -0600] cupsdSaveJob(job=0x8934d28(4)): job->attrs=0x8912a18
d [02/Feb/2007:18:42:46 -0600] cupsdSaveJob(job=0x8934d28): new spool file
context=system_u:object_r:print_spool_t:SystemLow
d [02/Feb/2007:18:42:46 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:18:42:46 -0600] cupsdCheckJobs: Job 4: state_value=3, loaded=yes
D [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest: 12 status_code=0
(successful-ok)
d [02/Feb/2007:18:42:46 -0600] cupsdProcessIPPRequest: Adding fd 12 to OutputSet...
d [02/Feb/2007:18:42:46 -0600] cupsdWriteClient: 12 bytes < 0
d [02/Feb/2007:18:42:46 -0600] cupsdWriteClient: Removing fd 12 from OutputSet...
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: 12, used=0, file=-1 state=0
d [02/Feb/2007:18:42:46 -0600] cupsdReadClient: httpGets returned EOF...
D [02/Feb/2007:18:42:46 -0600] cupsdCloseClient: 12
d [02/Feb/2007:18:42:46 -0600] cupsdCloseClient: Removing fd 12 from InputSet
and OutputSet...
d [02/Feb/2007:18:42:47 -0600] select_timeout: 11 seconds to process active jobs
d [02/Feb/2007:18:42:58 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:18:42:58 -0600] cupsdCheckJobs: Job 4: state_value=3, loaded=yes
d [02/Feb/2007:18:42:58 -0600] select_timeout: 11 seconds to process active jobs
d [02/Feb/2007:18:43:09 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:18:43:09 -0600] cupsdCheckJobs: Job 4: state_value=3, loaded=yes
d [02/Feb/2007:18:43:09 -0600] select_timeout: 11 seconds to process active jobs
d [02/Feb/2007:18:43:20 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:18:43:20 -0600] cupsdCheckJobs: Job 4: state_value=3, loaded=yes
d [02/Feb/2007:18:43:20 -0600] stringpool: 347 strings, 7528 allocated, 7272
total bytes
d [02/Feb/2007:18:43:20 -0600] select_timeout: 11 seconds to process active jobs
d [02/Feb/2007:18:43:31 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:18:43:31 -0600] cupsdCheckJobs: Job 4: state_value=3, loaded=yes
d [02/Feb/2007:18:43:31 -0600] select_timeout: 11 seconds to process active jobs
d [02/Feb/2007:18:43:42 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:18:43:42 -0600] cupsdCheckJobs: Job 4: state_value=3, loaded=yes
d [02/Feb/2007:18:43:42 -0600] select_timeout: 11 seconds to process active jobs

<last messages keep looping while job is not canceled>

Comment 1 Klaus Heinrich Kiwi 2007-02-02 21:40:51 UTC
Some other info:

* Trying to print to /dev/usb/lp0 in a similar debian system also fails, but
printing to usb://Lexmark/T630 succeeds

* Trying to print to usb://Lexmark/T630 in RHEL5 fails with 'Printer not
connected; will retry in 30 seconds...' error_log while trying to add a job follows:
--------------------------------
d [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient(lis=0x83717b8) 3 Clients = 0
I [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: peer's pid=2476, uid=0, gid=0,
auid=502
I [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: client
context=abat_u:abat_r:abat_t:SystemLow-SystemHigh
D [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: 6 from localhost (Domain)
d [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: 6 connected to server on
localhost:0
d [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: Adding fd 6 to InputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0
d [02/Feb/2007:19:33:12 -0600] stringpool: 329 strings, 6904 allocated, 6912
total bytes
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6, used=0, file=-1 state=0
D [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6 POST / HTTP/1.1
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: uri = "/"...
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL
Limit 0
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location /admin/conf Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location /admin Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location / Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: best = /
d [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: con->uri="/", con->best=0x8371990(/)
d [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: Authorization=""
D [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: No authentication data provided.
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x8371990(/)
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:19:33:12 -0600] POST /
d [02/Feb/2007:19:33:12 -0600] CONTENT_TYPE = application/ipp
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=351, con->file=-1
d [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest(0x8398f38[6]):
operation_id = 4002
D [02/Feb/2007:19:33:12 -0600] CUPS-Get-Printers
d [02/Feb/2007:19:33:12 -0600] get_printers(0x8398f38[6], 0)
d [02/Feb/2007:19:33:12 -0600] cupsdFindPolicyOp(p=0x8371b58,
op=4002(CUPS-Get-Printers))
d [02/Feb/2007:19:33:12 -0600] cupsdFindPolicyOp: Found wildcard match...
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x8372da8((null))
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: op=0(unknown-0000)
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:19:33:12 -0600] add_printer_state_reasons(0x8398f38[6],
0x836bbf0[BRHRTP3F])
d [02/Feb/2007:19:33:12 -0600] copy_attrs(to=0x839c8c8, from=0x837cc00,
ra=0x839cbb0, group=0, quickcopy=0)
d [02/Feb/2007:19:33:12 -0600] copy_attribute(0x839c8c8,
0x837cd10[printer-name,4,42])
d [02/Feb/2007:19:33:12 -0600] copy_attribute(0x839c8c8,
0x837cdb0[printer-info,4,41])
d [02/Feb/2007:19:33:12 -0600] copy_attribute(0x839c8c8,
0x837cf38[job-sheets-default,4,42])
d [02/Feb/2007:19:33:12 -0600] copy_attribute(0x839c8c8,
0x837d040[printer-make-and-model,4,41])
d [02/Feb/2007:19:33:12 -0600] copy_attrs(to=0x839c8c8, from=0x836c630,
ra=0x839cbb0, group=0, quickcopy=-2147483648)
d [02/Feb/2007:19:33:12 -0600] add_printer_state_reasons(0x8398f38[6],
0x837d7d0[PsPrinter])
d [02/Feb/2007:19:33:12 -0600] copy_attrs(to=0x839c8c8, from=0x837dd40,
ra=0x839cbb0, group=0, quickcopy=0)
d [02/Feb/2007:19:33:12 -0600] copy_attribute(0x839c8c8,
0x837ded0[printer-name,4,42])
d [02/Feb/2007:19:33:12 -0600] copy_attribute(0x839c8c8,
0x837df20[printer-info,4,41])
d [02/Feb/2007:19:33:12 -0600] copy_attribute(0x839c8c8,
0x837dfe8[job-sheets-default,4,42])
d [02/Feb/2007:19:33:12 -0600] copy_attribute(0x839c8c8,
0x837e0c0[printer-make-and-model,4,41])
d [02/Feb/2007:19:33:12 -0600] copy_attrs(to=0x839c8c8, from=0x836c630,
ra=0x839cbb0, group=0, quickcopy=-2147483648)
D [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest: 6 status_code=0
(successful-ok)
d [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest: Adding fd 6 to OutputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdWriteClient: 6 bytes < 0
d [02/Feb/2007:19:33:12 -0600] cupsdWriteClient: Removing fd 6 from OutputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6, used=0, file=-1 state=0
D [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6 POST / HTTP/1.1
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: uri = "/"...
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL
Limit 0
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location /admin/conf Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location /admin Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location / Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: best = /
d [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: con->uri="/", con->best=0x8371990(/)
d [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: Authorization=""
D [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: No authentication data provided.
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x8371990(/)
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:19:33:12 -0600] POST /
d [02/Feb/2007:19:33:12 -0600] CONTENT_TYPE = application/ipp
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=351, con->file=-1
d [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest(0x8398f38[6]):
operation_id = 4005
D [02/Feb/2007:19:33:12 -0600] CUPS-Get-Classes
d [02/Feb/2007:19:33:12 -0600] get_printers(0x8398f38[6], 1)
d [02/Feb/2007:19:33:12 -0600] cupsdFindPolicyOp(p=0x8371b58,
op=4005(CUPS-Get-Classes))
d [02/Feb/2007:19:33:12 -0600] cupsdFindPolicyOp: Found wildcard match...
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x8372da8((null))
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: op=0(unknown-0000)
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
D [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest: 6 status_code=0
(successful-ok)
d [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest: Adding fd 6 to OutputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdWriteClient: 6 bytes < 0
d [02/Feb/2007:19:33:12 -0600] cupsdWriteClient: Removing fd 6 from OutputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6, used=0, file=-1 state=0
D [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6 POST / HTTP/1.1
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: uri = "/"...
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL
Limit 0
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location /admin/conf Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location /admin Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location / Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: best = /
d [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: con->uri="/", con->best=0x8371990(/)
d [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: Authorization=""
D [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: No authentication data provided.
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x8371990(/)
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:19:33:12 -0600] POST /
d [02/Feb/2007:19:33:12 -0600] CONTENT_TYPE = application/ipp
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=75, con->file=-1
d [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest(0x8398f38[6]):
operation_id = 4001
D [02/Feb/2007:19:33:12 -0600] CUPS-Get-Default
d [02/Feb/2007:19:33:12 -0600] get_default(0x8398f38[6])
d [02/Feb/2007:19:33:12 -0600] cupsdFindPolicyOp(p=0x8371b58,
op=4001(CUPS-Get-Default))
d [02/Feb/2007:19:33:12 -0600] cupsdFindPolicyOp: Found wildcard match...
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: con->uri="/",
con->best=0x8372da8((null))
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: op=0(unknown-0000)
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
D [02/Feb/2007:19:33:12 -0600] CUPS-Get-Default client-error-not-found: No
default printer
D [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest: 6 status_code=406
(client-error-not-found)
d [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest: Adding fd 6 to OutputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdWriteClient: 6 bytes < 0
d [02/Feb/2007:19:33:12 -0600] cupsdWriteClient: Removing fd 6 from OutputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient(lis=0x83717b8) 3 Clients = 1
I [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: peer's pid=2476, uid=0, gid=0,
auid=502
I [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: client
context=abat_u:abat_r:abat_t:SystemLow-SystemHigh
D [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: 8 from localhost (Domain)
d [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: 8 connected to server on
localhost:0
d [02/Feb/2007:19:33:12 -0600] cupsdAcceptClient: Adding fd 8 to InputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 6, used=0, file=-1 state=0
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: httpGets returned EOF...
D [02/Feb/2007:19:33:12 -0600] cupsdCloseClient: 6
d [02/Feb/2007:19:33:12 -0600] cupsdCloseClient: Removing fd 6 from InputSet and
OutputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=-1 state=0
D [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 POST /printers/PsPrinter HTTP/1.1
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: uri = "/printers/PsPrinter"...
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL
Limit 0
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location /admin/conf Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location /admin Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: Location / Limit 7f
d [02/Feb/2007:19:33:12 -0600] cupsdFindBest: best = /
d [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: con->uri="/printers/PsPrinter",
con->best=0x8371990(/)
d [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: Authorization=""
D [02/Feb/2007:19:33:12 -0600] cupsdAuthorize: No authentication data provided.
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized:
con->uri="/printers/PsPrinter", con->best=0x8371990(/)
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:19:33:12 -0600] POST /printers/PsPrinter
d [02/Feb/2007:19:33:12 -0600] CONTENT_TYPE = application/ipp
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=364246, con->file=-1
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 REQUEST /var/spool/cups/00000000=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: /var/spool/cups/00000000 set to
system_u:object_r:print_spool_t:SystemLow
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=331225, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=298457, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=265689, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=232921, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=200153, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=167385, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=134617, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=101849, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=69081, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=36313, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 32768 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=6 state=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8
con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=3545, con->file=6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 writing 3545 bytes to 6
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8 Closing data file 6, size=363993.
d [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest(0x839f178[8]):
operation_id = 0002
D [02/Feb/2007:19:33:12 -0600] Print-Job ipp://localhost/printers/PsPrinter
d [02/Feb/2007:19:33:12 -0600] print_job(0x839f178[8],
ipp://localhost/printers/PsPrinter)
D [02/Feb/2007:19:33:12 -0600] print_job: auto-typing file...
D [02/Feb/2007:19:33:12 -0600] print_job: request file type is
application/unrenderedps.
d [02/Feb/2007:19:33:12 -0600] add_job(0x839f178[8],
ipp://localhost/printers/PsPrinter)
d [02/Feb/2007:19:33:12 -0600] cupsdFindPolicyOp(p=0x8371b58, op=2(Print-Job))
d [02/Feb/2007:19:33:12 -0600] cupsdFindPolicyOp: Found wildcard match...
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized:
con->uri="/printers/PsPrinter", con->best=0x8372da8((null))
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: level=AUTH_ANON,
type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: op=0(unknown-0000)
d [02/Feb/2007:19:33:12 -0600] cupsdIsAuthorized: auth=AUTH_ALLOW...
d [02/Feb/2007:19:33:12 -0600] check_quotas(0x839f178[8], 0x837d7d0[PsPrinter])
D [02/Feb/2007:19:33:12 -0600] add_job: requesting-user-name="root"
I [02/Feb/2007:19:33:12 -0600] Classification="mls", ClassifyOverride=0
I [02/Feb/2007:19:33:12 -0600] Adding start banner page "mls" to job 6.
d [02/Feb/2007:19:33:12 -0600] copy_banner(0x839f178[8], 0x839efd8[6], mls)
d [02/Feb/2007:19:33:12 -0600] add_file(con=0x839f178[8], job=6,
filetype=application/unrenderedps, compression=0)
d [02/Feb/2007:19:33:12 -0600] copy_banner: /var/spool/cups/d00006-001 set to
system_u:object_r:print_spool_t:SystemLow
d [02/Feb/2007:19:33:12 -0600] add_job_state_reasons(0x839f178[8], 6)
d [02/Feb/2007:19:33:12 -0600] cupsdAddEvent(event=job-created,
dest=0x837d7d0(PsPrinter), job=0x839efd8(6), text="Job created.", ...)
D [02/Feb/2007:19:33:12 -0600] Discarding unused job-created event...
d [02/Feb/2007:19:33:12 -0600] add_file(con=0x839f178[8], job=6,
filetype=application/unrenderedps, compression=0)
I [02/Feb/2007:19:33:12 -0600] Adding end banner page "mls" to job 6.
d [02/Feb/2007:19:33:12 -0600] copy_banner(0x839f178[8], 0x839efd8[6], mls)
d [02/Feb/2007:19:33:12 -0600] add_file(con=0x839f178[8], job=6,
filetype=application/unrenderedps, compression=0)
d [02/Feb/2007:19:33:12 -0600] copy_banner: /var/spool/cups/d00006-003 set to
system_u:object_r:print_spool_t:SystemLow
I [02/Feb/2007:19:33:12 -0600] Job 6 queued on "PsPrinter" by "root".
D [02/Feb/2007:19:33:12 -0600] Job 6 hold_until = 0
d [02/Feb/2007:19:33:12 -0600] cupsdSaveJob(job=0x839efd8(6)): job->attrs=0x839c818
d [02/Feb/2007:19:33:12 -0600] cupsdSaveJob(job=0x839efd8): new spool file
context=system_u:object_r:print_spool_t:SystemLow
d [02/Feb/2007:19:33:12 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:19:33:12 -0600] cupsdCheckJobs: Job 6: state_value=3, loaded=yes
d [02/Feb/2007:19:33:12 -0600] start_job: id = 6, file = 0/3
D [02/Feb/2007:19:33:12 -0600] [Job 6] Sending job to queue tagged as raw...
d [02/Feb/2007:19:33:12 -0600] cupsdAddEvent(event=printer-state-changed,
dest=0x837d7d0(PsPrinter), job=(nil)(0), text="%s "%s" state changed.", ...)
D [02/Feb/2007:19:33:12 -0600] Discarding unused printer-state-changed event...
D [02/Feb/2007:19:33:12 -0600] job-sheets=mls,mls
D [02/Feb/2007:19:33:12 -0600] banner_page = 1
D [02/Feb/2007:19:33:12 -0600] [Job 6] argv[0]="PsPrinter"
D [02/Feb/2007:19:33:12 -0600] [Job 6] argv[1]="6"
D [02/Feb/2007:19:33:12 -0600] [Job 6] argv[2]="root"
D [02/Feb/2007:19:33:12 -0600] [Job 6] argv[3]="SystemLow_ok.ps"
D [02/Feb/2007:19:33:12 -0600] [Job 6] argv[4]="1"
D [02/Feb/2007:19:33:12 -0600] [Job 6]
argv[5]="security-context=abat_u:abat_r:abat_t:SystemLow-SystemHigh
job-uuid=urn:uuid:51fdf0b2-32ba-32ec-41c1-548a56392ad5"
D [02/Feb/2007:19:33:12 -0600] [Job 6] argv[6]="/var/spool/cups/d00006-001"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [02/Feb/2007:19:33:12 -0600] [Job 6]
envp[2]="CUPS_DOCROOT=/usr/share/doc/cups-1.2.4"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [02/Feb/2007:19:33:12 -0600] [Job 6]
envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[9]="SERVER_ADMIN=root@ct"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[10]="SOFTWARE=CUPS/1.2.4"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[11]="TMPDIR=/var/spool/cups/tmp"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[12]="USER=root"
D [02/Feb/2007:19:33:12 -0600] [Job 6]
envp[13]="CUPS_SERVER=/var/run/cups/cups.sock"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[14]="CUPS_ENCRYPTION=IfRequested"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[15]="CHARSET=utf-8"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[16]="LANG=en_US"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[17]="PPD=/etc/cups/ppd/PsPrinter.ppd"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[18]="RIP_MAX_CACHE=8m"
D [02/Feb/2007:19:33:12 -0600] [Job 6]
envp[19]="CONTENT_TYPE=application/unrenderedps"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[20]="DEVICE_URI=usb://Lexmark/T630"
D [02/Feb/2007:19:33:12 -0600] [Job 6] envp[21]="PRINTER=PsPrinter"
d [02/Feb/2007:19:33:12 -0600] start_job: status_pipes = [ 10 11 ]
d [02/Feb/2007:19:33:12 -0600] start_job: backend="/usr/lib/cups/backend/usb"
d [02/Feb/2007:19:33:12 -0600] start_job: filterfds[0] = [ -1 -1 ]
d [02/Feb/2007:19:33:12 -0600] cupsdStartProcess("/usr/lib/cups/backend/usb",
0x837c5e0, 0xbfe4efa8, -1, -1, 11)
I [02/Feb/2007:19:33:12 -0600] Started backend /usr/lib/cups/backend/usb (PID
2477) for job 6.
d [02/Feb/2007:19:33:12 -0600] start_job: Closing filter pipes for slot 0 [ -1
-1 ]...
d [02/Feb/2007:19:33:12 -0600] start_job: Adding fd 10 to InputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdAddEvent(event=job-state,
dest=0x837d7d0(PsPrinter), job=0x839efd8(6), text="Job #%d started.", ...)
D [02/Feb/2007:19:33:12 -0600] Discarding unused job-state event...
D [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest: 8 status_code=0
(successful-ok)
d [02/Feb/2007:19:33:12 -0600] cupsdProcessIPPRequest: Adding fd 8 to OutputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdWriteClient: 8 bytes < 0
d [02/Feb/2007:19:33:12 -0600] cupsdWriteClient: Removing fd 8 from OutputSet...
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: 8, used=0, file=-1 state=0
d [02/Feb/2007:19:33:12 -0600] cupsdReadClient: httpGets returned EOF...
D [02/Feb/2007:19:33:12 -0600] cupsdCloseClient: 8
d [02/Feb/2007:19:33:12 -0600] cupsdCloseClient: Removing fd 8 from InputSet and
OutputSet...
d [02/Feb/2007:19:33:12 -0600] [Job 6] STATE: +connecting-to-device
I [02/Feb/2007:19:33:12 -0600] [Job 6] Printer not connected; will retry in 30
seconds...
d [02/Feb/2007:19:33:12 -0600] cupsdAddEvent(event=printer-state-changed,
dest=0x837d7d0(PsPrinter), job=(nil)(0), text="Printer "%s" state changed.", ...)
D [02/Feb/2007:19:33:12 -0600] Discarding unused printer-state-changed event...
d [02/Feb/2007:19:33:13 -0600] select_timeout: 11 seconds to process active jobs
d [02/Feb/2007:19:33:24 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:19:33:24 -0600] cupsdCheckJobs: Job 6: state_value=5, loaded=yes
d [02/Feb/2007:19:33:24 -0600] select_timeout: 11 seconds to process active jobs
d [02/Feb/2007:19:33:35 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:19:33:35 -0600] cupsdCheckJobs: Job 6: state_value=5, loaded=yes
d [02/Feb/2007:19:33:35 -0600] select_timeout: 11 seconds to process active jobs
I [02/Feb/2007:19:33:42 -0600] [Job 6] Printer not connected; will retry in 30
seconds...
d [02/Feb/2007:19:33:43 -0600] select_timeout: 11 seconds to process active jobs
d [02/Feb/2007:19:33:54 -0600] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
d [02/Feb/2007:19:33:54 -0600] cupsdCheckJobs: Job 6: state_value=5, loaded=yes
d [02/Feb/2007:19:33:54 -0600] select_timeout: 11 seconds to process active jobs
----------------------


* Don't see any files/dirs inside /proc/bus/usb (dir is empty)


* Don't see any AVC denials while inserting the usb printer, nor when adding a
printing job


* If udev is put in debug mode, some operations appear to fail (can't say if
it's expected/normal behavior):
Feb  2 19:20:06 ct udevd-event[2299]: udev_db_get_device: no db file to read
/dev/.udev/db/devices@pci0000:00@0000:00:1d.2@usb3@3-2@usbdev3.5_ep00: No such
file or directory
Feb  2 19:20:06 ct udevd-event[2309]: udev_db_get_device: no db file to read
/dev/.udev/db/devices@pci0000:00@0000:00:1d.2@usb3@3-2@3-2:1.0@usbdev3.5_ep01:
No such file or directory
Feb  2 19:20:06 ct udevd-event[2310]: udev_db_get_device: no db file to read
/dev/.udev/db/devices@pci0000:00@0000:00:1d.2@usb3@3-2@3-2:1.0@usbdev3.5_ep81:
No such file or directory
Feb  2 19:20:06 ct udevd-event[2308]: udev_db_get_device: no db file to read
/dev/.udev/db/class@usb@lp0: No such file or directory



Comment 2 Matt Anderson 2007-02-02 22:07:56 UTC
Try adding a PPD file for the printer.  Either create the printer like this:
`lpadmin -p PsPrinter -E -v usb:/dev/usb/lp0 -m postscript.ppd.gz`

or you could look online to see if you can find a PPD specific for your printer
http://openprinting.org/printer_list.cgi

Once you have a PPD file you don't always have to delete and readd the printer,
you can copy the file to /etc/cups/ppd with the name of your printer (ie.
/etc/cups/ppd/PsPrinter.ppd )

Comment 3 Linda Knippers 2007-02-02 22:27:06 UTC
This doesn't seem related to the MLS policy.  Can you get it to work without
classification set to mls in the /etc/cups/cupsd.conf file?  Or on a stock
RHEL5 (not MLS) installation?  How about on RHEL4? 

 

Comment 4 Klaus Heinrich Kiwi 2007-02-05 21:11:36 UTC
(In reply to comment #2)
> Try adding a PPD file for the printer.  Either create the printer like this:
> `lpadmin -p PsPrinter -E -v usb:/dev/usb/lp0 -m postscript.ppd.gz`

Took your suggestion and re-added the printer with the postscript.ppd.gz PPD and
 tried some combinations trying to match the correct uri. Still, Besides the
network printer, all others fails to print (tried with a PS file):

[root@ct cups]# lpstat -t
scheduler is running
no system default destination
device for BRHRTP3F: socket://9.18.227.13:9100
device for PsPrinter: usb://Lexmark/T630
device for PsPrinter2: usb:/dev/usb/lp0
device for PsPrinter3: usb://dev/usb/lp0
device for PsPrinter4: usb:/Lexmark/T630
BRHRTP3F accepting requests since Wed 31 Jan 2007 10:44:19 AM CST
PsPrinter accepting requests since Mon 05 Feb 2007 06:38:38 PM CST
PsPrinter2 accepting requests since Mon 05 Feb 2007 06:44:31 PM CST
PsPrinter3 accepting requests since Mon 05 Feb 2007 06:53:22 PM CST
PsPrinter4 accepting requests since Mon 05 Feb 2007 06:53:56 PM CST
printer BRHRTP3F is idle.  enabled since Wed 31 Jan 2007 10:44:19 AM CST
printer PsPrinter is idle.  enabled since Mon 05 Feb 2007 06:38:38 PM CST
        Printer not connected; will retry in 30 seconds...
printer PsPrinter2 now printing PsPrinter2-7.  enabled since Mon 05 Feb 2007
06:44:31 PM CST
        Unable to open USB device "usb:/dev/usb/lp0": Permission denied
printer PsPrinter3 now printing PsPrinter3-8.  enabled since Mon 05 Feb 2007
06:53:22 PM CST
        Printer not connected; will retry in 30 seconds...
printer PsPrinter4 now printing PsPrinter4-9.  enabled since Mon 05 Feb 2007
06:53:56 PM CST
        Printer not connected; will retry in 30 seconds...
PsPrinter2-7            root            380928   Mon 05 Feb 2007 06:44:31 PM CST
PsPrinter3-8            root            380928   Mon 05 Feb 2007 06:53:22 PM CST
PsPrinter4-9            root            380928   Mon 05 Feb 2007 06:53:56 PM CST
[root@ct cups]#

No AVCs either..

> or you could look online to see if you can find a PPD specific for your printer
> http://openprinting.org/printer_list.cgi
> 
> Once you have a PPD file you don't always have to delete and readd the printer,
> you can copy the file to /etc/cups/ppd with the name of your printer (ie.
> /etc/cups/ppd/PsPrinter.ppd )

Couldn't find a ppd for the Lexmark T630 I'm using, but as noted above, I can
print for the same printer in a Debian-based system without any ppd (raw).


Comment 5 Klaus Heinrich Kiwi 2007-02-06 17:20:15 UTC
So much effort for such a simple configuration mistake (Redhat, please mark this
as NOTABUG)

 Currently, the lspp ks script adds 'User lp' and 'Group sys' to the cupsd.conf
file. I don't know exactly why, but that way cups ends up running all external
files (including the backends) as id=lp, group(s)=nobody.

A simple change to 'Group lp' in the config solved the issue.

But I'm curious. Even if I specify 'Group sys' in the configuration, why does
cups run external programs with 'nobody' [e|s]gid? See the audit log:

type=SYSCALL msg=audit(1170795505.594:528): arch=40000003 syscall=5 success=no
exit=-13 a0=bfd0cf90 a1=8082 a2=0 a3=8082 items=1 ppid=1891 pid=2207
auid=4294967295 uid=4 gid=99 euid=4 suid=4 fsuid=4 egid=99 sgid=99 fsgid=99
tty=(none) comm="usb" exe="/usr/lib/cups/backend/usb"
subj=system_u:system_r:cupsd_t:s15:c0.c1023 key=(null)
type=CWD msg=audit(1170795505.594:528):  cwd="/"
type=PATH msg=audit(1170795505.594:528): item=0 name="/dev/usb/lp0" inode=7660
dev=00:10 mode=020660 ouid=0 ogid=7 rdev=b4:00
obj=system_u:object_r:printer_device_t:s0


Comment 6 Tim Waugh 2007-02-07 11:39:16 UTC
I expect you have something like this further up in your error_log file:

N [07/Feb/2007:11:36:12 +0000] Group and SystemGroup cannot use the same groups!
I [07/Feb/2007:11:36:12 +0000] Resetting Group to "nobody"...


Comment 7 Klaus Heinrich Kiwi 2007-02-07 16:08:43 UTC
(In reply to comment #6)
> I expect you have something like this further up in your error_log file:
> 
> N [07/Feb/2007:11:36:12 +0000] Group and SystemGroup cannot use the same groups!
> I [07/Feb/2007:11:36:12 +0000] Resetting Group to "nobody"...
> 

indeed, that was the case. thank you


Note You need to log in before you can comment on or make changes to this bug.