673010 – Unable to write uncompressed document data: Operation not permitted

Bug 673010 - Unable to write uncompressed document data: Operation not permitted

Summary: Unable to write uncompressed document data: Operation not permitted

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	Red Hat Enterprise Linux 5
Classification:	Red Hat
Component:	cups
Sub Component:
Version:	5.4
Hardware:	i386
OS:	Linux
Priority:	unspecified
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	Tim Waugh
QA Contact:	qe-baseos-daemons
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2011-01-27 01:29 UTC by Apostolos Pantazis
Modified:	2012-03-26 12:01 UTC (History)
CC List:	1 user (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2012-03-26 12:01:42 UTC
Target Upstream Version:
Dependent Products:

Attachments	(Terms of Use)
Add an attachment (proposed patch, testcase, etc.)

Description Apostolos Pantazis 2011-01-27 01:29:19 UTC

Description of problem:
Cups seizes to function temporarily and logs the following in error_log:
[25/Jan/2011:17:14:37 -0800] [Job 16568] Unable to write uncompressed document
E [25/Jan/2011:17:14:57 -0800] [Job 16572] Unable to write uncompressed document
E [25/Jan/2011:17:15:07 -0800] [Job 16574] Unable to write uncompressed document
E [25/Jan/2011:17:15:12 -0800] [Job 16575] Unable to write uncompressed document
E [25/Jan/2011:17:17:01 -0800] [Job 8694] Unable to write uncompressed document
E [25/Jan/2011:17:17:06 -0800] [Job 8696] Unable to write uncompressed document
E [26/Jan/2011:12:11:50 -0800] [Job 18278] Unable to write uncompressed document

W [19/Jan/2011:12:57:32 -0800] [Job 2079] recoverable: Network host '127.0.0.1' is busy; will retry in 30 seconds...
E [19/Jan/2011:12:57:54 -0800] [Job 6432] Unable to write print data: Broken pipe
E [19/Jan/2011:12:57:54 -0800] PID 18701 (/usr/lib/cups/backend/socket) stopped with status 1!
I [19/Jan/2011:12:57:54 -0800] Hint: Try setting the LogLevel to "debug" to find out more.
E [19/Jan/2011:12:57:54 -0800] [Job 6432] Unable to write uncompressed document data: Operation not permitted
E [19/Jan/2011:12:57:54 -0800] PID 18702 (/usr/lib/cups/filter/gziptoany) stopped with status 1!
I [19/Jan/2011:12:57:54 -0800] Hint: Try setting the LogLevel to "debug" to find out more.
I [19/Jan/2011:12:57:54 -0800] [Job 6432] Backend returned status 1 (failed)
I [19/Jan/2011:12:57:54 -0800] Saving printers.conf...



Version-Release number of selected component (if applicable):
cups-libs-1.3.7-11.el5
cups-1.3.7-11.el5

Linux details

Linux  2.6.18-164.el5PAE #1 SMP Tue Aug 18 15:59:11 EDT 2009 i686 i686 i386 GNU/Linux

How reproducible:
Unfortunately behavior is not reproducible; It seems to happen after approximately a day or so of cups running; I am working on trying to figure out a pattern if any and I will update.

Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:

This is all I have to go on:

 [19/Jan/2011:12:57:54 -0800] Hint: Try setting the LogLevel to "debug" to find out more.
E [19/Jan/2011:12:57:54 -0800] [Job 6432] Unable to write uncompressed document data: Operation not permitted
E [19/Jan/2011:12:57:54 -0800] PID 18702 (/usr/lib/cups/filter/gziptoany) stopped with status 1!
I [19/Jan/2011:12:57:54 -0800] Hint: Try setting the LogLevel to "debug" to find out more.
I [19/Jan/2011:12:57:54 -0800] [Job 6432] Backend returned status 1 (failed)
I [19/Jan/2011:12:57:54 -0800] Saving printers.conf...

Comment 1 Apostolos Pantazis 2011-01-27 01:40:17 UTC

I spoken with my Team here to try and get some more clues as to the details of the error; we seem to be convinced that it is Load induced; A way to replicate this may be creating a good number of printers (160 or so) and trying to throw some load at it (printing wise)

Comment 2 Tim Waugh 2011-02-03 16:04:26 UTC

The 'socket' backend is unable to connect to the server, and the connection timeout (normally 1 week) has elapsed.

What device URIs are you using on the queues that fail in this way?  I'm guessing they will look something like socket://127.0.0.1:xxx?contimeout=yyy.

Comment 3 Apostolos Pantazis 2011-02-15 02:01:17 UTC

Tim, sorry for the delay, got slammed;

First off thanks for the response;

The Device URI socket looks as follows (using config from one of the printers):

<Printer Paul>
Info act1
DeviceURI socket://172.20.22.201:9100/
State Idle
StateTime 1272493620
Accepting Yes
Shared Yes
JobSheets ep none
QuotaPeriod 0
PageLimit 0
KLimit 0
OpPolicy default
ErrorPolicy stop-printer
</Printer>

I am not seeing a continue Timeout setting configured as you specified;
Is it recommended that we do so?

Comment 4 Apostolos Pantazis 2011-02-15 02:19:17 UTC

Tim, I am adding another occurrence of the error as well; In fact we are now to the Point that we are getting Multiple of these errors a day across many printers; Restarting the job from the cups web interface does not work either (it says that the job completes but it never does and regardless of the size of the job it "finishes" instantaneously)
 

E [03/Feb/2011:06:20:32 -0800] [Job 31518] Unable to write print data: Broken pipe
D [03/Feb/2011:06:20:32 -0800] Discarding unused printer-state-changed event...
E [03/Feb/2011:06:20:32 -0800] [Job 31518] Unable to write uncompressed document data: Operation not permitted
D [03/Feb/2011:06:20:32 -0800] Discarding unused printer-state-changed event...
E [03/Feb/2011:06:20:32 -0800] PID 22534 (/usr/lib/cups/backend/socket) stopped with status 1!
E [03/Feb/2011:06:20:32 -0800] PID 22535 (/usr/lib/cups/filter/gziptoany) stopped with status 1!
D [03/Feb/2011:06:20:32 -0800] [Job 31518] File 1 is complete.
I [03/Feb/2011:06:20:32 -0800] [Job 31518] Backend returned status 1 (failed)
D [03/Feb/2011:06:20:32 -0800] Discarding unused printer-state-changed event...
D [03/Feb/2011:06:20:32 -0800] Discarding unused printer-stopped event...
I [03/Feb/2011:06:20:32 -0800] Saving printers.conf...
D [03/Feb/2011:06:20:32 -0800] Discarding unused job-stopped event...
D [03/Feb/2011:06:20:33 -0800] [Job 31518] Unloading...
D [03/Feb/2011:06:20:55 -0800] Report: clients=0
D [03/Feb/2011:06:20:55 -0800] Report: jobs=7
D [03/Feb/2011:06:20:55 -0800] Report: jobs-active=7
D [03/Feb/2011:06:20:55 -0800] Report: printers=164
D [03/Feb/2011:06:20:55 -0800] Report: printers-implicit=0
D [03/Feb/2011:06:20:55 -0800] Report: stringpool-string-count=35357
D [03/Feb/2011:06:20:55 -0800] Report: stringpool-alloc-bytes=33448
D [03/Feb/2011:06:20:55 -0800] Report: stringpool-total-bytes=657120
D [03/Feb/2011:06:20:55 -0800] cupsdAcceptClient: skipping getpeercon()

Comment 5 Tim Waugh 2011-02-15 10:50:14 UTC

This small section of the log file is not quite enough -- I'd need to see (for example) all the lines containing "[Job 31518]" to know what went wrong.

Is it possible for you to attach that?

Comment 6 Apostolos Pantazis 2011-02-15 17:26:14 UTC

I [01/Feb/2011:11:06:35 -0800] [Job 26521] Started backend /usr/lib/cups/backend/socket (PID 31518)
D [01/Feb/2011:11:06:40 -0800] PID 31518 (/usr/lib/cups/backend/socket) exited with no errors.
I [03/Feb/2011:05:54:31 -0800] [Job 31518] Adding start banner page "ep".
I [03/Feb/2011:05:54:31 -0800] [Job 31518] Adding job file of type application/vnd.cups-raw.
I [03/Feb/2011:05:54:31 -0800] [Job 31518] Adding end banner page "none".
I [03/Feb/2011:05:54:31 -0800] [Job 31518] Queued on "Paul" by "pauladmin".
D [03/Feb/2011:05:54:31 -0800] [Job 31518] hold_until = 0
D [03/Feb/2011:05:54:31 -0800] [Job 31518] Sending job to queue tagged as raw...
D [03/Feb/2011:05:54:31 -0800] [Job 31518] job-sheets=ep,none
D [03/Feb/2011:05:54:31 -0800] [Job 31518] banner_page = 1
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[0]="Paul"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[1]="31518"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[2]="pauladmin"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[3]="(stdin)"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[4]="1"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[5]="document-name=4d4ab39729a5b finishings=3 job-uuid=urn:uuid:c3b3ed65-20fa-3d60-639e-389c284effbe"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[6]="/var/spool/cups/d31518-001"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[2]="CUPS_DOCROOT=/usr/share/doc/cups-1.3.7"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[8]="LD_LIBRARY_PATH=/usr/local/lib::/lib:/usr/lib:/opt/ibm/db2/V9.7/lib32:/opt/IBM/XMS/lib:/usr/lib/java/jre/lib/ext/x86:/usr/local/axis2c/lib:/usr/X11/lib:/opt/intel/Compiler/lib/ia32"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[10]="SERVER_ADMIN=root@paulhost"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[11]="SOFTWARE=CUPS/1.3.7"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[13]="USER=root"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[14]="CUPS_SERVER=localhost"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[16]="IPP_PORT=631"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[17]="CHARSET=utf-8"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[18]="LANG=en.UTF8"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[19]="PPD=/etc/cups/ppd/Paul.ppd"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[20]="RIP_MAX_CACHE=8m"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[21]="CONTENT_TYPE=text/plain"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[22]="DEVICE_URI=socket://172.21.5.6:9100/"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[23]="PRINTER=Paul"
I [03/Feb/2011:05:54:31 -0800] [Job 31518] Started filter /usr/lib/cups/filter/gziptoany (PID 22533)
I [03/Feb/2011:05:54:31 -0800] [Job 31518] Started backend /usr/lib/cups/backend/socket (PID 22534)
D [03/Feb/2011:05:54:31 -0800] [Job 31518] File 0 is complete.
D [03/Feb/2011:05:54:31 -0800] [Job 31518] Sending job to queue tagged as raw...
D [03/Feb/2011:05:54:31 -0800] [Job 31518] job-sheets=ep,none
D [03/Feb/2011:05:54:31 -0800] [Job 31518] banner_page = 0
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[0]="Paul"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[1]="31518"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[2]="pauladmin"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[3]="(stdin)"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[4]="1"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[5]="document-name=4d4ab39729a5b finishings=3 number-up=1 job-uuid=urn:uuid:c3b3ed65-20fa-3d60-639e-389c284effbe"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] argv[6]="/var/spool/cups/d31518-002"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[2]="CUPS_DOCROOT=/usr/share/doc/cups-1.3.7"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[8]="LD_LIBRARY_PATH=/usr/local/lib::/lib:/usr/lib:/opt/ibm/db2/V9.7/lib32:/opt/IBM/XMS/lib:/usr/lib/java/jre/lib/ext/x86:/usr/local/axis2c/lib:/usr/X11/lib:/opt/intel/Compiler/lib/ia32"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[10]="SERVER_ADMIN=root@paulhost"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[11]="SOFTWARE=CUPS/1.3.7"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[13]="USER=root"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[14]="CUPS_SERVER=localhost"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[16]="IPP_PORT=631"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[17]="CHARSET=utf-8"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[18]="LANG=en.UTF8"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[19]="PPD=/etc/cups/ppd/Paul.ppd"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[20]="RIP_MAX_CACHE=8m"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[21]="CONTENT_TYPE=application/vnd.cups-raw"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[22]="DEVICE_URI=socket://172.21.5.6:9100/"
D [03/Feb/2011:05:54:31 -0800] [Job 31518] envp[23]="PRINTER=Paul"
I [03/Feb/2011:05:54:31 -0800] [Job 31518] Started filter /usr/lib/cups/filter/gziptoany (PID 22535)
D [03/Feb/2011:05:54:31 -0800] [Job 31518] Connected to 172.21.5.6:9100 (IPv4)...
D [03/Feb/2011:05:54:31 -0800] [Job 31518] backendRunLoop(print_fd=0, device_fd=5, use_bc=1, side_cb=0x96ff00)
D [03/Feb/2011:05:54:31 -0800] [Job 31518] Read 8192 bytes of print data...
D [03/Feb/2011:05:54:31 -0800] [Job 31518] Wrote 8192 bytes of print data...
D [03/Feb/2011:05:54:31 -0800] [Job 31518] Read 8192 bytes of print data...
D [03/Feb/2011:05:54:31 -0800] [Job 31518] Wrote 8192 bytes of print data...
D [03/Feb/2011:05:54:31 -0800] [Job 31518] Read 8192 bytes of print data...
D [03/Feb/2011:05:54:33 -0800] [Job 31518] Wrote 8192 bytes of print data...
D [03/Feb/2011:05:54:33 -0800] [Job 31518] Read 8192 bytes of print data...
D [03/Feb/2011:05:54:45 -0800] [Job 31518] Wrote 8192 bytes of print data...
D [03/Feb/2011:05:54:45 -0800] [Job 31518] Read 8192 bytes of print data...
D [03/Feb/2011:05:55:49 -0800] [Job 31518] Wrote 8192 bytes of print data...
D [03/Feb/2011:05:55:49 -0800] [Job 31518] Read 8192 bytes of print data...
E [03/Feb/2011:06:20:32 -0800] [Job 31518] Unable to write print data: Broken pipe
E [03/Feb/2011:06:20:32 -0800] [Job 31518] Unable to write uncompressed document data: Operation not permitted
D [03/Feb/2011:06:20:32 -0800] [Job 31518] File 1 is complete.
I [03/Feb/2011:06:20:32 -0800] [Job 31518] Backend returned status 1 (failed)
D [03/Feb/2011:06:20:33 -0800] [Job 31518] Unloading...
D [03/Feb/2011:07:13:55 -0800] [Job 31518] Loading attributes...
D [03/Feb/2011:07:15:00 -0800] [Job 31518] Unloading...
D [03/Feb/2011:07:18:58 -0800] [Job 31518] Loading attributes...
D [03/Feb/2011:07:20:05 -0800] [Job 31518] Unloading...
D [03/Feb/2011:07:47:51 -0800] [Job 31518] Loading attributes...
D [03/Feb/2011:07:48:58 -0800] [Job 31518] Unloading...
D [03/Feb/2011:10:52:45 -0800] [Job 31518] Loading attributes...
D [03/Feb/2011:10:53:53 -0800] [Job 31518] Unloading...
D [03/Feb/2011:10:54:37 -0800] [Job 31518] Loading attributes...
D [03/Feb/2011:10:55:15 -0800] cupsdReadClient: 10 GET /jobs/?op=restart-job&job_id=31518&job_printer_uri=/printers/nycom6 HTTP/1.1
D [03/Feb/2011:10:55:15 -0800] Restart-Job ipp://localhost/jobs/31518
D [03/Feb/2011:10:55:16 -0800] cupsdReadClient: 10 GET /jobs/?op=restart-job&job_id=31518&job_printer_uri=/printers/nycom6 HTTP/1.1
D [03/Feb/2011:10:55:16 -0800] Restart-Job ipp://localhost/jobs/31518
D [03/Feb/2011:10:55:18 -0800] cupsdReadClient: 10 GET /jobs/?op=restart-job&job_id=31518&job_printer_uri=/printers/nycom6 HTTP/1.1
D [03/Feb/2011:10:55:18 -0800] Restart-Job ipp://localhost/jobs/31518
I [03/Feb/2011:10:55:18 -0800] [Job 31518] Restarted by "root".
D [03/Feb/2011:10:55:23 -0800] cupsdReadClient: 11 GET /jobs/?op=restart-job%26job_id=31518%26job_printer_uri=/printers/nycom6 HTTP/1.1
D [03/Feb/2011:10:56:53 -0800] [Job 31518] Sending job to queue tagged as raw...
D [03/Feb/2011:10:56:53 -0800] [Job 31518] job-sheets=ep,none
D [03/Feb/2011:10:56:53 -0800] [Job 31518] banner_page = 0
D [03/Feb/2011:10:56:53 -0800] [Job 31518] argv[0]="Paul"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] argv[1]="31518"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] argv[2]="pauladmin"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] argv[3]="(stdin)"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] argv[4]="1"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] argv[5]="document-name=4d4ab39729a5b finishings=3 number-up=1 job-uuid=urn:uuid:c3b3ed65-20fa-3d60-639e-389c284effbe"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] argv[6]="/var/spool/cups/d31518-002"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[2]="CUPS_DOCROOT=/usr/share/doc/cups-1.3.7"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[8]="LD_LIBRARY_PATH=/usr/local/lib::/lib:/usr/lib:/opt/ibm/db2/V9.7/lib32:/opt/IBM/XMS/lib:/usr/lib/java/jre/lib/ext/x86:/usr/local/axis2c/lib:/usr/X11/lib:/opt/intel/Compiler/lib/ia32"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[9]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[10]="SERVER_ADMIN=root@paulhost"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[11]="SOFTWARE=CUPS/1.3.7"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[12]="TMPDIR=/var/spool/cups/tmp"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[13]="USER=root"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[14]="CUPS_SERVER=localhost"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[16]="IPP_PORT=631"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[17]="CHARSET=utf-8"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[18]="LANG=en.UTF8"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[19]="PPD=/etc/cups/ppd/Paul.ppd"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[20]="RIP_MAX_CACHE=8m"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[21]="CONTENT_TYPE=application/vnd.cups-raw"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[22]="DEVICE_URI=socket://172.21.5.6:9100/"
D [03/Feb/2011:10:56:53 -0800] [Job 31518] envp[23]="PRINTER=Paul"
I [03/Feb/2011:10:56:53 -0800] [Job 31518] Started filter /usr/lib/cups/filter/gziptoany (PID 19631)
D [03/Feb/2011:10:56:53 -0800] [Job 31518] File 1 is complete.
I [03/Feb/2011:10:56:53 -0800] [Job 31518] Completed successfully.
I [10/Feb/2011:09:34:57 -0800] [Job 44015] Started backend /usr/lib/cups/backend/socket (PID 31518)
D [10/Feb/2011:09:35:02 -0800] PID 31518 (/usr/lib/cups/backend/socket) exited with no errors.
I [11/Feb/2011:14:37:03 -0800] [Job 47238] Started backend /usr/lib/cups/backend/socket (PID 31518)
D [11/Feb/2011:14:37:08 -0800] PID 31518 (/usr/lib/cups/backend/socket) exited with no errors.

Comment 7 Apostolos Pantazis 2011-02-15 17:29:39 UTC

Tim, Let me know if that is better or whether or not you need more details; I would gladly provide.

Also to give you a idea of the frequency of the issue see below:

E [31/Jan/2011:16:58:15 -0800] [Job 25012] Unable to write uncompressed document data: Operation not permitted
E [02/Feb/2011:15:25:17 -0800] [Job 30521] Unable to write uncompressed document data: Operation not permitted
E [03/Feb/2011:06:20:32 -0800] [Job 31518] Unable to write uncompressed document data: Operation not permitted
E [07/Feb/2011:15:42:02 -0800] [Job 36859] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:10:47:03 -0800] [Job 41419] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:10:47:08 -0800] [Job 41422] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:10:54:28 -0800] [Job 41460] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:10:55:46 -0800] [Job 41465] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:20:38 -0800] [Job 41565] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:32:17 -0800] [Job 41595] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:32:27 -0800] [Job 41597] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:32:32 -0800] [Job 41598] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:38:35 -0800] [Job 41645] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:39:16 -0800] [Job 41646] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:51:12 -0800] [Job 41700] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:52:00 -0800] [Job 41701] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:52:00 -0800] [Job 41706] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:52:06 -0800] [Job 41707] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:11:55:50 -0800] [Job 41732] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:08:05 -0800] [Job 41764] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:14:59 -0800] [Job 41797] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:15:12 -0800] [Job 41798] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:15:19 -0800] [Job 41799] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:24:14 -0800] [Job 41845] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:27:22 -0800] [Job 41877] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:30:10 -0800] [Job 41888] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:36:13 -0800] [Job 41901] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:36:19 -0800] [Job 41902] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:52:23 -0800] [Job 41943] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:58:11 -0800] [Job 41958] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:12:59:10 -0800] [Job 41961] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:13:13:44 -0800] [Job 41985] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:13:14:26 -0800] [Job 41986] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:13:14:49 -0800] [Job 41988] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:13:17:51 -0800] [Job 42036] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:13:23:43 -0800] [Job 42049] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:13:26:51 -0800] [Job 42062] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:13:33:48 -0800] [Job 42080] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:13:34:23 -0800] [Job 42086] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:14:15:00 -0800] [Job 42282] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:14:23:50 -0800] [Job 42227] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:14:37:03 -0800] [Job 42357] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:14:37:21 -0800] [Job 42323] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:14:37:26 -0800] [Job 42328] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:13:30 -0800] [Job 42529] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:14:54 -0800] [Job 42539] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:14:59 -0800] [Job 42540] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:15:10 -0800] [Job 42544] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:15:36 -0800] [Job 42534] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:18:09 -0800] [Job 42552] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:20:13 -0800] [Job 42557] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:20:21 -0800] [Job 42558] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:35:43 -0800] [Job 42610] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:36:04 -0800] [Job 42611] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:39:29 -0800] [Job 42621] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:39:48 -0800] [Job 42625] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:45:11 -0800] [Job 42656] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:46:15 -0800] [Job 42662] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:46:20 -0800] [Job 42663] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:49:00 -0800] [Job 42674] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:49:05 -0800] [Job 42675] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:49:10 -0800] [Job 42676] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:53:43 -0800] [Job 42695] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:57:17 -0800] [Job 42708] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:15:58:48 -0800] [Job 42713] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:16:01:04 -0800] [Job 42722] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:16:02:41 -0800] [Job 42729] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:16:04:59 -0800] [Job 42739] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:16:05:20 -0800] [Job 42741] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:17:11:13 -0800] [Job 42997] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:17:13:14 -0800] [Job 43000] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:17:31:58 -0800] [Job 43086] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:17:35:05 -0800] [Job 43034] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:17:36:35 -0800] [Job 43114] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:17:39:27 -0800] [Job 43118] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:17:44:49 -0800] [Job 43132] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:17:46:05 -0800] [Job 43136] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:17:47:36 -0800] [Job 43146] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:18:20:08 -0800] [Job 43196] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:19:37:09 -0800] [Job 43301] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:19:37:40 -0800] [Job 43302] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:19:51:43 -0800] [Job 43321] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:19:53:41 -0800] [Job 43327] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:19:58:24 -0800] [Job 43333] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:20:03:51 -0800] [Job 43341] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:20:08:08 -0800] [Job 43346] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:20:08:50 -0800] [Job 43348] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:20:08:55 -0800] [Job 43349] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:21:30:28 -0800] [Job 43427] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:21:34:36 -0800] [Job 43438] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:21:34:46 -0800] [Job 43441] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:21:40:59 -0800] [Job 43471] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:21:41:04 -0800] [Job 43472] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:21:41:09 -0800] [Job 43473] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:21:47:35 -0800] [Job 43478] Unable to write uncompressed document data: Operation not permitted
E [09/Feb/2011:21:49:09 -0800] [Job 43480] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:06:10:13 -0800] [Job 43543] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:28:39 -0800] [Job 43784] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:39:32 -0800] [Job 43817] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:52:48 -0800] [Job 43845] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:53:05 -0800] [Job 43847] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:53:11 -0800] [Job 43848] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:53:17 -0800] [Job 43849] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:53:23 -0800] [Job 43850] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:53:42 -0800] [Job 43853] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:53:48 -0800] [Job 43854] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:08:59:35 -0800] [Job 43858] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:09:04:00 -0800] [Job 43874] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:09:06:01 -0800] [Job 43880] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:09:14:35 -0800] [Job 43925] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:09:15:08 -0800] [Job 43930] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:09:17:34 -0800] [Job 43943] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:09:29:43 -0800] [Job 43959] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:09:43:24 -0800] [Job 44045] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:09:43:30 -0800] [Job 44047] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:00:42 -0800] [Job 44085] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:00:47 -0800] [Job 44086] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:01:03 -0800] [Job 44089] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:01:08 -0800] [Job 44090] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:01:24 -0800] [Job 44093] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:01:29 -0800] [Job 44094] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:01:45 -0800] [Job 44097] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:01:50 -0800] [Job 44098] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:02:05 -0800] [Job 44101] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:02:10 -0800] [Job 44102] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:02:26 -0800] [Job 44105] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:02:31 -0800] [Job 44106] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:02:46 -0800] [Job 44110] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:02:52 -0800] [Job 44111] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:03:02 -0800] [Job 44113] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:03:07 -0800] [Job 44114] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:03:12 -0800] [Job 44115] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:20:10 -0800] [Job 44271] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:23:16 -0800] [Job 44287] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:23:29 -0800] [Job 44292] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:23:34 -0800] [Job 44293] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:29:21 -0800] [Job 44322] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:29:26 -0800] [Job 44323] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:29:31 -0800] [Job 44324] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:35:40 -0800] [Job 44337] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:35:54 -0800] [Job 44339] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:35:59 -0800] [Job 44340] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:36:56 -0800] [Job 44351] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:37:01 -0800] [Job 44352] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:37:06 -0800] [Job 44353] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:37:17 -0800] [Job 44355] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:37:22 -0800] [Job 44356] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:46:56 -0800] [Job 44468] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:48:44 -0800] [Job 44490] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:48:59 -0800] [Job 44498] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:10:58:54 -0800] [Job 44538] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:11:07:43 -0800] [Job 44600] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:11:12:39 -0800] [Job 44623] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:11:17:21 -0800] [Job 44635] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:11:22:08 -0800] [Job 44656] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:11:24:50 -0800] [Job 44669] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:11:27:58 -0800] [Job 44690] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:11:28:18 -0800] [Job 44692] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:11:49:05 -0800] [Job 44768] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:11:52:20 -0800] [Job 44777] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:12:19:05 -0800] [Job 44878] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:12:38:37 -0800] [Job 44914] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:12:52:16 -0800] [Job 44947] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:12:52:21 -0800] [Job 44948] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:12:52:26 -0800] [Job 44949] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:35:52 -0800] [Job 45071] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:37:07 -0800] [Job 45077] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:37:21 -0800] [Job 45050] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:52:45 -0800] [Job 45131] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:52:51 -0800] [Job 45132] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:53:02 -0800] [Job 45135] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:55:23 -0800] [Job 45150] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:56:12 -0800] [Job 45156] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:56:17 -0800] [Job 45158] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:59:52 -0800] [Job 45075] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:13:59:57 -0800] [Job 45119] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:14:00:02 -0800] [Job 45125] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:14:00:08 -0800] [Job 45126] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:14:00:14 -0800] [Job 45133] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:14:23:46 -0800] [Job 45282] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:14:48:53 -0800] [Job 45374] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:14:49:04 -0800] [Job 45375] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:14:49:10 -0800] [Job 45376] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:14:50:00 -0800] [Job 45399] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:15:34:26 -0800] [Job 45596] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:15:37:35 -0800] [Job 45611] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:15:38:33 -0800] [Job 45606] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:15:41:47 -0800] [Job 45621] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:15:41:52 -0800] [Job 45622] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:15:41:57 -0800] [Job 45623] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:15:42:22 -0800] [Job 45626] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:16:36:02 -0800] [Job 45763] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:16:42:17 -0800] [Job 45826] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:16:43:32 -0800] [Job 45822] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:16:57:28 -0800] [Job 45874] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:17:04:45 -0800] [Job 45894] Unable to write uncompressed document data: Operation not permitted
E [10/Feb/2011:17:43:18 -0800] [Job 45993] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:12:27:12 -0800] [Job 46953] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:12:27:16 -0800] [Job 46952] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:12:42:17 -0800] [Job 46973] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:13:23:28 -0800] [Job 47053] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:13:42:12 -0800] [Job 47088] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:14:33:02 -0800] [Job 47211] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:14:42:30 -0800] [Job 47258] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:14:46:35 -0800] [Job 47275] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:15:21:01 -0800] [Job 47373] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:15:21:06 -0800] [Job 47374] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:15:45:05 -0800] [Job 47407] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:22:48 -0800] [Job 47483] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:22:54 -0800] [Job 47484] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:28:40 -0800] [Job 47501] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:28:50 -0800] [Job 47470] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:28:57 -0800] [Job 47502] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:29:39 -0800] [Job 47478] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:31:08 -0800] [Job 47480] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:33:26 -0800] [Job 47522] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:35:22 -0800] [Job 47532] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:38:05 -0800] [Job 47539] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:16:59:34 -0800] [Job 47593] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:17:10:10 -0800] [Job 47601] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:17:30:41 -0800] [Job 47655] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:17:47:09 -0800] [Job 47686] Unable to write uncompressed document data: Operation not permitted
E [11/Feb/2011:17:47:19 -0800] [Job 47688] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:06:55:37 -0800] [Job 47738] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:08:18:07 -0800] [Job 47824] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:08:21:17 -0800] [Job 47808] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:08:30:36 -0800] [Job 47870] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:08:32:28 -0800] [Job 47826] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:08:32:33 -0800] [Job 47869] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:08:33:59 -0800] [Job 47873] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:08:49:40 -0800] [Job 47951] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:09:01:05 -0800] [Job 47984] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:10:08:24 -0800] [Job 48349] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:10:12:38 -0800] [Job 48357] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:10:33:25 -0800] [Job 48435] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:10:34:01 -0800] [Job 48437] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:11:03:54 -0800] [Job 48601] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:11:17:10 -0800] [Job 48659] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:11:28:22 -0800] [Job 48693] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:11:30:21 -0800] [Job 48687] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:11:30:26 -0800] [Job 48694] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:11:30:45 -0800] [Job 48706] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:11:32:53 -0800] [Job 48715] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:12:00:48 -0800] [Job 48780] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:12:22:32 -0800] [Job 48857] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:12:22:37 -0800] [Job 48858] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:12:25:17 -0800] [Job 48877] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:12:26:26 -0800] [Job 48883] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:12:35:02 -0800] [Job 48905] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:12:51:32 -0800] [Job 48931] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:12:58:56 -0800] [Job 48968] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:13:05:11 -0800] [Job 48976] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:13:07:17 -0800] [Job 48983] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:13:07:22 -0800] [Job 48984] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:13:09:35 -0800] [Job 48993] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:13:17:31 -0800] [Job 49018] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:14:03:12 -0800] [Job 49177] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:14:47:21 -0800] [Job 49298] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:14:47:32 -0800] [Job 49300] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:14:47:36 -0800] [Job 49305] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:14:48:55 -0800] [Job 49290] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:14:54:10 -0800] [Job 49335] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:23:41 -0800] [Job 49415] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:23:56 -0800] [Job 49420] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:32:53 -0800] [Job 49444] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:33:00 -0800] [Job 49449] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:33:34 -0800] [Job 49453] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:36:48 -0800] [Job 49469] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:39:49 -0800] [Job 49492] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:41:27 -0800] [Job 49503] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:43:14 -0800] [Job 49515] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:49:21 -0800] [Job 49487] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:54:33 -0800] [Job 49567] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:54:48 -0800] [Job 49572] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:56:27 -0800] [Job 49587] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:56:53 -0800] [Job 49598] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:59:12 -0800] [Job 49621] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:59:40 -0800] [Job 49591] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:15:59:46 -0800] [Job 49602] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:05:28 -0800] [Job 49663] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:05:51 -0800] [Job 49670] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:06:33 -0800] [Job 49649] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:09:29 -0800] [Job 49685] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:09:39 -0800] [Job 49686] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:09:44 -0800] [Job 49687] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:09:52 -0800] [Job 49688] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:10:03 -0800] [Job 49650] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:10:15 -0800] [Job 49692] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:12:30 -0800] [Job 49678] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:12:35 -0800] [Job 49698] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:12:40 -0800] [Job 49699] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:45:48 -0800] [Job 49788] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:54:25 -0800] [Job 49817] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:55:03 -0800] [Job 49820] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:16:55:12 -0800] [Job 49821] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:17:20:32 -0800] [Job 49889] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:17:42:02 -0800] [Job 49957] Unable to write uncompressed document data: Operation not permitted
E [14/Feb/2011:17:42:29 -0800] [Job 49960] Unable to write uncompressed document data: Operation not permitted

Comment 8 Apostolos Pantazis 2011-02-16 21:11:13 UTC

FYI, on a different environment (not the production that is configured as described above), I am experimenting with the following upgrades:

Upgraded cups to:
cups-1.3.7-26.el5.i386.rpm
cups-libs-1.3.7-26.el5.i386.rpm

I am trying to test and see if I can replicate the issue there; I believe the following updates are included with this new version of cups:

RHBA-2011:0185 
RHBA-2011:0095 
RHSA-2010:0866 
RHSA-2010:0811 
RHSA-2010:0754 
RHSA-2010:0755 
RHBA-2010:0614 
RHSA-2010:0490 
RHBA-2010:0210 

Its a stab in the dark and I still appreciate your efforts in troubleshooting under the original config the error was reported with.

Paul

Comment 10 Tim Waugh 2011-02-18 11:52:09 UTC

This is the cause of the problem:

E [03/Feb/2011:06:20:32 -0800] [Job 31518] Unable to write print data: Broken pipe

It comes from the socket backend.

The printer has reset the connection during the job transmission, so the socket backend has exited.  This causes the gziptoany filter to fail when writing its output to the pipe.

The question is why the printer reset the connection.

If it occurs intermittently, it seems not to be as a result of the content of the job.

Are these jobs all going to the same printer, or different printers?  Are they the same model?  It might be worth checking to see if there is a firmware update available as a first step.

The next thing to examine is the TCP traffic between the CUPS server and the printer at the moment the connection is reset.  Would it be possible for you to run this command to capture that?:

tcpdump -nl host 172.21.5.6 port 9100 | tee jetdirect.txt

One a job fails with 'Broken pipe', we should be able to match up the timestamps and see what actually happened in the TCP stream.

Comment 12 Apostolos Pantazis 2011-02-18 17:11:01 UTC

Are these jobs all going to the same printer, or different printers?  Are they
the same model?  It might be worth checking to see if there is a firmware
update available as a first step.

Tim, this is happening across many different printers of different models (Remember we have approximately 165 Printers]

We can look at firmware for some of the,

I would be glad to gather a tcpdump; Since I dont know when this is going to happen next as soon as I see a instance of the error bubble up via our alerting mechanisms I will start collecting; Chances are there will be another back to back.

Tim, is it possible on a busy box (one that has a relatively high load average at certain points in time) that this behavior (cups socket resets) is experienced?

Thanks

Comment 13 Tim Waugh 2011-02-24 10:53:04 UTC

Without seeing the TCP traffic it's hard to know where the problem comes from.  Anything is possible, of course, but I wouldn't expect high load on the CUPS server to cause that problem.

The socket backend is seeing write() fail with errno set to EPIPE.  That means the socket is shut down for writing (well, we don't do that) or is no longer connected.  It strongly suggests that the connection was reset by the printer.

Comment 14 Tim Waugh 2011-03-07 16:39:52 UTC

Setting needinfo flag for tcpdump output.

Comment 15 Apostolos Pantazis 2011-03-08 01:02:45 UTC

Our printing subsystem has been very stable since the upgrade described in comment (8); For the time being I would like to continue monitoring for a additional (2) weeks and assuming the issue does not repeat itself (it has not in 3 weeks now) Then we can close this bug with upgrade as the resolution.

If the issues occurs again I will upload a TCPDump.

Thank you.

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