cupsd can't access /var/log/cups/error_log permission denied

[Walter Tautz]

Binary package hint: cupsys

dapper release. The subject line appears in /var/log/syslog
repeatedly. Looking at the files in /var/log/cups/ :
drwxr-xr-x 2 root root 4096 2006-07-27 06:25 .
drwxr-xr-x 6 root root 4096 2006-07-27 06:25 ..
-rw-r--r-- 1 cupsys lp 21981 2006-07-27 14:27 access_log
-rw-r--r-- 1 cupsys lp 2253 2006-07-24 15:10 access_log.1.gz
-rw-r--r-- 1 cupsys lp 2498 2006-07-20 16:01 access_log.2.gz
-rw-r--r-- 1 root lp 3146700 2006-07-27 13:51 error_log
-rw-r--r-- 1 root lp 40473 2006-07-26 09:31 error_log.1.gz
-rw-r--r-- 1 root lp 40469 2006-07-25 09:31 error_log.2.gz
-rw-r--r-- 1 root lp 256199 2006-07-24 18:21 error_log.3.gz
-rw-r--r-- 1 cupsys lp 38898 2006-07-24 06:24 error_log.4.gz
-rw-r--r-- 1 cupsys lp 38914 2006-07-23 06:24 error_log.5.gz
-rw-r--r-- 1 cupsys lp 39081 2006-07-22 06:24 error_log.6.gz
-rw-r--r-- 1 cupsys lp 171024 2006-07-21 06:24 error_log.7.gz
-rw-r--r-- 1 cupsys lp 372 2006-07-27 14:23 page_log
-rw-r--r-- 1 cupsys lp 113 2006-07-24 14:42 page_log.1.gz

Note the root ownership of the file error_log. Note if one does
a chown it just gets switched back to root ownership of cups
gets restarted.... another consequence of running cupsd as
cupsys I suppose...sigh

[Pascal De Vuyst (pascal-devuyst)]

I just noticed the same thing, see relevant part of my /var/log/syslog in attachment.
Confirming this bug.

[Ante Karamatić (ivoks)]

Hm. I can't confirm this.

If you take a look at your perms, you'll see that it was cupsys:lp before, but something/somehow changed to root:lp. On a fresh Dapper install permissons are cupsys:lp and stay that way after cups restart.

If everybody had perms root:lp, then we wouldn't be able to solve any cups bugs (since requierment for debuging are entrys from error_log).

Could you add your cupsd.conf and check your system configuration? Also, it would be great if you could remeber what you've done on July 24. If this machine is on-line 24/7, then different cdate and ctime for every error_log are very strange.

[Pascal De Vuyst (pascal-devuyst)]

I'm using Dapper 6.06 LTS with cupsys 1.2.1-0ubuntu2.

As indicated by Walter when I do:

$ ls -l /var/log/cups/error_log
-rw-r--r-- 1 root lp 190608 2006-07-28 10:45 /var/log/cups/error_log

$ sudo chown cupsys /var/log/cups/error_log*

$ ls -l /var/log/cups/error_log
-rw-r--r-- 1 cupsys lp 195464 2006-07-28 10:46 /var/log/cups/error_log

And then restart cups:
$ sudo /etc/init.d/cupsys restart

I see permissions of /var/log/cups/error_log changed again to:
$ ls -l /var/log/cups/error_log
-rw-r--r-- 1 root lp 124369 2006-07-28 10:36 error_log

So it seems that permissions are changed everytime a log file has been accessed after restart of cups.
In Edgy which has a newer cupsys I don't have this permission problems and owner of error_log is cupsys.

In attachment you find my cupsd.conf, I doubt you will find anything in it since it is the one that got installed by default and I never changed it.

Ante, since you don't have this problem on Dapper, have you any idea how to further debug this problem?
Since all error_log* files have owner root now I'm unable to see at which point in time something happened.

[Walter Tautz (wtautz)]

Pascal De Vuyst wrote:
> I'm using Dapper 6.06 LTS with cupsys 1.2.1-0ubuntu2.
>
> As indicated by Walter when I do:
>
> $ ls -l /var/log/cups/error_log
> -rw-r--r-- 1 root lp 190608 2006-07-28 10:45 /var/log/cups/error_log
>
> $ sudo chown cupsys /var/log/cups/error_log*
>
> $ ls -l /var/log/cups/error_log
> -rw-r--r-- 1 cupsys lp 195464 2006-07-28 10:46 /var/log/cups/error_log
>
> And then restart cups:
> $ sudo /etc/init.d/cupsys restart
>
> I see permissions of /var/log/cups/error_log changed again to:
> $ ls -l /var/log/cups/error_log
> -rw-r--r-- 1 root lp 124369 2006-07-28 10:36 error_log
>
> So it seems that permissions are changed everytime a log file has been accessed after restart of cups.
> In Edgy which has a newer cupsys I don't have this permission problems and owner of error_log is cupsys.
>
> In attachment you find my cupsd.conf, I doubt you will find anything in
> it since it is the one that got installed by default and I never changed
> it.
>
> Ante, since you don't have this problem on Dapper, have you any idea how to further debug this problem?
> Since all error_log* files have owner root now I'm unable to see at which point in time something happened.
>
>

Just to follow up. My cups was an update of a previous release but yes,
I also get the
same behaviour, i.e., restarting it changes ownership. I suppose I could
just purge
and reinstall from scratch..... Yes, I did update my config file to
conform with newer
release.

walter

[Walter Tautz (wtautz)]

Still a problem with 1.2.2 release of Ubuntu package...

[Martin Pitt (pitti)]

A fresh cupsys installation does not have this problem, but there might be a bug on upgrades. I'll look into this soon.

[Martin Pitt (pitti)]

Fixed in development version, will be uploaded after Knot-3 freeze.

[Martin Pitt (pitti)]

Easy patch and high-impact, thus appropriate for dapper-updates. Matt, can you please add your blessing here?

[Till Kamppeter (till-kamppeter)]

I think, the

[ -e /var/log/cups/$l ] && touch /var/log/cups/$l

in the patch must be replaced by

[ ! -e /var/log/cups/$l ] && touch /var/log/cups/$l

as the file should only be created if it is not already there.

[Martin Pitt (pitti)]

Yup, sorry, of course this was supposed to be

  [ -e /var/log/cups/$l ] || touch /var/log/cups/$l

(&& doesn't work well in -e scripts). Fixed in svn head.

[Martin Pitt (pitti)]

 cupsys (1.2.3-1ubuntu1) edgy; urgency=low
 .
   * Merge recent bug fixes from Debian (see Kenshi's changes in 1.2.3-1 for
     Ubuntu-relevant details). 00_r5958.dpatch has the following fixes from
     upstream:
     - The "All Documents" link in the on-line help was missing a trailing
       slash (STR #1971)
     - The Polish web interface translation used the wrong URLs for the job
       history (STR #1963)
     - The "reprint job" button did not work (STR #1956)
     - The scheduler did not always report printer or job events properly (STR
       #1955)
     - The scheduler always stopped the queue on error, regardless of the exit
       code, if the error policy was set to "stop-printer" (STR #1959)
     - ppdEmitJCL() included UTF-8 characters in the JCL job name, which caused
       problems on some printers (STR #1959)
     - Fixed a buffering problem that cause high CPU usage (STR #1968)
       (Closes: LP#59542)
     - The command-line applications did not convert command-line strings to
       UTF-8 as needed (STR #1958)
     - cupsDirRead() incorrectly aborted when reading a symbolic link that
       pointed to a file/directory that did not exist (STR #1953)
     - The cupsInterpretRasterPPD() function did not handle custom page sizes
       properly.
   * debian/cupsys.init.d: Always make sure that log files have proper
     permissions. Closes: LP#54277

[Martin Pitt (pitti)]

Attaching updated patch for SRU request.

[Martin Pitt (pitti)]

Hi Matt,

I propose to fix https://launchpad.net/bugs/54277 in dapper.

Impact: In some circumstances, cupsys does not start (like, a previous
installation from upstream, or an upgrade with modified configuration
from Breezy, in particular if RunAsRoot was disabled). Does not affect
the default installation.

Patch: http://librarian.launchpad.net/4313481/patch
Instead of only setting permissions of log files when they are
created, fix the permissions everytime in the init script.
Applied in edgy, no reported regressions.

[Matt Zimmerman (mdz)]

On Tue, Sep 19, 2006 at 06:31:53PM +0200, Martin Pitt wrote:
> Hi Matt,
>
> I propose to fix https://launchpad.net/bugs/54277 in dapper.
>
> Impact: In some circumstances, cupsys does not start (like, a previous
> installation from upstream, or an upgrade with modified configuration
> from Breezy, in particular if RunAsRoot was disabled). Does not affect
> the default installation.
>
> Patch: http://librarian.launchpad.net/4313481/patch
> Instead of only setting permissions of log files when they are
> created, fix the permissions everytime in the init script.
> Applied in edgy, no reported regressions.

Looks appropriate; please upload to dapper-proposed.

--
 - mdz

[Martin Pitt (pitti)]

 status fixcommitted

Matt Zimmerman [2006-09-19 20:55 -0700]:
> Looks appropriate; please upload to dapper-proposed.

Done:

   * Add 16-nonpartitions-ending-in-nums.patch:
     - Hal currently assumes that device names ending in numbers are
       partitions. This patch adds a safe and easy, but slightly ugly
       workaround. (Real fix will be discussed with upstream at
       https://bugs.freedesktop.org/show_bug.cgi?id=5558)
     - This breaks SCSI, USB, and Firewire CD drives, which are usually called
       'scd0', 'sr1', etc.
     - Closes: LP#56484 and an impressive number of duplicates.

I attached the debdiff to the bug report.

Bug submitters, can you please test this, too, after it's available in
dapper-proposed? Thank you!

[Martin Pitt (pitti)]

Already fixed in edgy a while ago.

[Martin Pitt (pitti)]

Bah, sorry for comment #16 which was the changelog for the hal bug 56484.

[Martin Pitt (pitti)]

Matt Zimmerman [2006-09-19 20:55 -0700]:
> Looks appropriate; please upload to dapper-proposed.

Done:

 cupsys (1.2.2-0ubuntu0.6.06.1) dapper-proposed; urgency=low
 .
   * debian/cupsys.init.d: Always make sure that log files have proper
     permissions. Closes: LP#54277

[Martin Pitt (pitti)]

Package is in dapper-proposed. Testing and feedback would be highly appreciated! It will go into -updates next Wednesday if all goes well.

[Walter Tautz (wtautz)]

Just did an apt-get install cupsys to get the new version.
If one does /etc/init.d/cupsys stop
and /etc/init.d/cupsys start then ls -al /var/log/cups/error_log is:
-rw-r--r-- 1 root lp 834320 2006-10-12 09:07 /var/log/cups/error_log
at least initially and then about a minute later it has ownership
cupsys.lp. NOTE. the change only occurs after a little while? So
I guess it's fixed but in a weird way. Would be nice to know
why there is lag?

walter

[Martin Pitt (pitti)]

Hi Walter,

Walter Tautz [2006-10-12 13:12 -0000]:
> Just did an apt-get install cupsys to get the new version.
> If one does /etc/init.d/cupsys stop
> and /etc/init.d/cupsys start then ls -al /var/log/cups/error_log is:
> -rw-r--r-- 1 root lp 834320 2006-10-12 09:07 /var/log/cups/error_log
> at least initially and then about a minute later it has ownership
> cupsys.lp. NOTE. the change only occurs after a little while? So
> I guess it's fixed but in a weird way. Would be nice to know
> why there is lag?

Weird, this happens immediately for me. Can you please do

  sudo /etc/init.d/cupsys stop
  sudo sh -ex /etc/init.d/cupsys start 2>&1|grep var/log

and copy the output here?

[Till Kamppeter (till-kamppeter)]

For me strange things happen:

----------------------------------------------------------------------------
till@laptoptill:~$ ls -l /var/log/cups/error_log
-rw-r--r-- 1 root lp 1648147 2006-10-13 10:24 /var/log/cups/error_log
till@laptoptill:~$ sudo /etc/init.d/cupsys stop
 * Stopping Common Unix Printing System: cupsd [ ok ]
till@laptoptill:~$ ls -l /var/log/cups/error_log
-rw-r--r-- 1 cupsys lp 1638329 2006-10-13 10:24 /var/log/cups/error_log
till@laptoptill:~$ sudo sh -ex /etc/init.d/cupsys start 2>&1|grep var/log
+ [ -e /var/log/cups/access_log ]
+ chmod 640 /var/log/cups/access_log
+ chown cupsys:lpadmin /var/log/cups/access_log
+ [ -e /var/log/cups/page_log ]
+ chmod 640 /var/log/cups/page_log
+ chown cupsys:lpadmin /var/log/cups/page_log
+ [ -e /var/log/cups/error_log ]
+ chmod 640 /var/log/cups/error_log
+ chown cupsys:lpadmin /var/log/cups/error_log
till@laptoptill:~$ ls -l /var/log/cups/error_log
-rw-r--r-- 1 root lp 1648147 2006-10-13 10:24 /var/log/cups/error_log
till@laptoptill:~$ ls -l /var/log/cups/error_log
-rw-r--r-- 1 root lp 1648147 2006-10-13 10:24 /var/log/cups/error_log
till@laptoptill:~$ ls -l /var/log/cups/error_log
-rw-r--r-- 1 root lp 1648147 2006-10-13 10:24 /var/log/cups/error_log
till@laptoptill:~$ ls -l /var/log/cups/error_log
-rw-r--r-- 1 root lp 1648147 2006-10-13 10:24 /var/log/cups/error_log
till@laptoptill:~$
----------------------------------------------------------------------------

The commands for doing the ownership/permission change are executed, but immediately afterwards the ownerships are back to the wrong values. When is the CUPS daemon started? Before or after correcting the ownerships? Perhaps the CUPS daemon sets them to root.lp before it drops its privileges.

Perhaps we need to patch the CUPS daemon to get the right thing.

I have tested on current Edgy (cupsys 1.2.4-2ubuntu3).

[Walter Tautz (wtautz)]

I can confirm Till's observations with a slight caveat.

Prior to stoping cupsd I get ownership cupsys.lp on error_log
and after I stop it still has ownership cupsys.lp.

If I start it it has ownership root.lp until the error_log gets rolled
at which point the new instance of error_log has ownership cupsys.lp.

Conclusion: the chown down in the init script is too early....or the
code in
cupsd has to be hacked to do things...

Walter

[Till Kamppeter (till-kamppeter)]

The problem is caused by logrotate. As soon as logrotate takes the error_log away from CUPS, CUPS needs to open a new error_log and does not succeed.

Either we must hack CUPS, so that it sets our ownerships (so that it re-opens the file as normal user without problem) or we must make logrotate placing an empty error_log with correct ownerships, after it has taken away the old file.

Probably the CUPS solution is the better one, as otherwise both CUPS and logrotate packages have to carry the information what the ownerships and permissions of error_log have to be.

[Simon Law (sfllaw)]

Confirmed Walter and Till's comments.

A sane thing to do might be to have logrotate remember the permissions of the file it moves away, and then recreates them? This would solve the general case for any application that has its logs rotated.

[Till Kamppeter (till-kamppeter)]

Simon, you suggestion will not work, as CUPS has to open the new file (we have taken the open file away and provided a new file which is not yet opened by CUPS) and with dropped privileges CUPS cannot open a file with these permissions/ownerships.

[Walter Tautz (wtautz)]

Simon Law wrote:
> Confirmed Walter and Till's comments.
>
> A sane thing to do might be to have logrotate remember the permissions
> of the file it moves away, and then recreates them? This would solve
> the general case for any application that has its logs rotated.
>
>
Doesn't cupsd do it's own logrotating. Looking in /etc/logrotate.conf
I have:
# see "man logrotate" for details
# rotate log files weekly
weekly

# keep 4 weeks worth of backlogs
rotate 4

# create new (empty) log files after rotating old ones
create

# uncomment this if you want your log files compressed
#compress

# packages drop log rotation information into this directory
include /etc/logrotate.d

# no packages own wtmp, or btmp -- we'll rotate them here
/var/log/wtmp {
    missingok
    monthly
    create 0664 root utmp
    rotate 1
}

/var/log/btmp {
    missingok
    monthly
    create 0664 root utmp
    rotate 1
}

which suggests it ain't lookin' in /var/log/cups/

Indeed, considering MaxLogSize can be set to 0 bytes in
/etc/cups/cupsd.conf implies no rotating will occur, see man cupsd.conf.

walter

[Walter Tautz (wtautz)]

cupsd does its own log rotating, not logrotate. So it implies
that cupsd does not set the permission properly when this
happens nor when it starts up from scratch.

Wrt the changes in /etc/init.d/cupsys we see that the chown
stuff is before cupsd starts up...clearly it should come after
starting it up. However this is NOT the appropriate fix, it's a
workaround to the problem that cupsd simply doesn't create
it's log files correctly. I.e. you guys haven't put the string 'cupsys'
in enough places in the source code. Too bad this isn't something
one could declare at build via configure time using the code from www.cups.org rather than having to rely on Ubuntu patches...........@#!$%^ :-)

[Matt Zimmerman (mdz)]

On Fri, Oct 13, 2006 at 09:08:54PM -0000, Walter Tautz wrote:
> Doesn't cupsd do it's own logrotating. Looking in /etc/logrotate.conf
> I have:
> [...]
> # packages drop log rotation information into this directory
> include /etc/logrotate.d

See above.

--
 - mdz

[Walter Tautz (wtautz)]

oops /etc/logrotate.d/cupsys exists....mispoke obviously......
and yet how does this connect with MaxLogSize? I must admit
to being a bit confused......

/etc/logrotate.d/cupsys:

/var/log/cups/*log {
        daily
        missingok
        rotate 7
        sharedscripts
        postrotate
                if [ -e /var/run/cups/cupsd.pid ]; then
                        invoke-rc.d --quiet cupsys force-reload > /dev/null
                        sleep 10
                fi
        endscript
        compress
        notifempty
        create 640 cupsys lpadmin
}

Learn something new everyday....so the invoke-rc.d is
the problem obviously...i.e. cupsd is doing the wrong thing.....

[Martin Pitt (pitti)]

Removing milestone tag. The remaining issues need to be addressed in Edgy+1.

[Martin Pitt (pitti)]

Setting dapper back to 'in progress', too. The current -proposed upload certainly improves matters a bit, but not completely.

[Ralf Hildebrandt (ralf-hildebrandt)]

Very bizarre:

# ll *_log
-rw-r----- 1 cupsys lpadmin 0 2006-10-31 09:45 access_log
-rw-r--r-- 1 root lp 227932 2006-10-31 09:45 error_log
-rw-r----- 1 cupsys lpadmin 0 2006-10-31 09:45 page_log

root@hummus:/var/log/cups# /etc/init.d/cupsys stop
 * Stopping Common Unix Printing System: cupsd [ ok ]

# /etc/init.d/cupsys start
 * Starting Common Unix Printing System: cupsd OK
-rw-r----- 1 cupsys lpadmin 0 2006-10-31 09:46 /var/log/cups/access_log
OK
-rw-r----- 1 cupsys lpadmin 0 2006-10-31 09:46 /var/log/cups/page_log
OK
-rw-r----- 1 cupsys lpadmin 228051 2006-10-31 09:46 /var/log/cups/error_log
                                                                                                                  [ ok ]
# ll *_log
-rw-r----- 1 cupsys lpadmin 0 2006-10-31 09:46 access_log
-rw-r--r-- 1 root lp 255154 2006-10-31 09:46 error_log
-rw-r----- 1 cupsys lpadmin 0 2006-10-31 09:46 page_log

Can somebody explain this? The init.d script sets the permissions OK, and then something fubars them.

Further debugging of the script shows that:
start-stop-daemon --start --quiet --oknodo --pidfile "$PIDFILE" --exec $DAEMON
resets the permissions to

before start-stop
-rw-r----- 1 cupsys lpadmin 282800 2006-10-31 09:48 /var/log/cups/error_log
after start-stop
-rw-r--r-- 1 root lp 309598 2006-10-31 09:48 /var/log/cups/error_log

The only solution for me is to change the permissions AGAIN after start-stop-daemon.

[Till Kamppeter (till-kamppeter)]

I have now fixed it by correcting the permissions after starting the daemon, as Ralf Hildebrandt said.

Get the corrected packages for testing here:

http://www.linux-foundation.org/~till/tmp/ubuntu/feisty/cupsys/

My CUPS daemon is now happily logging and I hope this helps us to fix the other printing-related bugs.

[Till Kamppeter (till-kamppeter)]

According to Martin Pitt this fixes the last regression caused by running CUPS as non-root user.

[Martin Pitt (pitti)]

We will not fix this in Dapper. It only affects few people and the impact is relatively low, thus it is not worth the risk of getting a regression through an SRU.

[Michael Vogt (mvo)]

Removing verification-needed task.

[Henrik Nilsen Omma (henrik)]

Removing dapper milstone.