Changed kalman offset message to debug level

[jpds]

After deploying ntpd-rs on my systems, the system logs are peppered with:

ntp-daemon[2022]: 2025-04-28T22:16:44.902268Z  INFO ntp_proto::algorithm::kalman: Offset: -9.71569488420898+-5.958433943105912ms, frequency: -0.029784204729893793+-1.5403756385090928pp

Which isn't useful to the average system admin, hence reduce this message to debug.

[rnijveld]

This is the core functionality of our daemon (i.e. determining what the time and frequency offsets are). I'm not sure what should be an info level log message, if this is not it? If you're not interested in that information, you could also increase the log level to warn or higher?

[rnijveld]

I do think that the messages themselves might a little too spammy though: the formatting isn't great (way to many digits, most of them realistically completely useless information) and the number of messages might be too high especially when you have many sources (even more so with a low max poll interval) given that we get these messages most of the time when we receive a new packet from a source.

[jpds]

I'm interested in this message at info:

ntpd-rs/ntp-proto/src/algorithm/kalman/mod.rs

Line 275 in b8e5b2c

info!("Jumped offset by {}ms", change * 1e3);

- but not these ones.

[davidv1992]

Perhaps the better solution here is to make those jumps a warning. Thinking about this, that makes a certain amount of sense to me as it is something that may cause issues (not all software likes the system time jumping around) although it can be unavoidable. What do you think @rnijveld

[jpds]

I have now been running ntpd-rs on 8 bare metal servers I manage for a month. Here are some stats of you folks on how noisy this single log message is:

Let's see the stats of how many messages in total ntpd-rs has produced, timestamp here is last 30 days:

SELECT host, count(message) FROM journald.logs WHERE ( timestamp >= $__fromTime AND timestamp <= $__toTime ) AND ( unit LIKE '%ntpd-rs%' ) GROUP by host ORDER by host

I have a host that's produced almost ¾ of a million messages. Let's filter out any message with 'kalman' in it:

SELECT host, count(message) FROM journald.logs WHERE ( timestamp >= $__fromTime AND timestamp <= $__toTime ) AND ( unit LIKE '%ntpd-rs%' ) AND ( NOT message LIKE '%kalman%' ) GROUP by host ORDER by host

Well, that host that has suddenly dropped to just 294 messages. The ones with other higher counts of 10k+ are because I have some hosts on a network that can't get to the local IPv6 server thanks to #1880 so that logs is being filled with INFO ntpd::daemon::system: new source messages.

Here's a graph of the volume of all messages:

And here's a graph of the same time period WITHOUT the kalman messages:

Here the light blue, green and orange are the messages related IPv6 source mentioned above.

Here's how quiet a host is with no IPv6 problems, or kalman messages:

Basically, on boot-up; does the initial DNS resolution for the pool servers, logs the IPs and is then... essentially... silent.

[rnijveld]

Sorry for the slow response, we've been discussing this a little internally, but haven't quite figured out a way forward yet. We do agree that the number of messages is a concern at the very least, but we also think that just moving this log message to a lower level isn't the way forward. I've summed up our current considerations in #1912, if you have any ideas we'd love to hear them in there, but I'll close this PR for now until we've found a good solution going forward. Thanks for all the effort you've put into this so far though!