Increase log level for "Expiring subscriptions..."

[ckiee]

Fixes NixOS/nixpkgs#195090.

NixOS systems with Avahi enabled would previously spam the journal with
this log message once a second: this hides that spam behind the log level.

[ju1m]

@clefru asked in NixOS/nixpkgs#195090 (comment) if https://sourcegraph.com/github.com/OpenPrinting/cups/-/blob/scheduler/main.c?L978-985 is buggy? expecting expire_time = current_time + 600 to be more correct.
So, is the present merged fix only hiding the problem? or is everything right? Thanks

[clefru]

@ju1m Yes, this fix by my judgement just hides the problem. I recompiled cups with debugging symbols, so I can investigate why under my NixOS, the scheduler wakes up every second. I am particularly interested in "select_timeout" and the value in the "why" variable before it returns.

Sadly, since I recompiled cups, the issue is gone, and I have not seen the "Expiring subscriptions..." spam for the last 2-3 weeks. If somebody knows how to trigger this regression, please ping me, so I can take it apart.

(And yes, the expire_time calculation seems buggy)

[ckiee]

@clefru: Do you have the debug logging on? Does your network have some Avahi traffic?

I haven't deployed to my print server host in a while, so if you want to poke at it while it's running we can probably arrange something if timezones work out, Matrix @ckie:ckie.dev.

[ckiee]

The pattern seems to have changed on that machine to something more healthy. I think we need a larger view of how this part of CUPS works.

[..previous days follow same pattern..]
Jan 26 17:14:29 pansear cupsd[2545]: REQUEST localhost - root "POST / HTTP/1.1" 200 186 Renew-Subscription successful-ok
Jan 26 17:14:30 pansear cupsd[2545]: Expiring subscriptions...
Jan 26 17:15:00 pansear cupsd[2545]: Saving subscriptions.conf...
Jan 26 17:15:00 pansear cupsd[2545]: Expiring subscriptions...
Jan 26 17:29:30 pansear cupsd[2545]: Expiring subscriptions...
Jan 27 05:14:29 pansear cupsd[2545]: Expiring subscriptions...
Jan 27 05:14:29 pansear cupsd[2545]: REQUEST localhost - root "POST / HTTP/1.1" 200 186 Renew-Subscription successful-ok
Jan 27 05:14:30 pansear cupsd[2545]: Expiring subscriptions...
Jan 27 05:15:00 pansear cupsd[2545]: Saving subscriptions.conf...
Jan 27 05:15:00 pansear cupsd[2545]: Expiring subscriptions...
Jan 27 05:29:30 pansear cupsd[2545]: Expiring subscriptions...

[root@pansear:~]# cat /var/lib/cups/subscriptions.conf
# Subscription configuration file for CUPS v2.4.2
# Written by cupsd
NextSubscriptionId 75
<Subscription 74>
Events all
Owner anonymous
Recipient dbus://
LeaseDuration 86400
Interval 0
ExpirationTime 1674875669
NextEventId 54
</Subscription>

[zdohnal]

Hi,

this issue appears in cupsd randomly and it does not depend on subscriptions - I have seen it in several symptoms - removing job files, removing temporary printers, expiring subscriptions - the same ground is a variable which is compared with current_time is always lower than current_time, which causes cupsd doing the process every time when cupsdDoSelect() finishes.

I haven't been able to reproduce it in stable way, so I wasn't able to deliver a fix yet.

[zdohnal]

I've filed an issue to track it #604

[clefru]

I believe that I found the culprit: #604 (comment)
Let's move the discussion there. The "Expiring subscriptions" line should stay suppressed, IMHO, as it conveys almost no information.