search

OpenPrinting / cups

OpenPrinting CUPS Sources
https://openprinting.github.io/cups
Apache License 2.0
1.05k stars 187 forks source link

[2.4.9 regression] cupsd don't start when only Listen /path/to/domain/socket is set in conf #985

Closed Maryse47 closed 3 months ago

Maryse47 commented 3 months ago

Describe the bug Setting cupsd to listen only on socket path prevents cups daemon from starting. It worked in 2.4.8 and before and stopped working in 2.4.9.

If the only Listen directive in cupsd.conf is set to socket path like: Listen /run/cups/cups.sock then cupsd daemon fails to start when running from systemd: cups.service: Failed with result 'protocol'.

The cups error log shows: No valid Listen or Port lines were found in the configuration file.

To Reproduce Steps to reproduce the behavior (on ArchLinux):

  1. Go to /etc/cups/cupsd.conf and remove any other Listen directive than Listen /run/cups/cups.sock
  2. Run systemct start cups.socket
  3. Run systemctl start cups
  4. See cups.service: Failed with result 'protocol'. and No valid Listen or Port lines were found in the configuration file. error messages

Expected behavior I expect cupsd service to start like before

System Information: OS: ArchLinux Cups 2.4.9

Additional context By reading changelog I presume it's somewhat related to https://github.com/OpenPrinting/cups/commit/a436956f374b0fd7f5da9df482e4f5840fa1c0d2 but the listening on socket functionality is still present in cups and I don't know what users are supposed to do to make it work.

michaelrsweet commented 3 months ago

Sounds like a configuration problem - systemd is supposed to supply the domain socket to cupsd when running on-demand.

Maryse47 commented 3 months ago

I use the default cups.service and cups.socket provided from this repo.

Maryse47 commented 3 months ago

If I remove Listen /run/cups/cups.sock from config then it fails with the same error message: No valid Listen or Port lines were found in the configuration file. so something isn't working as it should. Does anyone has it working with only Listen on socket file?

Maryse47 commented 3 months ago

The @CUPS_LISTEN_DOMAINSOCKET@ is also provided by default in cupsd.conf so the only thing I did is to remove Listen localhost:@DEFAULT_IPP_PORT@ line above because I don't want it to listen on local network. I don't see what I did wrong @zdohnal do you have any idea how it should work after your changes?

zdohnal commented 3 months ago

Ok, we did not count the possibility the Listen for socket is the only Listen directive in the cupsd.conf. In that case, the Listen line for .sock is ignored, thus the service is not started.

@michaelrsweet probably we have to move continue into the if block, so we don't omit the socket if it matches the expected domain socket name. WDYT?

zdohnal commented 3 months ago

Or do not let the loading fail - I'll look into the code.

Maryse47 commented 3 months ago

Ok, we did not count the possibility the Listen for socket is the only Listen directive in the cupsd.conf. In that case, the Listen line for .sock is ignored, thus the service is not started.

Even if there are two Listen directives and the service start does cups listen on both or is socket no-op?

michaelrsweet commented 3 months ago

@zdohnal @Maryse47 OK, I think I have a fix:

[master 7adb50839] Don't abort early if there are no listen sockets after loading cupsd.conf (Issue #985)

[2.4.x 6131f6a73] Don't abort early if there are no listen sockets after loading cupsd.conf (Issue #985)

Maryse47 commented 3 months ago

@michaelrsweet A added https://github.com/OpenPrinting/cups/commit/6131f6a73c188f3db0ec94ae488991ce80cfd7ea on top of 2.4.9 but unfortunately it still fails with the same error: No valid Listen or Port lines were found in the configuration file.

Maryse47 commented 3 months ago

The difference is it fails later than before:

systemd[1]: Starting CUPS Scheduler...
cupsd[43038]: Remote access is disabled.
cupsd[43038]: Loaded configuration file "/etc/cups/cupsd.conf"
cupsd[43038]: Using default TempDir of /var/spool/cups/tmp...
cupsd[43038]: Configured for up to 100 clients.
cupsd[43038]: Allowing up to 100 client connections per host.
cupsd[43038]: Using policy "default" as the default.
cupsd[43038]: Full reload is required.
cupsd[43038]: Loaded MIME database from "/usr/share/cups/mime" and "/etc/cups": 41 types, 31 filters...
cupsd[43038]: Loading job cache file "/var/cache/cups/job.cache"...
cupsd[43038]: Full reload complete.
cupsd[43038]: Cleaning out old files in "/var/spool/cups/tmp".
cupsd[43038]: Cleaning out old files in "/var/cache/cups".
cupsd[43038]: No valid Listen or Port lines were found in the configuration file.
systemd[1]: cups.service: Failed with result 'protocol'.
systemd[1]: Failed to start CUPS Scheduler.

Previously it failed right after reading the config:

systemd[1]: Starting CUPS Scheduler...
cupsd[43862]: Remote access is disabled.
cupsd[43862]: Loaded configuration file "/etc/cups/cupsd.conf"
cupsd[43862]: No valid Listen or Port lines were found in the configuration file.
systemd[1]: cups.service: Failed with result 'protocol'.
systemd[1]: Failed to start CUPS Scheduler.
michaelrsweet commented 3 months ago

OK, so that tells me there is an issue with the systemd configuration - the change I pushed delays the error message until we have queried systemd for its listen sockets...

Maryse47 commented 3 months ago

I have the systemd socket active before cups is started:

❯ systemctl status cups.socket
● cups.socket - CUPS Scheduler
     Loaded: loaded (/usr/lib/systemd/system/cups.socket; enabled; preset: disabled)
     Active: active (listening)
   Triggers: ● cups.service
     Listen: /run/cups/cups.sock (Stream)
     CGroup: /system.slice/cups.socket

systemd[1]: cups.socket: Deactivated successfully.
systemd[1]: Closed CUPS Scheduler.
systemd[1]: Stopping CUPS Scheduler...
systemd[1]: Listening on CUPS Scheduler.

Something connecting to that socket triggers cups startup but then it fails with the usual error.

Maryse47 commented 3 months ago

Here's the excerpt from the log with debug2 enabled:

cupsd[3892]: service_checkin: pid=3892
cupsd[3892]: service_checkin: 1 listeners.
cupsd[3892]: service_add_listener: Listener #1 at fd 3, "/run/cups/cups.sock".
cupsd[3892]: service_add_listener: Adding new listener #1 for /run/cups/cups.sock.
cupsd[3892]: No valid Listen or Port lines were found in the configuration file.
cupsd[3892]: cupsdEndProcess(pid=3892, force=0)
systemd[1]: cups.service: Failed with result 'protocol'.
systemd[1]: Failed to start CUPS Scheduler.

I don't know if /run/cups/cups.sock is what it got from systemd or from cupsd config but it refuses to use it.

BTW: is the cupsdLogMessage(CUPSD_LOG_INFO, "Ignoring %s address %s at line %d - only using domain socket from launchd/systemd from the CVE patch expected to show in the logs?

Maryse47 commented 3 months ago

I made another test - this time I removed Listen /run/cups/cups.sock directive from cupsd.conf:

cupsd[4228]: service_checkin: pid=4228
cupsd[4228]: service_checkin: 1 listeners.
cupsd[4228]: service_add_listener: Listener #1 at fd 3, "/run/cups/cups.sock".
cupsd[4228]: service_add_listener: Adding new listener #1 for /run/cups/cups.sock.
cupsd[4228]: No valid Listen or Port lines were found in the configuration file.
cupsd[4228]: cupsdEndProcess(pid=4228, force=0)
systemd[1]: cups.service: Failed with result 'protocol'.
systemd[1]: Failed to start CUPS Scheduler.

The logs is identical to one before - so the /run/cups/cups.sock socket is passed from systemd not from cupsd.config but cups refuses to use it.

Or maybe it expects at least one valid Listen directive coming from cupd.conf even when it could use the socket provided from systemd?

michaelrsweet commented 3 months ago

@Maryse47 Can you test against the current Github master or 2.4.x branch? The log messages indicate that service_checkin was able to add the listener from systemd but the subsequent error message indicates otherwise. I added a different message for the service_checkin failure so we'd know where the problem was getting reported.

Thanks!

Maryse47 commented 3 months ago

Here's excerpt from log using 2.4.x git branch:

systemd[1]: Starting CUPS Scheduler...
cupsd[39853]: Remote access is disabled.
cupsd[39853]: Loaded configuration file "/etc/cups/cupsd.conf"
cupsd[39853]: Using keychain "/etc/cups/ssl" for server name "localhost".
cupsd[39853]: Using default TempDir of /var/spool/cups/tmp...
cupsd[39853]: cupsdSetEnv: CUPS_CACHEDIR=/var/cache/cups
cupsd[39853]: cupsdSetEnv: CUPS_DATADIR=/usr/share/cups
cupsd[39853]: cupsdSetEnv: CUPS_DOCROOT=/usr/share/cups/doc
cupsd[39853]: cupsdSetEnv: CUPS_REQUESTROOT=/var/spool/cups
cupsd[39853]: cupsdSetEnv: CUPS_SERVERBIN=/usr/lib/cups
cupsd[39853]: cupsdSetEnv: CUPS_SERVERROOT=/etc/cups
cupsd[39853]: cupsdSetEnv: CUPS_STATEDIR=/run/cups
cupsd[39853]: cupsdSetEnv: HOME=/var/spool/cups/tmp
cupsd[39853]: cupsdSetEnv: PATH=/usr/lib/cups/filter:/usr/bin:/usr/bin:/bin:/usr/bin
cupsd[39853]: cupsdSetEnv: SOFTWARE=CUPS/2.4.10
cupsd[39853]: cupsdSetEnv: TMPDIR=/var/spool/cups/tmp
cupsd[39853]: cupsdSetEnv: USER=root
cupsd[39853]: cupsdSetEnv: CUPS_MAX_MESSAGE=2047
cupsd[39853]: Configured for up to 100 clients.
cupsd[39853]: Allowing up to 100 client connections per host.
cupsd[39853]: Using policy "default" as the default.
cupsd[39853]: Full reload complete.
cupsd[39853]: cupsdCleanFiles(path="/var/spool/cups/tmp", pattern="(null)")
cupsd[39853]: Cleaning out old files in "/var/spool/cups/tmp".
cupsd[39853]: cupsdCleanFiles(path="/var/cache/cups", pattern="*.ipp")
cupsd[39853]: Cleaning out old files in "/var/cache/cups".
cupsd[39853]: service_checkin: pid=39853
cupsd[39853]: service_checkin: 1 listeners.
cupsd[39853]: service_add_listener: Listener #1 at fd 3, "/run/cups/cups.sock".
cupsd[39853]: service_add_listener: Adding new listener #1 for /run/cups/cups.sock.
cupsd[39853]: service_checkin: No listener sockets present.
cupsd[39853]: cupsdEndProcess(pid=39853, force=0)
systemd[1]: cups.service: Failed with result 'protocol'.
systemd[1]: Failed to start CUPS Scheduler.