Automatic print routing aborting job

David McNicoll mcnicoll at ringball.com
Thu Aug 16 06:00:23 PDT 2012


> David McNicoll wrote:
>
> > Our ERP software uses and automatic print routing for printing packing
> > slips to our line printers.
> >
> > We have recently upgraded from RHEL 3 to 6.3.  Since the upgrade the auto
> > print feature is dropping print jobs, yet the ERP software registers them
> > as printed.
> >
> > All manual printing functions seem to be working fine.
> >
> > Here is the error_log of the job that failed.
> >
> > I [14/Aug/2012:12:11:38 -0400] [Job 8604] Adding end banner page "none".
> > D [14/Aug/2012:12:11:38 -0400] Discarding unused job-state-changed
> > event... I [14/Aug/2012:12:11:38 -0400] [Job 8604] Job submission timed
> > out. D [14/Aug/2012:12:11:38 -0400] cupsdMarkDirty(----J-)
> > D [14/Aug/2012:12:11:38 -0400] cupsdSetBusyState: Dirty files
> > D [14/Aug/2012:12:11:38 -0400] Discarding unused job-completed event...
> > E [14/Aug/2012:12:11:38 -0400] [Job 8604] Aborting job because it has no
> > files. D [14/Aug/2012:12:11:38 -0400] [Job 8604] Unloading...
> > D [14/Aug/2012:12:11:38 -0400] cupsdAcceptClient: skipping getpeercon()
> > D [14/Aug/2012:12:11:38 -0400] cupsdAcceptClient: 15 from localhost
> > (Domain) I [14/Aug/2012:12:11:38 -0400] Saving job cache file
> > "/var/cache/cups/job.cache"... D [14/Aug/2012:12:11:38 -0400]
> > cupsdSetBusyState: Not busy D [14/Aug/2012:12:11:38 -0400]
> > cupsdReadClient: 15 POST / HTTP/1.1 D [14/Aug/2012:12:11:38 -0400]
> > cupsdSetBusyState: Active clients D [14/Aug/2012:12:11:38 -0400]
> > cupsdAuthorize: No authentication data provided. D [14/Aug/2012:12:11:38
> > -0400] cupsdReadClient: 15 1.1 Get-Jobs 1 D [14/Aug/2012:12:11:38 -0400]
> > Get-Jobs ipp://localhost/printers/ D [14/Aug/2012:12:11:38 -0400]
> > Returning IPP successful-ok for Get-Jobs (ipp://localhost/printers/) from
> > localhost D [14/Aug/2012:12:11:38 -0400] cupsdSetBusyState: Not busy D
> > [14/Aug/2012:12:11:38 -0400] cupsdReadClient: 15 WAITING Closing on EOF D
> > [14/Aug/2012:12:11:38 -0400] cupsdCloseClient: 15
> >
> > Can anyone give me some idea as to what may cause these jobs to fail?
>
> It seems CUPS is receiving the request (IPP request?) but not the
> corrensponding data.
> To do further analysis, you need to supply more information:
> 1. the portion of the error_log (produced with log level debug) of a
> complete job that does exhibit this issue
> 2. information on how your ERP software submits the print jobs (as much
> information as possible).
>
> Helge
>

Here is some more information from a previous error_log that failed to print:

D [26/Jul/2012:08:08:31 -0400] [Job 3280] STATE: -connecting-to-device
I [26/Jul/2012:08:08:31 -0400] [Job 3280] Connected to printer...
D [26/Jul/2012:08:08:31 -0400] [Job 3280] Connected to 172.16.172.137:9100 (IPv4)...
D [26/Jul/2012:08:08:31 -0400] [Job 3280] PAGE: 1 1
D [26/Jul/2012:08:08:31 -0400] Discarding unused job-progress event...
D [26/Jul/2012:08:08:31 -0400] [Job 3280] backendRunLoop(print_fd=5, device_fd=6, snmp_fd=7, addr=0xf468ac, use_bc=1, side_cb=0x7fe370)
D [26/Jul/2012:08:08:31 -0400] [Job 3280] Read 1031 bytes of print data...
D [26/Jul/2012:08:08:31 -0400] [Job 3280] Wrote 1031 bytes of print data...
I [26/Jul/2012:08:08:31 -0400] [Job 3280] Sent print file, 1031 bytes...
I [26/Jul/2012:08:08:31 -0400] [Job 3280] Print file sent, waiting for printer to finish...
I [26/Jul/2012:08:08:31 -0400] [Job 3280] Ready to print.
D [26/Jul/2012:08:08:31 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:31 -0400] Discarding unused job-progress event...
D [26/Jul/2012:08:08:31 -0400] cupsdAcceptClient: skipping getpeercon()
D [26/Jul/2012:08:08:31 -0400] cupsdAcceptClient: 18 from localhost (Domain)
D [26/Jul/2012:08:08:31 -0400] Discarding unused job-completed event...
I [26/Jul/2012:08:08:31 -0400] [Job 3280] Job completed.
D [26/Jul/2012:08:08:31 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:31 -0400] cupsdMarkDirty(----J-)
D [26/Jul/2012:08:08:31 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:31 -0400] [Job 3281] Sending job to queue tagged as raw...
D [26/Jul/2012:08:08:31 -0400] [Job 3281] job-sheets=none,none
D [26/Jul/2012:08:08:31 -0400] [Job 3281] argv[0]="LP21"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] argv[1]="3281"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] argv[2]="smith"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] argv[3]="(stdin)"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] argv[4]="1"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:d29633ac-bef2-3b70-5fc7-194ed64f7c2e job-originating-host-name=localhost"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] argv[6]="/var/spool/cups/d03281-001"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[2]="CUPS_DOCROOT=/usr/share/cups/www"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[8]="HOME=/var/spool/cups/tmp"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[10]="SERVER_ADMIN=root at rincor"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[11]="SOFTWARE=CUPS/1.4.2"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[13]="USER=root"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[16]="IPP_PORT=631"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[17]="CHARSET=utf-8"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[18]="LANG=en_US.UTF-8"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[19]="PPD=/etc/cups/ppd/LP21.ppd"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[20]="RIP_MAX_CACHE=128m"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[21]="CONTENT_TYPE=application/octet-stream"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[22]="DEVICE_URI=socket://172.16.172.137:9100"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[23]="PRINTER_INFO=LP21"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[24]="PRINTER_LOCATION=BRANCH 21"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[25]="PRINTER=LP21"
D [26/Jul/2012:08:08:31 -0400] [Job 3281] envp[26]="CUPS_FILETYPE=document"
I [26/Jul/2012:08:08:31 -0400] [Job 3281] Started backend /usr/lib/cups/backend/socket (PID 3160)
D [26/Jul/2012:08:08:31 -0400] Discarding unused job-state-changed event...
D [26/Jul/2012:08:08:31 -0400] Send-Document ipp://localhost:631/printers/LP21
D [26/Jul/2012:08:08:31 -0400] cupsdIsAuthorized: requesting-user-name="smith"
D [26/Jul/2012:08:08:31 -0400] [Job 3282] Auto-typing file...
D [26/Jul/2012:08:08:31 -0400] [Job 3282] Request file type is application/octet-stream.
D [26/Jul/2012:08:08:31 -0400] cupsdMarkDirty(----J-)
I [26/Jul/2012:08:08:31 -0400] [Job 3282] File of type application/octet-stream queued by "smith".
I [26/Jul/2012:08:08:31 -0400] [Job 3282] Adding end banner page "none".
D [26/Jul/2012:08:08:31 -0400] cupsdMarkDirty(----J-)
D [26/Jul/2012:08:08:31 -0400] Returning IPP successful-ok for Send-Document (ipp://localhost:631/printers/LP21) from localhost
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 18 POST / HTTP/1.1
D [26/Jul/2012:08:08:31 -0400] cupsdAuthorize: No authentication data provided.
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 18 1.1 Get-Jobs 1
D [26/Jul/2012:08:08:31 -0400] Get-Jobs ipp://localhost/printers/
D [26/Jul/2012:08:08:31 -0400] Returning IPP successful-ok for Get-Jobs (ipp://localhost/printers/) from localhost
D [26/Jul/2012:08:08:31 -0400] cupsdSetBusyState: Printing jobs and dirty files
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 18 WAITING Closing on EOF
D [26/Jul/2012:08:08:31 -0400] cupsdCloseClient: 18
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 15 WAITING Closing on EOF
D [26/Jul/2012:08:08:31 -0400] cupsdCloseClient: 15
D [26/Jul/2012:08:08:31 -0400] [Job 3281] STATE: +connecting-to-device
D [26/Jul/2012:08:08:31 -0400] [Job 3281] Looking up "172.16.172.137"...
D [26/Jul/2012:08:08:31 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:31 -0400] [Job 3281] Connecting to 172.16.172.137:9100
I [26/Jul/2012:08:08:31 -0400] [Job 3281] Connecting to printer...
D [26/Jul/2012:08:08:31 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:31 -0400] Discarding unused job-progress event...
D [26/Jul/2012:08:08:31 -0400] cupsdAcceptClient: skipping getpeercon()
D [26/Jul/2012:08:08:31 -0400] cupsdAcceptClient: 15 from localhost (Domain)
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 15 POST / HTTP/1.1
D [26/Jul/2012:08:08:31 -0400] cupsdSetBusyState: Active clients, printing jobs, and dirty files
D [26/Jul/2012:08:08:31 -0400] cupsdAuthorize: No authentication data provided.
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 15 1.1 Get-Printer-Attributes 1
D [26/Jul/2012:08:08:31 -0400] Get-Printer-Attributes ipp://localhost:631/printers/LP21
D [26/Jul/2012:08:08:31 -0400] Returning IPP successful-ok for Get-Printer-Attributes (ipp://localhost:631/printers/LP21) from localhost
D [26/Jul/2012:08:08:31 -0400] cupsdSetBusyState: Printing jobs and dirty files
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 15 POST /printers/LP21 HTTP/1.1
D [26/Jul/2012:08:08:31 -0400] cupsdSetBusyState: Active clients, printing jobs, and dirty files
D [26/Jul/2012:08:08:31 -0400] cupsdAuthorize: No authentication data provided.
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 15 1.1 Create-Job 1
D [26/Jul/2012:08:08:31 -0400] Create-Job ipp://localhost:631/printers/LP21
D [26/Jul/2012:08:08:31 -0400] add_job: setting context of job to UNKNOWN SL
D [26/Jul/2012:08:08:31 -0400] cupsdMarkDirty(----J-)
D [26/Jul/2012:08:08:31 -0400] add_job: requesting-user-name="smith"
I [26/Jul/2012:08:08:31 -0400] [Job 3283] Adding start banner page "none".
D [26/Jul/2012:08:08:31 -0400] Discarding unused job-created event...
I [26/Jul/2012:08:08:31 -0400] [Job 3283] Queued on "LP21" by "smith".
D [26/Jul/2012:08:08:31 -0400] Returning IPP successful-ok for Create-Job (ipp://localhost:631/printers/LP21) from localhost
D [26/Jul/2012:08:08:31 -0400] cupsdSetBusyState: Printing jobs and dirty files
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 15 POST /printers/LP21 HTTP/1.1
D [26/Jul/2012:08:08:31 -0400] cupsdSetBusyState: Active clients, printing jobs, and dirty files
D [26/Jul/2012:08:08:31 -0400] cupsdAuthorize: No authentication data provided.
D [26/Jul/2012:08:08:31 -0400] cupsdReadClient: 15 1.1 Send-Document 1
D [26/Jul/2012:08:08:42 -0400] PID 3160 (/usr/lib/cups/backend/socket) exited with no errors.
D [26/Jul/2012:08:08:42 -0400] cupsdAcceptClient: skipping getpeercon()
D [26/Jul/2012:08:08:42 -0400] cupsdAcceptClient: 18 from localhost (Domain)
D [26/Jul/2012:08:08:42 -0400] [Job 3281] STATE: -connecting-to-device
I [26/Jul/2012:08:08:42 -0400] [Job 3281] Connected to printer...
D [26/Jul/2012:08:08:42 -0400] [Job 3281] Connected to 172.16.172.137:9100 (IPv4)...
D [26/Jul/2012:08:08:42 -0400] [Job 3281] PAGE: 1 1
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-progress event...
D [26/Jul/2012:08:08:42 -0400] [Job 3281] backendRunLoop(print_fd=5, device_fd=6, snmp_fd=7, addr=0x112b8ac, use_bc=1, side_cb=0x4a7370)
D [26/Jul/2012:08:08:42 -0400] [Job 3281] Read 1236 bytes of print data...
D [26/Jul/2012:08:08:42 -0400] [Job 3281] Wrote 1236 bytes of print data...
I [26/Jul/2012:08:08:42 -0400] [Job 3281] Sent print file, 1236 bytes...
I [26/Jul/2012:08:08:42 -0400] [Job 3281] Print file sent, waiting for printer to finish...
I [26/Jul/2012:08:08:42 -0400] [Job 3281] Ready to print.
D [26/Jul/2012:08:08:42 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-progress event...
D [26/Jul/2012:08:08:42 -0400] [Job 3280] Unloading...
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-completed event...
I [26/Jul/2012:08:08:42 -0400] [Job 3281] Job completed.
D [26/Jul/2012:08:08:42 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:42 -0400] cupsdMarkDirty(----J-)
D [26/Jul/2012:08:08:42 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:42 -0400] [Job 3282] Sending job to queue tagged as raw...
D [26/Jul/2012:08:08:42 -0400] [Job 3282] job-sheets=none,none
D [26/Jul/2012:08:08:42 -0400] [Job 3282] argv[0]="LP21"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] argv[1]="3282"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] argv[2]="smith"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] argv[3]="(stdin)"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] argv[4]="1"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:77197a26-d569-327c-7af1-4c4582542502 job-originating-host-name=localhost"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] argv[6]="/var/spool/cups/d03282-001"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[2]="CUPS_DOCROOT=/usr/share/cups/www"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[8]="HOME=/var/spool/cups/tmp"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[10]="SERVER_ADMIN=root at rincor"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[11]="SOFTWARE=CUPS/1.4.2"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[13]="USER=root"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[16]="IPP_PORT=631"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[17]="CHARSET=utf-8"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[18]="LANG=en_US.UTF-8"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[19]="PPD=/etc/cups/ppd/LP21.ppd"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[20]="RIP_MAX_CACHE=128m"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[21]="CONTENT_TYPE=application/octet-stream"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[22]="DEVICE_URI=socket://172.16.172.137:9100"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[23]="PRINTER_INFO=LP21"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[24]="PRINTER_LOCATION=BRANCH 21"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[25]="PRINTER=LP21"
D [26/Jul/2012:08:08:42 -0400] [Job 3282] envp[26]="CUPS_FILETYPE=document"
I [26/Jul/2012:08:08:42 -0400] [Job 3282] Started backend /usr/lib/cups/backend/socket (PID 3165)
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-state-changed event...
D [26/Jul/2012:08:08:42 -0400] cupsdReadClient: 18 POST / HTTP/1.1
D [26/Jul/2012:08:08:42 -0400] cupsdAuthorize: No authentication data provided.
D [26/Jul/2012:08:08:42 -0400] cupsdReadClient: 18 1.1 Get-Jobs 1
D [26/Jul/2012:08:08:42 -0400] Get-Jobs ipp://localhost/printers/
D [26/Jul/2012:08:08:42 -0400] Returning IPP successful-ok for Get-Jobs (ipp://localhost/printers/) from localhost
D [26/Jul/2012:08:08:42 -0400] cupsdReadClient: 18 WAITING Closing on EOF
D [26/Jul/2012:08:08:42 -0400] cupsdCloseClient: 18
D [26/Jul/2012:08:08:42 -0400] [Job 3282] STATE: +connecting-to-device
D [26/Jul/2012:08:08:42 -0400] [Job 3282] Looking up "172.16.172.137"...
D [26/Jul/2012:08:08:42 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:42 -0400] [Job 3282] Connecting to 172.16.172.137:9100
I [26/Jul/2012:08:08:42 -0400] [Job 3282] Connecting to printer...
D [26/Jul/2012:08:08:42 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-progress event...
D [26/Jul/2012:08:08:42 -0400] [Job 3282] STATE: -connecting-to-device
I [26/Jul/2012:08:08:42 -0400] [Job 3282] Connected to printer...
D [26/Jul/2012:08:08:42 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-progress event...
D [26/Jul/2012:08:08:42 -0400] [Job 3282] Connected to 172.16.172.137:9100 (IPv4)...
D [26/Jul/2012:08:08:42 -0400] [Job 3282] PAGE: 1 1
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-progress event...
D [26/Jul/2012:08:08:42 -0400] [Job 3282] backendRunLoop(print_fd=5, device_fd=6, snmp_fd=7, addr=0x1a698ac, use_bc=1, side_cb=0xc0f370)
D [26/Jul/2012:08:08:42 -0400] [Job 3282] Read 5389 bytes of print data...
D [26/Jul/2012:08:08:42 -0400] [Job 3282] Wrote 5389 bytes of print data...
I [26/Jul/2012:08:08:42 -0400] [Job 3282] Sent print file, 5389 bytes...
I [26/Jul/2012:08:08:42 -0400] [Job 3282] Print file sent, waiting for printer to finish...
D [26/Jul/2012:08:08:42 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-progress event...
I [26/Jul/2012:08:08:42 -0400] [Job 3282] Ready to print.
D [26/Jul/2012:08:08:42 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-progress event...
D [26/Jul/2012:08:08:42 -0400] PID 3165 (/usr/lib/cups/backend/socket) exited with no errors.
D [26/Jul/2012:08:08:42 -0400] Discarding unused job-completed event...
I [26/Jul/2012:08:08:42 -0400] [Job 3282] Job completed.
D [26/Jul/2012:08:08:42 -0400] Discarding unused printer-state-changed event...
D [26/Jul/2012:08:08:42 -0400] cupsdAcceptClient: skipping getpeercon()
D [26/Jul/2012:08:08:42 -0400] cupsdAcceptClient: 16 from localhost (Domain)
D [26/Jul/2012:08:08:42 -0400] cupsdReadClient: 16 POST / HTTP/1.1
D [26/Jul/2012:08:08:42 -0400] cupsdSetBusyState: Active clients and dirty files
D [26/Jul/2012:08:08:42 -0400] cupsdAuthorize: No authentication data provided.
D [26/Jul/2012:08:08:42 -0400] cupsdReadClient: 16 1.1 Get-Jobs 1
D [26/Jul/2012:08:08:42 -0400] Get-Jobs ipp://localhost/printers/
D [26/Jul/2012:08:08:42 -0400] Returning IPP successful-ok for Get-Jobs (ipp://localhost/printers/) from localhost
D [26/Jul/2012:08:08:42 -0400] cupsdReadClient: 16 WAITING Closing on EOF
D [26/Jul/2012:08:08:42 -0400] cupsdCloseClient: 16
D [26/Jul/2012:08:08:43 -0400] [Job 3281] Unloading...
D [26/Jul/2012:08:08:43 -0400] [Job 3282] Unloading...
I [26/Jul/2012:08:09:01 -0400] Saving job cache file "/var/cache/cups/job.cache"...
D [26/Jul/2012:08:09:01 -0400] cupsdSetBusyState: Active clients
D [26/Jul/2012:08:13:32 -0400] Closing client 15 after 300 seconds of inactivity...
D [26/Jul/2012:08:13:32 -0400] cupsdCloseClient: 15
D [26/Jul/2012:08:13:32 -0400] cupsdSetBusyState: Not busy
I [26/Jul/2012:08:13:32 -0400] [Job 3283] Adding end banner page "none".
D [26/Jul/2012:08:13:32 -0400] Discarding unused job-state-changed event...
I [26/Jul/2012:08:13:32 -0400] [Job 3283] Job submission timed out.
D [26/Jul/2012:08:13:32 -0400] cupsdMarkDirty(----J-)
D [26/Jul/2012:08:13:32 -0400] cupsdSetBusyState: Dirty files
D [26/Jul/2012:08:13:32 -0400] Discarding unused job-completed event...
E [26/Jul/2012:08:13:32 -0400] [Job 3283] Aborting job because it has no files.
D [26/Jul/2012:08:13:32 -0400] [Job 3283] Unloading...
D [26/Jul/2012:08:13:32 -0400] Report: clients=0
D [26/Jul/2012:08:13:32 -0400] Report: jobs=0
D [26/Jul/2012:08:13:32 -0400] Report: jobs-active=0
D [26/Jul/2012:08:13:32 -0400] Report: printers=21
D [26/Jul/2012:08:13:32 -0400] Report: printers-implicit=0
D [26/Jul/2012:08:13:32 -0400] Report: stringpool-string-count=2772
D [26/Jul/2012:08:13:32 -0400] Report: stringpool-alloc-bytes=9848
D [26/Jul/2012:08:13:32 -0400] Report: stringpool-total-bytes=60144
D [26/Jul/2012:08:13:32 -0400] cupsdAcceptClient: skipping getpeercon()
D [26/Jul/2012:08:13:32 -0400] cupsdAcceptClient: 15 from localhost (Domain)
D [26/Jul/2012:08:13:32 -0400] cupsdReadClient: 15 POST / HTTP/1.1
D [26/Jul/2012:08:13:32 -0400] cupsdSetBusyState: Active clients and dirty files
D [26/Jul/2012:08:13:32 -0400] cupsdAuthorize: No authentication data provided.
D [26/Jul/2012:08:13:32 -0400] cupsdReadClient: 15 1.1 Get-Jobs 1
D [26/Jul/2012:08:13:32 -0400] Get-Jobs ipp://localhost/printers/
D [26/Jul/2012:08:13:32 -0400] Returning IPP successful-ok for Get-Jobs (ipp://localhost/printers/) from localhost
D [26/Jul/2012:08:13:32 -0400] cupsdSetBusyState: Dirty files
D [26/Jul/2012:08:13:32 -0400] cupsdReadClient: 15 WAITING Closing on EOF
D [26/Jul/2012:08:13:32 -0400] cupsdCloseClient: 15

All starts well with the first few jobs printing [Job 3280] then ends with the last job failing [Job 3283].  Even after the last job fails, the automatic print routine continues to run and print more packing slips with an occasional failure.  According to our ERP vendor the automatic program is designed to run the same manual printing steps that would be performed by an operator.
The printouts are simple text, no graphics.




More information about the cups mailing list