Bug 227164 - [LSPP] '/usr/lib/cups/backend/usb failed' when trying to print to an USB printer
[LSPP] '/usr/lib/cups/backend/usb failed' when trying to print to an USB printer
Status: CLOSED NOTABUG
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: cups (Show other bugs)
5.0
All Linux
medium Severity high
: ---
: ---
Assigned To: Tim Waugh
David Lawrence
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2007-02-02 15:50 EST by Klaus Heinrich Kiwi
Modified: 2007-11-30 17:07 EST (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2007-02-07 06:39:16 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Klaus Heinrich Kiwi 2007-02-02 15:50:44 EST
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 16:40:51 EST
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 17:07:56 EST
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 17:27:06 EST
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 16:11:36 EST
(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 12:20:15 EST
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 06:39:16 EST
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 11:08:43 EST
(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.