Long Delays (ca. 40 secs) with CUPS 1.3.7

Mon May 7 05:40:08 PDT 2012

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