cupsd wakes up the hard disk every 14 minutes

[Hao-Ran Liu]

cupsd calls fsync() on /etc/subscriptions.conf.N every 14~15 minutes. This causes the hard disk to wake up soon after it spins down. Subscription renewal is from indicator-printers every 15 minutes.

I think we don't need cupsdRemoveFile() to always overwrite data and do a fsync() for this file. Currently only Precise is confirmed to be affected. Saucy seems not having the same issue according to
(http://bazaar.launchpad.net/~ubuntu-branches/ubuntu/saucy/cups/saucy/view/head:/scheduler/file.c#L149)

---- block_dump from the kernel ----
<7>[19935.646436] cupsd(1066): dirtied inode 15336755 (subscriptions.conf.N) on sda3
<7>[19935.646673] cupsd(1066): WRITE block 352753016 on sda3 (8 sectors)
<7>[19935.646755] cupsd(1066): dirtied inode 15335603 (?) on sda3
<7>[19935.646763] cupsd(1066): dirtied inode 15335603 (?) on sda3
<7>[19935.646776] cupsd(1066): WRITE block 352701128 on sda3 (8 sectors)
<7>[20774.607856] cupsd(1066): dirtied inode 15335603 (subscriptions.conf.N) on sda3
<7>[20774.608034] cupsd(1066): WRITE block 352862776 on sda3 (8 sectors)
<7>[20774.608113] cupsd(1066): dirtied inode 15335607 (?) on sda3
<7>[20774.608120] cupsd(1066): dirtied inode 15335607 (?) on sda3
<7>[20774.608133] cupsd(1066): WRITE block 352753008 on sda3 (8 sectors)
<7>[21613.569033] cupsd(1066): dirtied inode 15335607 (subscriptions.conf.N) on sda3
<7>[21613.569257] cupsd(1066): WRITE block 352753024 on sda3 (8 sectors)
<7>[21613.569345] cupsd(1066): dirtied inode 15336755 (?) on sda3
<7>[21613.569353] cupsd(1066): dirtied inode 15336755 (?) on sda3
<7>[21613.569367] cupsd(1066): WRITE block 352753016 on sda3 (8 sectors)

---- cups: scheduler/file.c ----
int /* O - 0 on success, -1 on error */
cupsdCloseCreatedConfFile(
    cups_file_t *fp, /* I - File to close */
    const char *filename) /* I - Filename */
{
...
  snprintf(newfile, sizeof(newfile), "%s.N", filename);
  snprintf(oldfile, sizeof(oldfile), "%s.O", filename);

  if ((cupsdRemoveFile(oldfile) && errno != ENOENT) ||
      (rename(filename, oldfile) && errno != ENOENT) ||
      rename(newfile, filename))
  {
    cupsdLogMessage(CUPSD_LOG_ERROR, "Unable to finalize \"%s\": %s",
                    filename, strerror(errno));
    return (-1);
  }

  return (0);
}

int /* O - 0 on success, -1 on error */
cupsdRemoveFile(const char *filename) /* I - File to remove */
{
...
 /*
  * Overwrite the file 7 times with 0xF6, 0x00, 0xFF, random, 0x00, 0xFF,
  * and more random data.
  */

  memset(buffer, 0xF6, sizeof(buffer));
  if (overwrite_data(fd, buffer, sizeof(buffer), (int)info.st_size))
  {
    close(fd);
    return (-1);
  }
...
}

static int /* O - 0 on success, -1 on error */
overwrite_data(int fd, /* I - File descriptor */
               const char *buffer, /* I - Buffer to write */
        int bufsize, /* I - Size of buffer */
               int filesize) /* I - Size of file */
{
  int bytes; /* Bytes to write/written */

 /*
  * Start at the beginning of the file...
  */

  if (lseek(fd, 0, SEEK_SET) < 0)
    return (-1);

 /*
  * Fill the file with the provided data...
  */

  while (filesize > 0)
  {
    if (filesize > bufsize)
      bytes = bufsize;
    else
      bytes = filesize;

    if ((bytes = write(fd, buffer, bytes)) < 0)
      return (-1);

    filesize -= bytes;
  }

 /*
  * Force the changes to disk...
  */

  return (fsync(fd));
}

---- indicator-printers-service.c ----
#define NOTIFY_LEASE_DURATION (15 * 60)

int main (int argc, char *argv[])
{
...
    g_timeout_add_seconds (NOTIFY_LEASE_DURATION - 60,
                           renew_subscription_timeout,
                           &subscription_id);
...
}

[Till Kamppeter (till-kamppeter)]

Mike, can you have a look into this? The CUPS currently in Ubuntu 13.10 (Saucy, CUPS 1.7rc1) does not show this problem, but the CUPS in 12.04 LTS (Precise, CUPS 1.5.3) has this problem of an subscription renewal constantly waking up the system. Can you tell us which change fixed this, so that we can backport this change? Thanks.

[Michael R Sweet (msweet)]

Make up your mind. You want sync. You don't want sync.

There is no reason to renew a subscription every 15 minutes. Stop doing that and this problem goes away.

On Oct 30, 2013, at 12:58 PM, Launchpad Bug Tracker <email address hidden> wrote:

> You have been subscribed to a public bug by Till Kamppeter (till-kamppeter):
>
> cupsd calls fsync() on /etc/subscriptions.conf.N every 14~15 minutes.
> This causes the hard disk to wake up soon after it spins down.
> Subscription renewal is from indicator-printers every 15 minutes.
>
> I think we don't need cupsdRemoveFile() to always overwrite data and do a fsync() for this file. Currently only Precise is confirmed to be affected. Saucy seems not having the same issue according to
> (http://bazaar.launchpad.net/~ubuntu-branches/ubuntu/saucy/cups/saucy/view/head:/scheduler/file.c#L149)
>
> ---- block_dump from the kernel ----
> <7>[19935.646436] cupsd(1066): dirtied inode 15336755 (subscriptions.conf.N) on sda3
> <7>[19935.646673] cupsd(1066): WRITE block 352753016 on sda3 (8 sectors)
> <7>[19935.646755] cupsd(1066): dirtied inode 15335603 (?) on sda3
> <7>[19935.646763] cupsd(1066): dirtied inode 15335603 (?) on sda3
> <7>[19935.646776] cupsd(1066): WRITE block 352701128 on sda3 (8 sectors)
> <7>[20774.607856] cupsd(1066): dirtied inode 15335603 (subscriptions.conf.N) on sda3
> <7>[20774.608034] cupsd(1066): WRITE block 352862776 on sda3 (8 sectors)
> <7>[20774.608113] cupsd(1066): dirtied inode 15335607 (?) on sda3
> <7>[20774.608120] cupsd(1066): dirtied inode 15335607 (?) on sda3
> <7>[20774.608133] cupsd(1066): WRITE block 352753008 on sda3 (8 sectors)
> <7>[21613.569033] cupsd(1066): dirtied inode 15335607 (subscriptions.conf.N) on sda3
> <7>[21613.569257] cupsd(1066): WRITE block 352753024 on sda3 (8 sectors)
> <7>[21613.569345] cupsd(1066): dirtied inode 15336755 (?) on sda3
> <7>[21613.569353] cupsd(1066): dirtied inode 15336755 (?) on sda3
> <7>[21613.569367] cupsd(1066): WRITE block 352753016 on sda3 (8 sectors)
>
> ---- cups: scheduler/file.c ----
> int /* O - 0 on success, -1 on error */
> cupsdCloseCreatedConfFile(
> cups_file_t *fp, /* I - File to close */
> const char *filename) /* I - Filename */
> {
> ...
> snprintf(newfile, sizeof(newfile), "%s.N", filename);
> snprintf(oldfile, sizeof(oldfile), "%s.O", filename);
>
> if ((cupsdRemoveFile(oldfile) && errno != ENOENT) ||
> (rename(filename, oldfile) && errno != ENOENT) ||
> rename(newfile, filename))
> {
> cupsdLogMessage(CUPSD_LOG_ERROR, "Unable to finalize \"%s\": %s",
> filename, strerror(errno));
> return (-1);
> }
>
> return (0);
> }
>
> int /* O - 0 on success, -1 on error */
> cupsdRemoveFile(const char *filename) /* I - File to remove */
> {
> ...
> /*
> * Overwrite the file 7 times with 0xF6, 0x00, 0xFF, random, 0x00, 0xFF,
> * and more random data.
> */
>
> memset(buffer, 0xF6, sizeof(buffer));
> if (overwrite_data(fd, buffer, sizeof(buffer), (int)info.st_size))
> {
> close(fd);
> return (-1);
> }
> ...
> }
>
> static int /* O - 0 on success, -1 on error */
> overwrite_data(int fd, /* I - File descri...

[Till Kamppeter (till-kamppeter)]

Seems that the problem is caused by indicator-printers, renewing to frequently. Adding indicator-printers task ...

[Michael R Sweet (msweet)]

The current scheduler/file.c code was last changed back when we added the SyncOnClose option. The sync-on-close was removed in r9766 in May of 2011 for STR #3715, as part of the 1.5.0 release (patches are attached).

On Oct 30, 2013, at 1:02 PM, Till Kamppeter <email address hidden> wrote:

> Mike, can you have a look into this? The CUPS currently in Ubuntu 13.10
> (Saucy, CUPS 1.7rc1) does not show this problem, but the CUPS in 12.04
> LTS (Precise, CUPS 1.5.3) has this problem of an subscription renewal
> constantly waking up the system. Can you tell us which change fixed
> this, so that we can backport this change? Thanks.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1244205
>
> Title:
> cupsd wakes up the hard disk every 14 minutes
>
> Status in The Ubuntu Power Consumption Project:
> New
> Status in “cups” package in Ubuntu:
> New
>
> Bug description:
> cupsd calls fsync() on /etc/subscriptions.conf.N every 14~15 minutes.
> This causes the hard disk to wake up soon after it spins down.
> Subscription renewal is from indicator-printers every 15 minutes.
>
> I think we don't need cupsdRemoveFile() to always overwrite data and do a fsync() for this file. Currently only Precise is confirmed to be affected. Saucy seems not having the same issue according to
> (http://bazaar.launchpad.net/~ubuntu-branches/ubuntu/saucy/cups/saucy/view/head:/scheduler/file.c#L149)
>
> ---- block_dump from the kernel ----
> <7>[19935.646436] cupsd(1066): dirtied inode 15336755 (subscriptions.conf.N) on sda3
> <7>[19935.646673] cupsd(1066): WRITE block 352753016 on sda3 (8 sectors)
> <7>[19935.646755] cupsd(1066): dirtied inode 15335603 (?) on sda3
> <7>[19935.646763] cupsd(1066): dirtied inode 15335603 (?) on sda3
> <7>[19935.646776] cupsd(1066): WRITE block 352701128 on sda3 (8 sectors)
> <7>[20774.607856] cupsd(1066): dirtied inode 15335603 (subscriptions.conf.N) on sda3
> <7>[20774.608034] cupsd(1066): WRITE block 352862776 on sda3 (8 sectors)
> <7>[20774.608113] cupsd(1066): dirtied inode 15335607 (?) on sda3
> <7>[20774.608120] cupsd(1066): dirtied inode 15335607 (?) on sda3
> <7>[20774.608133] cupsd(1066): WRITE block 352753008 on sda3 (8 sectors)
> <7>[21613.569033] cupsd(1066): dirtied inode 15335607 (subscriptions.conf.N) on sda3
> <7>[21613.569257] cupsd(1066): WRITE block 352753024 on sda3 (8 sectors)
> <7>[21613.569345] cupsd(1066): dirtied inode 15336755 (?) on sda3
> <7>[21613.569353] cupsd(1066): dirtied inode 15336755 (?) on sda3
> <7>[21613.569367] cupsd(1066): WRITE block 352753016 on sda3 (8 sectors)
>
> ---- cups: scheduler/file.c ----
> int /* O - 0 on success, -1 on error */
> cupsdCloseCreatedConfFile(
> cups_file_t *fp, /* I - File to close */
> const char *filename) /* I - Filename */
> {
> ...
> snprintf(newfile, sizeof(newfile), "%s.N", filename);
> snprintf(oldfile, sizeof(oldfile), "%s.O", filename);
>
> if ((cupsdRemoveFile(oldfile) && errno != ENOENT) ||
> (rename(filename, oldfile) && errno != ENOENT) ||
> rename(newfile, filename))
> {
> cupsdLogMessage(CU...

[Till Kamppeter (till-kamppeter)]

Mike, thank you very much.

[Hao-Ran Liu (hzliu123)]

I think a fix for this bug could be limited in this function: cupsdCloseCreatedConfFile(). Is there any concern if the logics of secure erase (overwrite_data() and fsync()) are removed from cupsdCloseCreatedConfFile()?

It's desirable to have a small diff so that we could have a SRU for precise.

[Michael R Sweet (msweet)]

The current release of CUPS does not have this problem. And unfortunately we do not have time to re-develop "fixes" for old CUPS releases that we no longer support in order to work around a design deficiency in a Linux-specific monitoring application which should not be using 15-minute lease times in the first place.

On Nov 8, 2013, at 7:14 AM, Hao-Ran Liu <email address hidden> wrote:

> I think a fix for this bug could be limited in this function:
> cupsdCloseCreatedConfFile(). Is there any concern if the logics of
> secure erase (overwrite_data() and fsync()) are removed from
> cupsdCloseCreatedConfFile()?
>
> It's desirable to have a small diff so that we could have a SRU for
> precise.
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1244205
>
> Title:
> cupsd wakes up the hard disk every 14 minutes
>
> Status in The Ubuntu Power Consumption Project:
> New
> Status in “cups” package in Ubuntu:
> New
> Status in “indicator-printers” package in Ubuntu:
> New
>
> Bug description:
> cupsd calls fsync() on /etc/subscriptions.conf.N every 14~15 minutes.
> This causes the hard disk to wake up soon after it spins down.
> Subscription renewal is from indicator-printers every 15 minutes.
>
> I think we don't need cupsdRemoveFile() to always overwrite data and do a fsync() for this file. Currently only Precise is confirmed to be affected. Saucy seems not having the same issue according to
> (http://bazaar.launchpad.net/~ubuntu-branches/ubuntu/saucy/cups/saucy/view/head:/scheduler/file.c#L149)
>
> ---- block_dump from the kernel ----
> <7>[19935.646436] cupsd(1066): dirtied inode 15336755 (subscriptions.conf.N) on sda3
> <7>[19935.646673] cupsd(1066): WRITE block 352753016 on sda3 (8 sectors)
> <7>[19935.646755] cupsd(1066): dirtied inode 15335603 (?) on sda3
> <7>[19935.646763] cupsd(1066): dirtied inode 15335603 (?) on sda3
> <7>[19935.646776] cupsd(1066): WRITE block 352701128 on sda3 (8 sectors)
> <7>[20774.607856] cupsd(1066): dirtied inode 15335603 (subscriptions.conf.N) on sda3
> <7>[20774.608034] cupsd(1066): WRITE block 352862776 on sda3 (8 sectors)
> <7>[20774.608113] cupsd(1066): dirtied inode 15335607 (?) on sda3
> <7>[20774.608120] cupsd(1066): dirtied inode 15335607 (?) on sda3
> <7>[20774.608133] cupsd(1066): WRITE block 352753008 on sda3 (8 sectors)
> <7>[21613.569033] cupsd(1066): dirtied inode 15335607 (subscriptions.conf.N) on sda3
> <7>[21613.569257] cupsd(1066): WRITE block 352753024 on sda3 (8 sectors)
> <7>[21613.569345] cupsd(1066): dirtied inode 15336755 (?) on sda3
> <7>[21613.569353] cupsd(1066): dirtied inode 15336755 (?) on sda3
> <7>[21613.569367] cupsd(1066): WRITE block 352753016 on sda3 (8 sectors)
>
> ---- cups: scheduler/file.c ----
> int /* O - 0 on success, -1 on error */
> cupsdCloseCreatedConfFile(
> cups_file_t *fp, /* I - File to close */
> const char *filename) /* I - Filename */
> {
> ...
> snprintf(newfile, sizeof(newfile), "%s.N", filename);
> snprintf(oldfile, sizeof(oldfile), "%s.O", filename);
>
> if ((cupsdRemoveFile(oldfile) && errno != ENOENT) ||
> ...

[Till Kamppeter (till-kamppeter)]

Seems that the best way to solve this problem is to fix indicator-printers, as we do not get any upstream patches for such an old version of CUPS. Closing cups task ...

[Lars Karlitski (larsu)]

I've attached a branch which increases the timeout to 24h.

Why don't we just patch cups to always send those dbus signals? (Or get on the bus properly even.)

[Launchpad Janitor (janitor)]

This bug was fixed in the package indicator-printers - 0.1.7+14.04.20140313-0ubuntu1

---------------
indicator-printers (0.1.7+14.04.20140313-0ubuntu1) trusty; urgency=low

  [ Ted Gould ]
  * Synchronize process management across indicators.

  [ Lars Uebernickel ]
  * Change notification lease time to 24h (LP: #1244205)
 -- Ubuntu daily release <email address hidden> Thu, 13 Mar 2014 22:04:55 +0000

[Michael R Sweet (msweet)]

Lars,

Due to the amount of information contained in the current notifications and the lack of aggregation, the existing dbus notifier is the right way to do this to avoid serious performance issues.

FWIW, OS X uses three "look at me" notifications (via Darwin's notify_post API) to let applications know that a printer has been added, modified, or deleted, that a printer's state has changed, or that a job's state has changed (or a job has been created). These notifications are aggregated to no more than once per second and are sufficient to let applications know when then need to query cupsd for changes, vs. the current DBUS messages containing the complete notification. I would not be opposed to adding always-on DBUS "look at me" notifications, as those could be delivered efficiently without the overhead of the current "rich" messaging.

As for your "get on the bus properly even" comment, I am not sure I follow. If you mean that cupsd should be auto-started and/or communicated with via DBUS, that will never happen. Aside from the fact that DBUS is NOT universally available, it does not deal well with multi-threaded applications, is limited to the local system, has a higher overhead than the current domain socket with HTTP+IPP protocol interface, and would require us to completely duplicate all IPP functionality over DBUS. The current socket-based interface allows clients to communicate locally and over the network as needed, all using the same APIs.

(FWIW, we are adding systemd support in CUPS 2.0 that includes launch-on-demand and idle exit of cupsd, much like we've been doing on OS X for over 10 years...)

On Mar 13, 2014, at 1:40 PM, Lars Uebernickel <email address hidden> wrote:

> I've attached a branch which increases the timeout to 24h.
>
> Why don't we just patch cups to always send those dbus signals? (Or get
> on the bus properly even.)
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1244205
>
> Title:
> cupsd wakes up the hard disk every 14 minutes
>
> Status in The Ubuntu Power Consumption Project:
> New
> Status in “cups” package in Ubuntu:
> Won't Fix
> Status in “indicator-printers” package in Ubuntu:
> New
>
> Bug description:
> cupsd calls fsync() on /etc/subscriptions.conf.N every 14~15 minutes.
> This causes the hard disk to wake up soon after it spins down.
> Subscription renewal is from indicator-printers every 15 minutes.
>
> I think we don't need cupsdRemoveFile() to always overwrite data and do a fsync() for this file. Currently only Precise is confirmed to be affected. Saucy seems not having the same issue according to
> (http://bazaar.launchpad.net/~ubuntu-branches/ubuntu/saucy/cups/saucy/view/head:/scheduler/file.c#L149)
>
> ---- block_dump from the kernel ----
> <7>[19935.646436] cupsd(1066): dirtied inode 15336755 (subscriptions.conf.N) on sda3
> <7>[19935.646673] cupsd(1066): WRITE block 352753016 on sda3 (8 sectors)
> <7>[19935.646755] cupsd(1066): dirtied inode 15335603 (?) on sda3
> <7>[19935.646763] cupsd(1066): dirtied inode 15335603 (?) on sda3
> <7>[19935.646776] cupsd(1066): WRITE block 3...

[Lars Karlitski (larsu)]

Mike, thanks for the detailed comment.

Sorry about the off-hand remark. What I meant by "get on the bus properly" is for CUPS to be on D-Bus all the time, not only when an event happens and a subscription exists. I think the subscription-based system is overkill for desktop notifications and makes our indicators, settings pages, and print-dialogs needlessly complicated.

I'm glad to hear that we seem to be on the same page about that and that it's similar to what you're doing on OSX already.