SickHub/docker-cups-airprint

Printers are not created on initial start/container setup, only on subsequent restarts

mundschenk-at opened this issue · 6 comments

I'd like to use the ENV method to create my printers. Unfortunately, the script does not seem to evaluate the ENV variables correctly on initialization of a container, but it does on subsequent restarts. I'm not sure why from reading the startup script, but there seems to be an issue with one of the cupsctl calls, which probably breaks the subshell.

...
.--> CUPS ready
cupsctl: Unable to connect to server: Bad file descriptor
E [01/Nov/2022:05:22:08 +0000] Unable to communicate with avahi-daemon: Daemon not running
===========================================================
The dockerized CUPS instance is now ready for use! The web
interface is available here:
...

whereas on restart the relevant part of the log looks like this:

.--> CUPS ready
localhost - - [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 401 0 - -
localhost - root [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 201 4614 - -
E [01/Nov/2022:19:42:43 +0000] Unable to communicate with avahi-daemon: Daemon not running
localhost - - [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 401 0 - -
localhost - root [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 201 4614 - -
E [01/Nov/2022:19:42:43 +0000] Unable to communicate with avahi-daemon: Daemon not running
localhost - - [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 401 0 - -
localhost - root [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 201 4614 - -
E [01/Nov/2022:19:42:43 +0000] Unable to communicate with avahi-daemon: Daemon not running
localhost - - [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 401 0 - -
localhost - root [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 201 4614 - -
E [01/Nov/2022:19:42:43 +0000] Unable to communicate with avahi-daemon: Daemon not running
localhost - - [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 401 0 - -
localhost - root [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 201 4640 - -
E [01/Nov/2022:19:42:43 +0000] Unable to communicate with avahi-daemon: Daemon not running
localhost - - [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 401 0 - -
localhost - root [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 201 4640 - -
E [01/Nov/2022:19:42:43 +0000] Unable to communicate with avahi-daemon: Daemon not running
localhost - - [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 401 0 - -
localhost - root [01/Nov/2022:19:42:43 +0000] "PUT /admin/conf/cupsd.conf HTTP/1.1" 201 4662 - -
--> adding printers
E [01/Nov/2022:19:42:43 +0000] Unable to communicate with avahi-daemon: Daemon not running
CUPS_LPADMIN_PRINTER1 = lpadmin ...
===========================================================
The dockerized CUPS instance is now ready for use! The web
interface is available here:

The time difference is because the container got recreated by Portainer this morning and I did a manual restart just now.

I have checked my installation and I cannot confirm your observation. Can you share your configuration and platform, to narrow down the potential cause?

Sure, I'm running this on a Synology NAS (x64) via docker-compose:

version: "3"
services:
  AirPrint:
    container_name: airprint
    domainname: (...)
    environment:
      - PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
      - CUPS_WEBINTERFACE=yes
      - CUPS_REMOTE_ADMIN=no
      - CUPS_ENV_DEBUG=no
      - CUPS_LPADMIN_PRINTER1=lpadmin -p LaserJet (...)      
      - CUPS_LPADMIN_PRINTER1_ENABLE=cupsenable LaserJet
      - CUPS_LPADMIN_PRINTER1_ACCEPT=cupsaccept LaserJet

    hostname: airprint
    image: drpsychick/airprint-bridge:latest
    ipc: shareable
    logging:
      driver: db
      options: {}
    networks:
      - macvlan
    restart: unless-stopped
networks:
  macvlan:
      external: true

From what I can tell this line in the startup script is the culprit:
until cupsctl -h localhost:631 --share-printers > /dev/null 2>&1; do echo -n "."; sleep 1; done;
I added this as the least ugly solution to make sure cups is up and running.

As I cannot reproduce your issue, can you try to find a command that wait till cups no longer reports cupsctl: Unable to connect to server: Bad file descriptor. Or check if cupsctl returns "0" with this error, which would explain why it breaks the loops and continues too early.

I've tried to debug the issue and it appears that the cupsctl --debug-logging line triggers the issue (or its equivalent when logging is disabled):

airprint    | + echo '--> CUPS ready'
airprint    | + '[' yes = yes ']'
airprint    | + cupsctl --debug-logging
airprint    | cupsctl: Unable to connect to server: Bad file descriptor
airprint    | + cupsctl --no-debug-logging
airprint    | E [18/Nov/2022:23:23:22 +0000] Unable to communicate with avahi-daemon: Daemon not running

Adding a second of sleep before the --debug-logging/--no-debug-logging line fixes the issue for me. Why it's necessary to wait a little longer, I've got no clue.

Let's see if this fixes it @mundschenk-at . If not you're more than welcome to reopen this issue.