<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0//EN" "http://www.w3.org/TR/REC-html40/strict.dtd"> <html><head><meta name="qrichtext" content="1" /><style type="text/css"> p, li { white-space: pre-wrap; } </style></head><body style=" font-family:'Monospace'; font-size:8pt; font-weight:400; font-style:normal;"> Since updates were installed on 18 Feb 2011, two of our RedHat servers act very slow to print (10minutes being normal). These two systems are meant to be very similar, but one is 32bit and one is 64bit. A client's machine is having similar issues (up to 60 minutes before printing) but I cannot say for certain if the issue/cause is the same or not. This may be related to the fact that occasionally on those systems I cannot restart CUPS without also restarting Samba, and vice versa. Other times, I can restart one without problem and without worrying about the other. I cannot find reasoning behind this behaviour, and I don't know if its related at all to the printing issues, but I thought it may be. I've pasted configs and logs below, seperated by '======'. The 10m print jobs are very basic text files created in vim, usually reading 'test print from 2011 March 08' or the like. I've removed and reinstalled CUPS and when I've tried to re-add a printer that also took a long time, and even running 'lpstat -a' seems to be taking over 5 minutes so far... Note, the logs etc (below) are a week old but nothing has improved or changed since then. I tried downgrading CUPS but its not helped at all; currently running the newest RHEL5 version, 1:1.3.7-26.el5_6.1 Thanks for any insites, Jeffrey ====== [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> ====== [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 ====== time lpr -P bill_s /root/test real 10m0.027s user 0m0.005s sys 0m0.005s ====== 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.</body></html>