[SOLVED] RHEL5: CUPS takes 10-60m to print and seems locked to Samba

lefty.crupps · 03-03-2011, 05:20 PM

This may be two separate issues, but the two problems exist on three different RHEL5 servers, two of which were fully updated to RHEL5.x on 18 Feb 2011. They've since been 'yum downgrade ____' for a number of CUPS, Gutenprint, HPLIP, and Samba packages but without fixing the issues.

The issues are:
1. Printing from CUPS takes between 10m and 60 (or so) minutes (!) before the printer prints basic text files;
and
2. SOMETIMES, CUPS cannot be restarted unless I also restart Samba, and Samba cannot be restarted unless I also restart CUPS. If I don't do both sometimes things are fine, but other times the one will just hang until I restart both...

Logs further below.

Here are the configs for one of the three machines; this server is the most pressing. Note on this how there are no local printers being shared nor are any remote printers using Samba.

Code:

[root@bp ~]# cat /etc/cups/printers.conf
# Printer configuration file for CUPS v1.3.7
# Written by cupsd on 2011-02-23 10:46
<Printer bill_s>
Info Bill S Printer
Location Bill's Office
DeviceURI socket://10.10.10.217:9100
State Idle
StateTime 1298479592
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy stop-printer
</Printer>
<Printer bills_printer>
Info test
Location test
DeviceURI socket://10.10.10.217:9100
State Idle
StateTime 1263326227
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy stop-printer
</Printer>
<Printer mfp3115>
Info Dell MFP 3115
Location SBC Corporate, Copy Room
DeviceURI socket://10.10.10.218
State Idle
StateTime 1298395068
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy stop-printer
</Printer>
<Printer mfp3115cl>
Info Dell MFP 3115 - Compressed Landscape
Location Corporate, Copy Room
DeviceURI socket://10.10.10.218
State Idle
StateTime 1263324472
Accepting Yes
Shared Yes
JobSheets none none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy stop-printer
</Printer>

Code:

[root@bp ~]# cat /etc/samba/smb.conf |grep -v "^#" |grep -v "^;"

[global]

        workgroup = MYGROUP
        server string = Samba Server Version %v

        security = user
        passdb backend = ldapsam:"ldap://1.2.1.2/ ldap://1.2.1.3"
        obey pam restrictions = no

        ldap admin dn = uid=authuser,dc=XXXXXXXX,dc=net
        ldap suffix = dc=XXXXXXXX, dc=net
        ldap group suffix = ou=Group
        ldap user suffix = ou=People
        ldap machine suffix = ou=Computers
        ldap idmap suffix = ou=People

        load printers = yes
        cups options = raw

[public]
   comment = Public P drive
   path = /var/samba/public
   public = yes
   writable = yes
   printable = no
   create mask = 0775
   create mode = 0775
   group = staff
   invalid users = pick
   valid users = @admins

[qb]
   comment = Public P drive
   path = /var/samba/public/qb
   public = yes
   writable = yes
   printable = no
   create mask = 0775
   create mode = 0775
   group = staff
   valid users = @admins

[invoices]
   comment = Public P drive
   path = /var/work/docs/invoices
   public = yes
   writable = yes
   printable = no
   create mask = 0775
   create mode = 0775
   group = staff
   valid users = @admins

Here are logs if I try a print job, note this job's time to print:

Code:

time lpr -P bill_s /root/test

real    10m0.027s
user    0m0.005s
sys     0m0.005s

Code:

tail -f {/var/log/samba/*,/var/log/cups/*}
==> /var/log/cups/access_log <==
localhost - - [03/Mar/2011:17:03:30 -0600] "POST / HTTP/1.1" 200 467 Get-Printer-Attributes successful-ok

==> /var/log/cups/error_log <==
D [03/Mar/2011:17:03:30 -0600] cupsdAcceptClient: skipping getpeercon()
D [03/Mar/2011:17:03:30 -0600] cupsdAcceptClient: 8 from localhost (Domain)
D [03/Mar/2011:17:03:30 -0600] Report: clients=1
D [03/Mar/2011:17:03:30 -0600] Report: jobs=40
D [03/Mar/2011:17:03:30 -0600] Report: jobs-active=0
D [03/Mar/2011:17:03:30 -0600] Report: printers=4
D [03/Mar/2011:17:03:30 -0600] Report: printers-implicit=0
D [03/Mar/2011:17:03:30 -0600] Report: stringpool-string-count=721
D [03/Mar/2011:17:03:30 -0600] Report: stringpool-alloc-bytes=9616
D [03/Mar/2011:17:03:30 -0600] Report: stringpool-total-bytes=13936
D [03/Mar/2011:17:03:30 -0600] cupsdReadClient: 8 POST / HTTP/1.1
D [03/Mar/2011:17:03:30 -0600] cupsdAuthorize: No authentication data provided.
D [03/Mar/2011:17:03:30 -0600] Get-Printer-Attributes ipp://localhost:631/printers/bill_s
D [03/Mar/2011:17:03:30 -0600] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
D [03/Mar/2011:17:03:30 -0600] cupsdCloseClient: 8
D [03/Mar/2011:17:03:30 -0600] cupsdAcceptClient: skipping getpeercon()
D [03/Mar/2011:17:03:30 -0600] cupsdAcceptClient: 8 from localhost (Domain)
D [03/Mar/2011:17:03:30 -0600] cupsdReadClient: 8 POST /printers/bill_s HTTP/1.1
D [03/Mar/2011:17:03:30 -0600] cupsdAuthorize: No authentication data provided.
D [03/Mar/2011:17:03:30 -0600] Print-Job ipp://localhost/printers/bill_s
D [03/Mar/2011:17:03:30 -0600] print_job: auto-typing file...
D [03/Mar/2011:17:03:30 -0600] add_job: setting context of job to UNKNOWN SL
D [03/Mar/2011:17:03:30 -0600] add_job: requesting-user-name="root"
I [03/Mar/2011:17:03:30 -0600] [Job 1910] Adding start banner page "none".
D [03/Mar/2011:17:05:30 -0600] Discarding unused job-created event...
I [03/Mar/2011:17:05:30 -0600] [Job 1910] Adding job file of type text/plain.
I [03/Mar/2011:17:05:30 -0600] [Job 1910] Adding end banner page "none".
I [03/Mar/2011:17:05:30 -0600] [Job 1910] Queued on "bill_s" by "root".
D [03/Mar/2011:17:05:30 -0600] [Job 1910] hold_until = 0

==> /var/log/samba/smbd.log <==
[2011/03/03 17:07:13, 0] rpc_parse/parse_prs.c:prs_grow(252)
  prs_grow: Buffer overflow - unable to expand buffer by 2 bytes.
[2011/03/03 17:07:13, 0] rpc_server/srv_spoolss.c:api_spoolss_addprinterex(885)
  spoolss_io_q_addprinterex: unable to unmarshall SPOOL_Q_ADDPRINTEREX.
[2011/03/03 17:07:13, 0] rpc_server/srv_pipe.c:api_rpcTNP(2287)
  api_rpcTNP: spoolss: SPOOLSS_ADDPRINTEREX failed.
[2011/03/03 17:07:24, 0] lib/util_sock.c:read_data(534)
  read_data: read failure for 4 bytes to client 10.10.10.6. Error = Connection reset by peer

==> /var/log/cups/error_log <==
D [03/Mar/2011:17:07:30 -0600] Discarding unused printer-state-changed event...
D [03/Mar/2011:17:07:30 -0600] [Job 1910] job-sheets=none,none
D [03/Mar/2011:17:07:30 -0600] [Job 1910] banner_page = 0
D [03/Mar/2011:17:07:30 -0600] [Job 1910] argv[0]="bill_s"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] argv[1]="1910"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] argv[2]="root"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] argv[3]="test"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] argv[4]="1"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] argv[5]="document-name=test media=Letter sides=one-sided finishings=3 number-up=1 job-uuid=urn:uuid:12d08677-2d7e-354b-7b33-efbe10162ecc"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] argv[6]="/var/spool/cups/d01910-001"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[2]="CUPS_DOCROOT=/usr/share/doc/cups-1.3.7"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[8]="PATH=/usr/lib/cups/filter:/usr/lib64/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[9]="SERVER_ADMIN=root@bigpapa.bravo"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[10]="SOFTWARE=CUPS/1.3.7"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[11]="TMPDIR=/var/spool/cups/tmp"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[12]="USER=root"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[13]="CUPS_SERVER=/var/run/cups/cups.sock"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[14]="CUPS_ENCRYPTION=IfRequested"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[15]="IPP_PORT=631"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[16]="CHARSET=utf-8"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[17]="LANG=en_US.UTF8"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[18]="PPD=/etc/cups/ppd/bill_s.ppd"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[19]="RIP_MAX_CACHE=8m"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[20]="CONTENT_TYPE=text/plain"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[21]="DEVICE_URI=socket://10.10.10.217:9100"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[22]="PRINTER=bill_s"
D [03/Mar/2011:17:07:30 -0600] [Job 1910] envp[23]="FINAL_CONTENT_TYPE=printer/bill_s"
I [03/Mar/2011:17:07:30 -0600] [Job 1910] Started filter /usr/lib/cups/filter/texttopaps (PID 13832)
I [03/Mar/2011:17:07:30 -0600] [Job 1910] Started filter /usr/lib/cups/filter/pstops (PID 13833)
I [03/Mar/2011:17:07:30 -0600] [Job 1910] Started filter /usr/lib/cups/filter/foomatic-rip (PID 13834)
I [03/Mar/2011:17:07:30 -0600] [Job 1910] Started backend /usr/lib/cups/backend/socket (PID 13835)
D [03/Mar/2011:17:09:30 -0600] Discarding unused job-state-changed event...
D [03/Mar/2011:17:09:30 -0600] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
D [03/Mar/2011:17:09:30 -0600] PID 13832 (/usr/lib/cups/filter/texttopaps) exited with no errors.
D [03/Mar/2011:17:09:30 -0600] PID 13833 (/usr/lib/cups/filter/pstops) exited with no errors.
D [03/Mar/2011:17:09:30 -0600] PID 13834 (/usr/lib/cups/filter/foomatic-rip) exited with no errors.
D [03/Mar/2011:17:09:30 -0600] PID 13835 (/usr/lib/cups/backend/socket) exited with no errors.
D [03/Mar/2011:17:09:30 -0600] [Job 1910] Connected to 10.10.10.217:9100 (IPv4)...
D [03/Mar/2011:17:09:30 -0600] [Job 1910] backendRunLoop(print_fd=0, device_fd=5, use_bc=1, side_cb=0x2b86c19b3330)
D [03/Mar/2011:17:09:30 -0600] [Job 1910] Page = 612x792; 0,0 to 612,792
D [03/Mar/2011:17:09:30 -0600] [Job 1910] slow_collate=0, slow_duplex=0, slow_order=0
D [03/Mar/2011:17:09:30 -0600] [Job 1910] Before copy_comments - %!PS-Adobe-3.0
D [03/Mar/2011:17:09:30 -0600] [Job 1910] %!PS-Adobe-3.0
D [03/Mar/2011:17:09:30 -0600] [Job 1910] %cupsRotation: 0
D [03/Mar/2011:17:09:30 -0600] [Job 1910] %%Title: test
D [03/Mar/2011:17:09:30 -0600] [Job 1910] %%Creator: paps version 0.6.3 by Dov Grobgeld
D [03/Mar/2011:17:09:30 -0600] [Job 1910] %%Pages: (atend)
D [03/Mar/2011:17:09:30 -0600] [Job 1910] %%BoundingBox: 0 0 612 792
D [03/Mar/2011:17:09:30 -0600] [Job 1910] %%For: root
D [03/Mar/2011:17:09:30 -0600] [Job 1910] %%BeginProlog
D [03/Mar/2011:17:09:30 -0600] [Job 1910] %%Orientation: Portrait
D [03/Mar/2011:17:09:30 -0600] [Job 1910] Before copy_prolog - /papsdict 1 dict def
D [03/Mar/2011:17:09:30 -0600] [Job 1910] Before copy_setup - %%EndPrologue
D [03/Mar/2011:17:09:30 -0600] [Job 1910] Label Page = 612x792; 0,0 to 612,792
D [03/Mar/2011:17:09:30 -0600] [Job 1910] Before page loop - %%Page: 1 1
D [03/Mar/2011:17:09:30 -0600] [Job 1910] Copying page 1...
D [03/Mar/2011:17:09:30 -0600] [Job 1910] pagew = 612.0, pagel = 792.0
D [03/Mar/2011:17:09:30 -0600] [Job 1910] bboxx = 0, bboxy = 0, bboxw = 612, bboxl = 792
D [03/Mar/2011:17:09:30 -0600] [Job 1910] PageLeft = 0.0, PageRight = 612.0
D [03/Mar/2011:17:11:30 -0600] Discarding unused printer-state-changed event...
D [03/Mar/2011:17:11:30 -0600] Report: clients=1
D [03/Mar/2011:17:11:30 -0600] Report: jobs=41
D [03/Mar/2011:17:11:30 -0600] Report: jobs-active=1
D [03/Mar/2011:17:11:30 -0600] Report: printers=4
D [03/Mar/2011:17:11:30 -0600] Report: printers-implicit=0
D [03/Mar/2011:17:11:30 -0600] Report: stringpool-string-count=830
D [03/Mar/2011:17:11:30 -0600] Report: stringpool-alloc-bytes=11000
D [03/Mar/2011:17:11:30 -0600] Report: stringpool-total-bytes=16248
D [03/Mar/2011:17:11:30 -0600] cupsdAcceptClient: skipping getpeercon()
D [03/Mar/2011:17:11:30 -0600] cupsdAcceptClient: 10 from localhost (Domain)
D [03/Mar/2011:17:11:30 -0600] [Job 1910] PageTop = 792.0, PageBottom = 0.0
D [03/Mar/2011:17:11:30 -0600] [Job 1910] PageWidth = 612.0, PageLength = 792.0
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Wrote 1 pages...
D [03/Mar/2011:17:11:30 -0600] [Job 1910] foomatic-rip version $Revision: 3.43.2.15 $ running...
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Parsing PPD file ...
D [03/Mar/2011:17:11:30 -0600] [Job 1910] *cupsFilter: "application/vnd.cups-postscript 0 foomatic-rip"
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Added option ColorSpace
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Added option PageSize
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Added option PageRegion
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Added option ImageableArea
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Added option PaperDimension
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Added option Duplex
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Added option Resolution
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Added option PreFilter
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Added option Font
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Parameter Summary
D [03/Mar/2011:17:11:30 -0600] [Job 1910] -----------------
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Spooler: cups
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Printer: bill_s
D [03/Mar/2011:17:11:30 -0600] [Job 1910] PPD file: /etc/cups/ppd/bill_s.ppd
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Printer model: Generic PostScript Printer Foomatic/Postscript (recommended)
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Job title: test
D [03/Mar/2011:17:11:30 -0600] [Job 1910] File(s) to be printed: 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] <STDIN>
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] GhostScript extra search path ('GS_LIB'): /usr/share/cups/fonts
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Pondering option 'document-name=test'
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Unknown option document-name=test.
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Pondering option 'media=Letter'
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Pondering option 'sides=one-sided'
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Pondering option 'finishings=3'
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Unknown option finishings=3.
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Pondering option 'number-up=1'
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Unknown option number-up=1.
D [03/Mar/2011:17:11:30 -0600] cupsdReadClient: 10 POST / HTTP/1.1
D [03/Mar/2011:17:11:30 -0600] cupsdAuthorize: No authentication data provided.
D [03/Mar/2011:17:11:30 -0600] CUPS-Get-Printers
D [03/Mar/2011:17:11:30 -0600] cupsdProcessIPPRequest: 10 status_code=0 (successful-ok)
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Pondering option 'job-uuid=urn:uuid:12d08677-2d7e-354b-7b33-efbe10162ecc'
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Unknown option job-uuid=urn:uuid:12d08677-2d7e-354b-7b33-efbe10162ecc.
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] ================================================
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] File: <STDIN>
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] ================================================
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Reading PostScript input ...
D [03/Mar/2011:17:11:30 -0600] [Job 1910] --> This document is DSC-conforming!
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] -----------
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%BeginProlog
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] -----------
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%BeginProlog
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%EndProlog
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%EndProlog
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] -----------
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%BeginSetup
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%BeginFeature: *PageSize Letter
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Option: PageSize=Letter --> Option will be set by PostScript interpreter
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%BeginFeature: *PreFilter No
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Option: PreFilter=No --> Setting option
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %% FoomaticRIPOptionSetting: PreFilter=No
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Option: PreFilter=No --> Setting option
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%BeginFeature: *Resolution default
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Option: Resolution=default --> Setting option
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %% FoomaticRIPOptionSetting: Resolution=default
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Option: Resolution=default --> Setting option
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%BeginFeature: *Duplex None
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Option: Duplex=None --> Correcting numerical/string option to Duplex=0 (Command line argument)
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%EndSetup
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Inserting PostScript code for CUPS' page accounting
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] -----------
D [03/Mar/2011:17:11:30 -0600] [Job 1910] New page:  1 1
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Inserting option code into "PageSetup" section.
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%BeginPageSetup
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Found: %%EndPageSetup
D [03/Mar/2011:17:11:30 -0600] [Job 1910] End of page header
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Flushing FIFO.
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Starting renderer
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Closing renderer
D [03/Mar/2011:17:11:30 -0600] [Job 1910] JCL: <job data> 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] 
D [03/Mar/2011:17:11:30 -0600] [Job 1910] renderer PID kid4=13841
D [03/Mar/2011:17:11:30 -0600] [Job 1910] renderer command: level=0; printf "%%!\n%%%% %%%%\n<</Duplex false>>setpagedevice\n"; if (( $level > 0 )); then if (( $level < 99 )); then level=" -dLanguageLevel=$level"; else level=""; fi; gs -q -dPARANOIDSAFER -dNOPAUSE -dBATCH -sDEVICE=pswrite$level -sOutputFile=- -; else cat; fi
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Read 40 bytes of print data...
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Wrote 40 bytes of print data...
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Read 75 bytes of print data...
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Wrote 75 bytes of print data...
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Read 218 bytes of print data...
D [03/Mar/2011:17:11:30 -0600] [Job 1910] Wrote 218 bytes of print data...

==> /var/log/cups/access_log <==
localhost - - [03/Mar/2011:17:03:30 -0600] "POST /printers/bill_s HTTP/1.1" 200 607 Print-Job successful-ok

==> /var/log/cups/error_log <==
D [03/Mar/2011:17:13:30 -0600] Discarding unused printer-state-changed event...
D [03/Mar/2011:17:13:30 -0600] Report: clients=2
D [03/Mar/2011:17:13:30 -0600] Report: jobs=41
D [03/Mar/2011:17:13:30 -0600] Report: jobs-active=1
D [03/Mar/2011:17:13:30 -0600] Report: printers=4
D [03/Mar/2011:17:13:30 -0600] Report: printers-implicit=0
D [03/Mar/2011:17:13:30 -0600] Report: stringpool-string-count=1422
D [03/Mar/2011:17:13:30 -0600] Report: stringpool-alloc-bytes=11616
D [03/Mar/2011:17:13:30 -0600] Report: stringpool-total-bytes=29000
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 306 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 306 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 195 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 195 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 174 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 174 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 211 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 211 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 123 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 123 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 175 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 175 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 166 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 166 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 283 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 283 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 121 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 121 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 214 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 214 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 128 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 128 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 104 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 104 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 295 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 295 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 427 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 427 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 176 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 176 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 126 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 126 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 125 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 125 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 157 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 157 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 201 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 201 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 140 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 140 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 268 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 268 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 160 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 160 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 115 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 115 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 89 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 89 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 91 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 91 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 61 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 61 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 102 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 102 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 86 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 86 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 111 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 111 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 54 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 54 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 158 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 158 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 295 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 295 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 314 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 314 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 230 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 230 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 50 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 50 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 151 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 151 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 144 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 144 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] KID3 exited with status 0
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 91 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 91 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 86 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 86 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 243 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 243 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 177 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 177 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 84 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 84 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 108 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 108 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 207 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 207 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 210 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 210 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 151 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 151 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 205 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 205 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 184 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 184 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 186 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] tail process done writing data to STDOUT
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 186 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] KID4 finished
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 8192 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] KID4 exited with status 0
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Renderer exit stat: 0
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 8192 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Read 1662 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Wrote 1662 bytes of print data...
D [03/Mar/2011:17:13:30 -0600] [Job 1910] KID3 finished
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Renderer process finished
D [03/Mar/2011:17:13:30 -0600] [Job 1910] 
D [03/Mar/2011:17:13:30 -0600] [Job 1910] Closing foomatic-rip.
D [03/Mar/2011:17:15:30 -0600] Discarding unused printer-state-changed event...
D [03/Mar/2011:17:15:30 -0600] Report: clients=2
D [03/Mar/2011:17:15:30 -0600] Report: jobs=41
D [03/Mar/2011:17:15:30 -0600] Report: jobs-active=1
D [03/Mar/2011:17:15:30 -0600] Report: printers=4
D [03/Mar/2011:17:15:30 -0600] Report: printers-implicit=0
D [03/Mar/2011:17:15:30 -0600] Report: stringpool-string-count=1417
D [03/Mar/2011:17:15:30 -0600] Report: stringpool-alloc-bytes=11600
D [03/Mar/2011:17:15:30 -0600] Report: stringpool-total-bytes=29000
D [03/Mar/2011:17:15:30 -0600] cupsdCloseClient: 8
D [03/Mar/2011:17:15:30 -0600] [Job 1910] File 0 is complete.
I [03/Mar/2011:17:15:30 -0600] [Job 1910] Completed successfully.

lefty.crupps · 04-13-2011, 09:28 AM

A reboot of this server fixed these issues. Not the ideal fix but the server was in need of a reboot for kernel updates anyways.

Thanks all for the eyeballs and sorry to future readers that I don't have a fix.