[cups] cups unable to communicate with avahi-daemon when running as a service on a read-only setup

[Andrzej Śliwiński]

Hi,

I'm finishing setting up my Raspberry Pi in a read-only mode and cups
service seems to be the last thing that is causing me issues.

As cups writes the config to /etc, I decided to mount /etc/cups as an
overlay system:

    $ mount
    ...
    overlay on /etc/cups type overlay
(rw,relatime,lowerdir=/etc/cups_org,upperdir=/etc/cups_rw/upper,workdir=/etc/cups_rw/work)
    ...

The cups service starts successfully, I'm able to access the localhost:631
page, however opening /admin subpage results in "Internal server error" and
the /printer subpage shows: Unable to get printer list: Bad file descriptor.

During the startup of the service I'm seeing in the log:

    E [03/Sep/2016:17:17:13 +0200] Unable to communicate with avahi-daemon:
Daemon not running

while the avahi daemon is active and running

When accessing the /admin subpage the log shows:

    D [03/Sep/2016:18:22:39 +0200] [CGI] Started
/usr/lib/cups/cgi-bin/admin.cgi (PID 5367)
    I [03/Sep/2016:18:22:39 +0200] [Client 13] Started
"/usr/lib/cups/cgi-bin/admin.cgi" (pid=5367)
    D [03/Sep/2016:18:22:39 +0200] [Client 13] file=14
    D [03/Sep/2016:18:22:39 +0200] [Client 13] Waiting for CGI data.
    D [03/Sep/2016:18:22:39 +0200] Report: clients=1
    D [03/Sep/2016:18:22:39 +0200] Report: jobs=0
    D [03/Sep/2016:18:22:39 +0200] Report: jobs-active=0
    D [03/Sep/2016:18:22:39 +0200] Report: printers=1
    D [03/Sep/2016:18:22:39 +0200] Report: stringpool-string-count=654
    D [03/Sep/2016:18:22:39 +0200] Report: stringpool-alloc-bytes=6392
    D [03/Sep/2016:18:22:39 +0200] Report: stringpool-total-bytes=11720
    D [03/Sep/2016:18:22:39 +0200] cupsd is not idle any more, canceling
shutdown.
    D [03/Sep/2016:18:22:39 +0200] [CGI] admin.cgi started...
    D [03/Sep/2016:18:22:39 +0200] cupsd is not idle any more, canceling
shutdown.
    E [03/Sep/2016:18:22:39 +0200] [CGI] Unable to connect to cupsd: Bad
file descriptor
    E [03/Sep/2016:18:22:39 +0200] [CGI] Unable to connect to cupsd: Bad
file descriptor
    D [03/Sep/2016:18:22:39 +0200] [CGI]
cupsServer()="/var/run/cups/cups.sock"
    D [03/Sep/2016:18:22:39 +0200] [CGI] ippPort()=631
    D [03/Sep/2016:18:22:39 +0200] cupsd is not idle any more, canceling
shutdown.
    D [03/Sep/2016:18:22:39 +0200] [CGI] cupsEncryption()=0
    D [03/Sep/2016:18:22:39 +0200] cupsd is not idle any more, canceling
shutdown.
    D [03/Sep/2016:18:22:39 +0200] [Client 13] CGI data ready to be sent.
    D [03/Sep/2016:18:22:39 +0200] PID 5367
(/usr/lib/cups/cgi-bin/admin.cgi) stopped with status 1.

However, when I stop the service, and run the program manually:

    sudo /usr/sbin/cupsd -f

the problem does not occur at all. The log shows:

    D [03/Sep/2016:18:25:33 +0200] Avahi server connection now available,
registering printers for Bonjour broadcasting.

And I'm able to access /admin (and all the other subpages):

    D [03/Sep/2016:18:25:36 +0200] [CGI] Started
/usr/lib/cups/cgi-bin/admin.cgi (PID 6269)
    I [03/Sep/2016:18:25:36 +0200] [Client 17] Started
"/usr/lib/cups/cgi-bin/admin.cgi" (pid=6269)
    D [03/Sep/2016:18:25:36 +0200] [Client 17] file=18
    D [03/Sep/2016:18:25:36 +0200] [Client 17] Waiting for CGI data.
    D [03/Sep/2016:18:25:36 +0200] cupsd is not idle any more, canceling
shutdown.
    D [03/Sep/2016:18:25:36 +0200] [CGI] admin.cgi started...
    D [03/Sep/2016:18:25:36 +0200] cupsd is not idle any more, canceling
shutdown.
    D [03/Sep/2016:18:25:36 +0200] [Client 19] Accepted from localhost
(Domain)
    D [03/Sep/2016:18:25:36 +0200] [Client 19] Waiting for request.
    D [03/Sep/2016:18:25:36 +0200] [CGI] http=0x554e9db8
    D [03/Sep/2016:18:25:36 +0200] [CGI] cgiSetVariable: SECTION="admin"
    D [03/Sep/2016:18:25:36 +0200] [CGI] cgiSetVariable: REFRESH_PAGE=""
    D [03/Sep/2016:18:25:36 +0200] cupsd is not idle any more, canceling
shutdown.
    D [03/Sep/2016:18:25:36 +0200] [CGI] org.cups.sid cookie is
"72b5efbcd72416115613b87b329ce911"
    D [03/Sep/2016:18:25:36 +0200] [CGI] No form data, showing main menu...


Any hints on what can be the reason of this behavior and how to solve the
issue (change the config in cups.service file?) or at least to move this
troubleshooting further?

Best regards,
Andrzej Sliwinski