Long Delays (ca. 40 secs) with CUPS 1.3.7

Thu Jun 7 06:51:21 PDT 2012

Sorry for not reporting back earlier, but we had a lot of work. I will try to use a newer version, but i can not tell if this will work, because i can not upgrade the build environment. This is because of our own developed application which is very sensitive when updating the build environment. I will report back, if I have any luck in getting it working.

> 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
>