Bug#758284: cups-daemon: IdleExitTimeout is unreliable

To: 758284@bugs.debian.org
Subject: Bug#758284: cups-daemon: IdleExitTimeout is unreliable
From: Brian Potkin <claremont102@gmail.com>
Date: Mon, 15 Sep 2014 23:47:49 +0100
Message-id: <[🔎] 15092014223834.a828b45f86a8@desktop.copernicus.demon.co.uk>
Reply-to: Brian Potkin <claremont102@gmail.com>, 758284@bugs.debian.org
In-reply-to: <16082014102308.6065a40fbbc9@desktop.copernicus.demon.co.uk>
References: <16082014102308.6065a40fbbc9@desktop.copernicus.demon.co.uk>

On Sat 16 Aug 2014 at 10:30:10 +0100, Brian Potkin wrote:

> I=IdleExitTimeout
> t=time for cups to become inactive after cups reports 'Job completed'.
> 
> For I > 30s, t=I+30.
> For I < 30s, t=I.
> For I = 30s it appears to be a toss up whether it is I or I+30.

Lets take a closer look at an error_log when LogLevel is debug2 and
I=40 seconds.

  I [15/Sep/2014:22:31:37 +0100] [Job 1] Job completed.
  D [15/Sep/2014:22:31:37 +0100] cupsdMarkDirty(---J-)
  D [15/Sep/2014:22:31:37 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
  D [15/Sep/2014:22:31:37 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
  d [15/Sep/2014:22:31:37 +0100] cupsdAddEvent(event=printer-state-changed, dest=0xb7a66e68(TESTIET), job=(nil)(0), text="%s "%s" state changed to %s.", ...)
  D [15/Sep/2014:22:31:37 +0100] Discarding unused printer-state-changed event...
  d [15/Sep/2014:22:31:37 +0100] cupsdSetPrinterReasons(p=0xb7a66e68(TESTIET),s="-paused"
  D [15/Sep/2014:22:31:37 +0100] cupsdMarkDirty(---J-)
  D [15/Sep/2014:22:31:37 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
  d [15/Sep/2014:22:31:37 +0100] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0, curtime=1410816697
  d [15/Sep/2014:22:31:37 +0100] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0, curtime=1410816697
  d [15/Sep/2014:22:31:37 +0100] select_timeout: JobHistoryUpdate=1410903097
  D [15/Sep/2014:22:31:37 +0100] cupsd is not idle any more, canceling shutdown.
  d [15/Sep/2014:22:31:38 +0100] cupsdSaveJob(job=0xb7aae630(1)): job->attrs=0xb7a6c7a0
  D [15/Sep/2014:22:31:38 +0100] [Job 1] Unloading...
  d [15/Sep/2014:22:31:38 +0100] select_timeout: JobHistoryUpdate=1410903097
  d [15/Sep/2014:22:31:38 +0100] select_timeout(0): 30 seconds to write dirty config/state files
**  D [15/Sep/2014:22:31:38 +0100] cupsd is not idle any more, canceling shutdown.
**  I [15/Sep/2014:22:32:08 +0100] Saving job.cache...
  D [15/Sep/2014:22:32:08 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files"
  d [15/Sep/2014:22:32:08 +0100] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0, curtime=1410816728
  qd [15/Sep/2014:22:32:08 +0100] select_timeout: JobHistoryUpdate=1410903097
  d [15/Sep/2014:22:32:08 +0100] select_timeout(0): 86370 seconds to update job history
  D [15/Sep/2014:22:32:08 +0100] cupsd is idle, scheduling shutdown in 40 seconds.
  I [15/Sep/2014:22:32:48 +0100] Printer sharing is off and there are no jobs pending, shutting down for now.
  I [15/Sep/2014:22:32:48 +0100] Scheduler shutting down normally.

Again we see the 30 second delay at the lines marked **. However, the
line to concentrate on is the one immediately prior to these two.

    d [15/Sep/2014:22:31:38 +0100] select_timeout(0): 30 seconds to write dirty config/state files

I have no idea what it means and do not know whether the 30 seconds is
fixed within cups or dynamically generated. I also do not understand
coding in C. But I am ace at fiddling. :)

The file cupsd-idleexittimeout.patch has

       if ((timeout = select_timeout(fds)) > 1 && LastEvent)
         timeout = 1;

  +   /*
  +    * If no other work is scheduled and we've set the exit-on-idle timeout
  +    * then timeout after 'IdleExitTimeout' seconds of inactivity...
  +    */
  +
  +    if (IdleExitTimeout && timeout >= IdleExitTimeout &&
  +        !cupsArrayCount(ActiveJobs) &&
  +       (!Browsing || !BrowseLocalProtocols || !cupsArrayCount(Printers)))

We'll change

		timeout >= IdleExitTimeout

to

		timeout <= IdleExitTimeout

in scheduler/main.c, refresh the patch and rebuild cups.

The outcome is that the 30 second delay goes away for I > 30s and cups
becomes inactive after a time set by I and for any value of I.

I'll not offer this as a definitive solution but as an indication of
where the solution might lie. An error_log extract follows.

  I [15/Sep/2014:23:31:13 +0100] [Job 6] Job completed.
  D [15/Sep/2014:23:31:13 +0100] cupsdMarkDirty(---J-)
  D [15/Sep/2014:23:31:13 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
  D [15/Sep/2014:23:31:13 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
  d [15/Sep/2014:23:31:13 +0100] cupsdAddEvent(event=printer-state-changed, dest=0xb8250e68(TESTIET), job=(nil)(0), text="%s "%s" state changed to %s.", ...)
  d [15/Sep/2014:23:31:13 +0100] cupsd_send_notification(sub=0xb825fdc8(7), event=0xb8264178(printer-state-changed))
  d [15/Sep/2014:23:31:13 +0100] sub->pipe=18
  D [15/Sep/2014:23:31:13 +0100] cupsdMarkDirty(----S)
  D [15/Sep/2014:23:31:13 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
  d [15/Sep/2014:23:31:13 +0100] cupsdSetPrinterReasons(p=0xb8250e68(TESTIET),s="-paused"
  D [15/Sep/2014:23:31:13 +0100] cupsdMarkDirty(---J-)
  D [15/Sep/2014:23:31:13 +0100] cupsdSetBusyState: newbusy="Printing jobs and dirty files", busy="Printing jobs and dirty files"
  d [15/Sep/2014:23:31:13 +0100] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0, curtime=1410820273
  d [15/Sep/2014:23:31:13 +0100] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0, curtime=1410820273
  d [15/Sep/2014:23:31:13 +0100] select_timeout: JobHistoryUpdate=1410906673
  D [15/Sep/2014:23:31:13 +0100] cupsd is idle, scheduling shutdown in 40 seconds.
  D [15/Sep/2014:23:31:13 +0100] [Notifier] state=3
  D [15/Sep/2014:23:31:13 +0100] [Notifier] JobCompleted
  D [15/Sep/2014:23:31:13 +0100] [Notifier] state=3
  D [15/Sep/2014:23:31:13 +0100] [Notifier] PrinterStateChanged
  d [15/Sep/2014:23:31:13 +0100] select_timeout: JobHistoryUpdate=1410906673
  D [15/Sep/2014:23:31:13 +0100] cupsd is idle, scheduling shutdown in 40 seconds.
  I [15/Sep/2014:23:31:53 +0100] Saving job.cache...
  d [15/Sep/2014:23:31:53 +0100] cupsdSaveJob(job=0xb826b0b8(6)): job->attrs=0xb829f030
  I [15/Sep/2014:23:31:53 +0100] Saving subscriptions.conf...
  D [15/Sep/2014:23:31:53 +0100] cupsdSetBusyState: newbusy="Not busy", busy="Printing jobs and dirty files"
  I [15/Sep/2014:23:31:53 +0100] Printer sharing is off and there are no jobs pending, shutting down for now.
  I [15/Sep/2014:23:31:53 +0100] Scheduler shutting down normally.

Regards,

Brian.

Reply to:

Follow-Ups:
- Bug#758284: cups-daemon: IdleExitTimeout aappears to be unreliable
  - From: Brian Potkin <claremont102@gmail.com>

Prev by Date: Bug#761316: printer-driver-splix depends on ghostscript-cups, which is not built anymore by src:ghostscript
Next by Date: Processed: epstool: crashes
Previous by thread: Bug#761316: marked as done (printer-driver-splix depends on ghostscript-cups, which is not built anymore by src:ghostscript)
Next by thread: Bug#758284: cups-daemon: IdleExitTimeout aappears to be unreliable
Index(es):
- Date
- Thread