[cups.general] Long Delays (ca. 40 secs) with CUPS 1.3.7

Mon May 7 07:04:31 PDT 2012

Mathias,

This is probably either the SNMP supply level stuff or the wait-for-backchannel-data stuff. Both have been resolved in later releases of CUPS.

On May 7, 2012, at 5:40 AM, Mathias Vaterlaus <m.vaterlaus at propharma.ch> wrote:

> Hi,
> I have a Problem with CUPS v 1.3.7. I upgraded to this version for installing the foomatic-filters v 4.0.5. The problems i have encountered is, that our label printers print with a hughe delay, when they are connected via a socket. we use raw printer queues for the label printers, so we don't use the printer with a ppd file.
> The current system is a LFS with kernel 2.4.25 and libc 2.2.4. Since the OS is an LFS, i compiled CUPS manually and installed it with the 'make install' command. Following is a short section out of the log files:
> 
> 
> bash-2.05a# cat /var/log/cups/error_log | grep -i socket
> D [04/May/2012:14:55:05 +0200] [Job 1021060] envp[21]="DEVICE_URI=socket://at1:3003"
> I [04/May/2012:14:55:05 +0200] [Job 1021060] Started backend /usr/lib/cups/backend/socket (PID 321)
> D [04/May/2012:14:55:50 +0200] PID 321 (/usr/lib/cups/backend/socket) exited with no errors.
> 
> 
> You will notice a delay of 45 seconds between the start and finishing of the job. The following section is the whole tracelog of one print job, with log level debug enabled in CUPS.
> 
> 
> D [04/May/2012:15:30:44 +0200] [Job 1021065] Sending job to queue tagged as raw...
> D [04/May/2012:15:30:44 +0200] Discarding unused printer-state-changed event...
> D [04/May/2012:15:30:44 +0200] [Job 1021065] job-sheets=none,none
> D [04/May/2012:15:30:44 +0200] [Job 1021065] banner_page = 0
> D [04/May/2012:15:30:44 +0200] [Job 1021065] argv[0]="apar"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] argv[1]="1021065"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] argv[2]="pdata"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] argv[3]="/tmp/dosetk33GaUnaz8zdq"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] argv[4]="1"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] argv[5]="finishings=3 number-up=1 job-uuid=urn:uuid:81eed53d-6188-3e95-6277-322b3031f0e8"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] argv[6]="/var/spool/cups/d1021065-001"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[1]="CUPS_DATADIR=/usr/share/cups"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[2]="CUPS_DOCROOT=/usr/share/doc/cups"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[6]="CUPS_SERVERROOT=/etc/cups"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[7]="CUPS_STATEDIR=/var/run/cups"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[9]="SERVER_ADMIN=root at centraltst"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[10]="SOFTWARE=CUPS/1.3.7"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[11]="TMPDIR=/var/spool/cups/tmp"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[12]="USER=root"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[13]="CUPS_SERVER=/usr/var/run/cups/cups.sock"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[14]="CUPS_ENCRYPTION=IfRequested"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[15]="IPP_PORT=631"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[16]="CHARSET=utf-8"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[17]="LANG=de_CH.UTF8"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[18]="PPD=/etc/cups/ppd/apar.ppd"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[19]="RIP_MAX_CACHE=8m"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[20]="CONTENT_TYPE=application/vnd.cups-raw"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[21]="DEVICE_URI=socket://at1:3003"
> D [04/May/2012:15:30:44 +0200] [Job 1021065] envp[22]="PRINTER=apar"
> I [04/May/2012:15:30:44 +0200] [Job 1021065] Started backend /usr/lib/cups/backend/socket (PID 310)
> D [04/May/2012:15:30:44 +0200] Discarding unused job-state-changed event...
> D [04/May/2012:15:30:45 +0200] [Job 1021064] Unloading...
> D [04/May/2012:15:31:18 +0200] Report: clients=0
> D [04/May/2012:15:31:18 +0200] Report: jobs=62
> D [04/May/2012:15:31:18 +0200] Report: jobs-active=1
> D [04/May/2012:15:31:18 +0200] Report: printers=3
> D [04/May/2012:15:31:18 +0200] Report: printers-implicit=0
> D [04/May/2012:15:31:18 +0200] Report: stringpool-string-count=756
> D [04/May/2012:15:31:18 +0200] Report: stringpool-alloc-bytes=7256
> D [04/May/2012:15:31:18 +0200] Report: stringpool-total-bytes=14728
> D [04/May/2012:15:31:24 +0200] Discarding unused printer-state-changed event...
> D [04/May/2012:15:31:24 +0200] [Job 1021065] Connected to 10.54.117.7:3003 (IPv4)...
> D [04/May/2012:15:31:24 +0200] Discarding unused job-progress event...
> D [04/May/2012:15:31:24 +0200] [Job 1021065] backendRunLoop(print_fd=5, device_fd=6, use_bc=1, side_cb=0x804959c)
> D [04/May/2012:15:31:24 +0200] [Job 1021065] Read 547 bytes of print data...
> D [04/May/2012:15:31:24 +0200] [Job 1021065] Wrote 547 bytes of print data...
> D [04/May/2012:15:31:24 +0200] Discarding unused printer-state-changed event...
> D [04/May/2012:15:31:29 +0200] Discarding unused printer-state-changed event...
> D [04/May/2012:15:31:29 +0200] Discarding unused printer-state-changed event...
> D [04/May/2012:15:31:29 +0200] PID 310 (/usr/lib/cups/backend/socket) exited with no errors.
> D [04/May/2012:15:31:29 +0200] [Job 1021065] File 0 is complete.
> I [04/May/2012:15:31:29 +0200] [Job 1021065] Completed successfully.
> D [04/May/2012:15:31:29 +0200] Discarding unused printer-state-changed event...
> D [04/May/2012:15:31:29 +0200] Discarding unused job-completed event...
> D [04/May/2012:15:31:30 +0200] [Job 1021065] Unloading...
> 
> 
> To overcome this problem, I tried the following approaches:
> 
> * Setting the ULR for the printers socket://$url/?waiteof=false
> * set MaxRunTime = 1 in snmp.conf
> * disabling the snmp backend with chmod 0 /usr/lib/cups/backend/snmp
> * activating the application/octet-stram line in /etc/cups/mime.convs
> * changing the value of waiteof = false in backend/socket.c at line 172
> * changing the value timeout.tv_sec = 0 in backend/socket.c at line 509
> 
> Because none of the approaches did work, I need another idea to solve this problem. I would really appreciate, if someone could guide me onto the right direction. If you need any other information about this problem, just ask and I will provide them.
> 
> 
> Greetings
> 
> Mathias
> _______________________________________________
> cups mailing list
> cups at easysw.com
> http://lists.easysw.com/mailman/listinfo/cups

__________________________________________________
Michael Sweet, Senior Printing System Engineer, PWG Chair