Journalctl spam with 1/sec 'cupsd[1394]: Expiring subscriptions'

[pwaller]

Describe the bug

A clear and concise description of what the bug is.

Steps To Reproduce

Steps to reproduce the behavior:

1. journalctl
2. Observe lines of the form 'cupsd[1394]: Expiring subscriptions' continuously once per second since boot.
3. ...

Expected behavior

No log spam.

Additional context

Here is my NixOS configuration which I could identify as 'obviously' relating to printing. So far as I know, printing and scanning work fine.

{
  services.printing.enable = true;
  services.printing.drivers = [ pkgs.hplip pkgs.hplipWithPlugin ];
  services.avahi.enable = true;
  services.avahi.nssmdns = true;

  networking.firewall.allowedUDPPorts = [
    427
    5353
  ];

  nixpkgs.config.allowUnfreePredicate = pkg: builtins.elem (lib.getName pkg) [
    "hplip"
  ];
}

Notify maintainers

cc @matthewbauer

Metadata

Please run nix-shell -p nix-info --run "nix-info -m" and paste the result.

[root@hostname]# nix run nixpkgs#nix-info -- -m
warning: Nix search path entry '/nix/var/nix/profiles/per-user/root/channels/nixos' does not exist, ignoring
warning: Nix search path entry '/nix/var/nix/profiles/per-user/root/channels' does not exist, ignoring
error: file 'nixpkgs' was not found in the Nix search path (add it using $NIX_PATH or -I)

       at «string»:1:9:

            1| (import <nixpkgs> {}).stdenv.hostPlatform.system
             |         ^
(use '--show-trace' to show detailed location information)
 - system: `0`
 - host os: `Linux 5.19.9, NixOS, 22.05 (Quokka), 22.05.20220925.72783a2`
 - multi-user?: `no`
 - sandbox: `yes`
 - version: `nix-env (Nix) 2.8.1`

Note, I'm using flakes and don't have any channels configured.

[TheOPtimal]

Experiencing this too.... weird

[yorickvP]

I disabled avahi to work around this, but I'm not happy about it.

[fstamour]

I just noticed the same issue on my desktop.

[addict3d]

I disabled avahi to work around this, but I'm not happy about it.

I've also gone the route of disabling avahi for the time being.

In a discourse thread here:
https://discourse.nixos.org/t/cupsd-messages-littering-logs/20015 there are a few comments discussing potential ways to restructure launching the cups daemon, that would remediate the 'Expiring subscriptions' message.

[nixos-discourse]

This issue has been mentioned on NixOS Discourse. There might be relevant details there:

https://discourse.nixos.org/t/cupsd-messages-littering-logs/20015/7

[clefru]

Two observations:

https://sourcegraph.com/github.com/OpenPrinting/cups/-/blob/scheduler/main.c?L978-985 looks buggy. I expect something like expire_time = current_time + 600, e.g. to expire subscriptions every 10 minutes. Currently, the main loop will always expire subscriptions because current_time should always be greater than expire_time.

However, more importantly for NixOS: epoll_wait on my system always gets called with a timeout of 1 second. It would be interesting what select_timeout returns. I run Cups on a laptop and don't want extra unnecessary wakeups. It would be nice, if I could just gdb-attach to cupsd and "b select_timeout" but I haven't figured out how I use cupsd debug symbols yet to inspect the "why" variable that is conveniently set by select_timeout.

Also for some weird reason, on my system restarting cups twice fixes the issue, at least temporarily.

[clefru]

I managed to rebuild my cupsd with debugging symbols. But sadly, the spam is gone! Does somebody know how to trigger the spam? Restarting avahi-daemon.service nor dbus.service does the trick.

[ju1m]

OpenPrinting/cups#578 has been merged upstream last week, that should solve this issue. Thanks @ckiee!

[bgamari]

Note that OpenPrinting/cups#578 doesn't actually fix the problem but rather only suppresses the message. cupsd will still wake-up once per second. This bug is tracked as OpenPrinting/cups#604.

[pwaller]

Upstream received a fix in OpenPrinting/cups#767.

OpenPrinting/cups@3c23d47

It's very new so not yet released.

[pwaller]

Should have been fixed by #256378.

[moritzschaefer]

will it be in 23.11? @pwaller

[pwaller]

will it be in 23.11? @pwaller

It's on nixos-unstable now so I believe so.

[pwaller]

It was also backported to 23.05 in #257637.