On Mon 21 May 2018 at 21:53:38 +0200, Francesco Poli (wintermute) wrote:
> Dear Debian Printing Team,
> this bug report is a sort of "sequel" of #894762...
>
> After some preliminary tests, I concluded that socket activation
> was working again.
>
> Well, I was wrong! :-(
>
> After some further testing, I found out the following misbehavior.
>
> a) in my preliminary tests, the "lpq" command correctly woke cupsd up,
> and the daemon correclty exited after 60 s of inactivity
> (I have set "IdleExitTimeout 60" in /etc/cups/cupsd.conf)
I can reproduce this.
> b) on the other hand, if I print something with the "lpr" command, cupsd
> is correctly started, but it seems to never exit for inactivity:
I can reproduce this too.
> $ systemctl status cups.service
> ● cups.service - CUPS Scheduler
> Loaded: loaded (/lib/systemd/system/cups.service; enabled; vendor
> preset: ena
> Active: active (running) since Mon 2018-05-21 11:59:07 CEST; 9h ago
> Docs: man:cupsd(8)
> Main PID: 15103 (cupsd)
> Tasks: 1 (limit: 4915)
> Memory: 6.6M
> CGroup: /system.slice/cups.service
> └─15103 /usr/sbin/cupsd -l
>
> May 21 11:59:07 HOSTNAME systemd[1]: Started CUPS Scheduler.
>
> c) now, after manually quitting cupsd and after re-enabling socket
> activation:
>
> # systemctl stop cups.service
> # systemctl daemon-reload
> # systemctl restart cups.socket
>
> an "lpq" command correctly starts cupsd (again), but the daemon
> fails to exit after 60 s of inactivity
I cannot reproduce this. (Please see c) below).
> Why does cupsd fail to exit?
> What's wrong?
>
> Please help me.
>
> Thanks for your time!
Thanks for pursuing the issue.
It is some time since I last looked at socket activation of cupsd. My
experience wasn't the best then either. My setup:
1. 'cupsctl WebInterface=no LogLevel=debug2'
From https://github.com/apple/cups/issues/4874;
> Finally, the systemd support code explicitly disables idle
> exit when the web interface is enabled,.......
2. cp /usr/share/doc/cups-daemon/examples/cups-socket.localhost.conf \
/etc/systemd/system/cups.socket.d/
3. No IdleExitTimeout in cupsd.conf. The default is 60 seconds.
4. 'systemctl daemon-reload' and 'systemctl restart cups'.
a) lpq, lpadmin and lpstat access cupsd and all lead to its becoming
inactive after the 60 seconds timeout is over. The behaviour is
reliable and consistent. An error_log after using lpadmin has:
I [25/May/2018:14:23:49 +0100] Expiring subscriptions...
d [25/May/2018:14:23:49 +0100] select_timeout: JobHistoryUpdate=0
d [25/May/2018:14:23:49 +0100] select_timeout(0): 28 seconds to write dirty
config/state files
lpadmin command completed; pause for 28 seconds
I [25/May/2018:14:24:17 +0100] Saving printers.conf...
I [25/May/2018:14:24:17 +0100] Generating printcap /run/cups/printcap...
I [25/May/2018:14:24:17 +0100] Saving subscriptions.conf...
D [25/May/2018:14:24:17 +0100] cupsdSetBusyState: newbusy="Not busy",
busy="Dirty files"
I [25/May/2018:14:24:17 +0100] Expiring subscriptions...
d [25/May/2018:14:24:17 +0100] cupsdCheckJobs: 0 active jobs, sleeping=0,
ac-power=-1, reload=0, curtime=1527254657
d [25/May/2018:14:24:17 +0100] select_timeout: JobHistoryUpdate=0
d [25/May/2018:14:24:17 +0100] select_timeout(0): 86400 seconds to do nothing
28 seconds pause over. After 60 seconds IdleExitTimeout kicks in.
Therefore, it is 88 seconds before 'systemctl status cups' shows cupsd as
inactive.
The error_log does not record any of the following lines when 'lp -d....' is
used
I [25/May/2018:14:25:17 +0100] Printer sharing is off and there are no jobs
pending, will restart on demand.
I [25/May/2018:14:25:17 +0100] Scheduler shutting down normally.
d [25/May/2018:14:25:17 +0100] cupsdAddEvent(event=server-stopped,
dest=(nil)(), job=(nil)(0), text="Scheduler shutting
down normally.", ...)
d [25/May/2018:14:25:17 +0100] cupsd_send_notification(sub=0xf830b0(4),
event=0xf415e0(server-stopped))
d [25/May/2018:14:25:17 +0100] sub->pipe=14
d [25/May/2018:14:25:17 +0100] cupsd_send_notification(sub=0xf831d0(6),
event=0xfa67b0(server-stopped))
d [25/May/2018:14:25:17 +0100] sub->pipe=15
D [25/May/2018:14:25:17 +0100] cupsdMarkDirty(----S)
D [25/May/2018:14:25:17 +0100] cupsdSetBusyState: newbusy="Dirty files",
busy="Not busy"
d [25/May/2018:14:25:17 +0100] cupsdCloseAllClients() Clients=0
cupsd stops listening.
d [25/May/2018:14:25:17 +0100] cupsdStopListening: closing all listen sockets.
d [25/May/2018:14:25:17 +0100] cupsdPauseListening: Clearing input bits...
d [25/May/2018:14:25:17 +0100] cupsdRemoveSelect(fd=5)
d [25/May/2018:14:25:17 +0100] cupsdRemoveSelect(fd=4)
d [25/May/2018:14:25:17 +0100] cupsdRemoveSelect(fd=3)
d [25/May/2018:14:25:17 +0100] cupsdEndProcess(pid=11543, force=0)
d [25/May/2018:14:25:17 +0100] cupsdEndProcess(pid=11544, force=0)
d [25/May/2018:14:25:17 +0100] cupsdRemoveSelect(fd=11)
d [25/May/2018:14:25:17 +0100] cupsdRemoveSelect(fd=9)
d [25/May/2018:14:25:17 +0100] cupsdDeleteProfile(profile="(null)")
I [25/May/2018:14:25:17 +0100] Saving subscriptions.conf...
D [25/May/2018:14:25:17 +0100] cupsdSetBusyState: newbusy="Not busy",
busy="Dirty files"
D [25/May/2018:14:25:17 +0100] Removing KeepAlive/PID file
"/var/cache/cups/org.cups.cupsd".
I [25/May/2018:14:25:17 +0100] Saving job.cache...
D [25/May/2018:14:25:17 +0100] cupsdStopSelect()
b) Setting up a print queue:
lpadmin -p testq -v file:/dev/null -E -m drv:///sample.drv/generic.ppd
'lp -d <file>' consistently fails to have cupsd closing the listening
sockets. For all intents and purposes socket activation has ceased to
work for printing. On Debian 9 (stretch) with CUPS 2.2.1 tests show
idle exit happening at every other invocation of lp <shrug>.
c) Using lpadmin or lpq after doing b) sees the scheduler never becoming
inactive. The commands in c) above return the system to the state in
a).
My view is that the failure of cupsd to process a printing job and act
on IdleExitTimeout is the important aspect. I have no explanation for
cupsd not exiting but would be interested in whether the behaviour is
widespread.
Yves-Alexis Perez (cc'ed) has an interest in socket activation working. I
wonder whether he observes the behaviour described in b) when printing?
Yves-Alexis?
Regards,
Brian.
