QA » openQA Project » openQA Infrastructure

It seems as though chrony's poking the server a bit too frequently and we're getting Kiss of Death i.e. rate limiting messages:

sudo journalctl -u chronyd
May 16 04:05:52 openqa-piworker chronyd[1655]: Received KoD RATE from 45.131.109.21
May 16 04:45:46 openqa-piworker chronyd[1655]: Received KoD RATE from 45.131.109.2

Researching this a bit I'm thinking we may want to have explicit timings.

cdywan wrote:

Researching this a bit I'm thinking we may want to have explicit timings.

I also rebooted the machine just to confirm if/ how that may affect the issue:

May 17 10:49:16 openqa-piworker chronyd[1651]: System clock was stepped by 6727706.753087 seconds

Maybe we really have a lot of clock skew as there's no hardware clock? I'll try and research with a more pi-specific angle. And maybe to check how much the clock drifts in practice compared to other machines.

Apparently chronyc is quite handy for checking the last and average offset from the correct time. It seems like even now it's very far behind:

> sudo salt -C '*' cmd.run 'sudo chronyc tracking | grep offset
QA-Power8-4-kvm.qa.suse.de:
    Last offset     : -0.000000336 seconds
    RMS offset      : 0.000014526 seconds
openqa-piworker.qa.suse.de:
    Last offset     : -0.000340357 seconds
    RMS offset      : 0.000133489 seconds
grenache-1.qa.suse.de:
    Last offset     : +0.000017157 seconds
    RMS offset      : 0.000028348 seconds

Also just to confirm the salt-configured servers get no preference:

May 17 10:50:21 openqa-piworker chronyd[1651]: Selected source 10.160.0.45 (ntp2.suse.de)
May 17 11:12:58 openqa-piworker chronyd[1651]: Selected source 212.18.3.19 (2.suse.pool.ntp.org)

Updated comparison. Looking a little better without any changes:

schort-server:
    Last offset     : +0.000041056 seconds
    RMS offset      : 0.000017617 seconds
worker12.oqa.suse.de:
    Last offset     : +0.000000676 seconds
    RMS offset      : 0.000010247 seconds
openqa-piworker.qa.suse.de:
    Last offset     : +0.000068636 seconds
    RMS offset      : 0.000052300 seconds

Numbers from today for reference:

jenkins.qa.suse.de:
    Last offset     : +0.000048731 seconds
    RMS offset      : 0.000033733 seconds
openqa-piworker.qa.suse.de:
    Last offset     : -0.000231949 seconds
    RMS offset      : 0.000248844 seconds
grenache-1.qa.suse.de:
    Last offset     : +0.000027556 seconds
    RMS offset      : 0.000040324 seconds

And we're still getting the kiss of death:

May 22 23:42:00 openqa-piworker chronyd[1651]: Received KoD RATE from 89.58.51.72
May 23 10:02:20 openqa-piworker chronyd[1651]: Received KoD RATE from 89.58.51.72

cdywan wrote:

And we're still getting the kiss of death:

May 22 23:42:00 openqa-piworker chronyd[1651]: Received KoD RATE from 89.58.51.72
May 23 10:02:20 openqa-piworker chronyd[1651]: Received KoD RATE from 89.58.51.72

of course we receive that because nobody changed anything. And as previously mentioned it's likely a red herring. sudo salt --no-color \* cmd.run 'journalctl -u chronyd | grep "Received KoD" | wc -l shows that we have a plethora of "Received KoD RATE" messages mentioning various different hosts. I would not worry about that.

Have you considered excluding that specific host+service configuration from alerting? What are your plans for this ticket?

As per upstream chronyd docs the standard suggestion would be to use -s so that's something we can try i.e. by systemctl edit chronyding this:

[Service]
ExecStart=
ExecStart=/usr/sbin/chronyd -s -d

However I found little evidence this was being used on raspberry pie setups. So I searched again and it seems there's a custom service called fake.hwclock which transparently restores the clock on RaspianOS. A relevant-looking issue on balena-os.

There's meanwhile https://github.com/kristjanvalur/soft-hwclock which we could use.

And apparently systemd-timesyncd does what fake-hwclock does automatically, and
also does SNTP. it should be fine for most usecases, no need to resort
to fake-hwclock according to the person who wrote it.

all those approaches sound good but are only useful to look into after we can actually reproduce the problem more easily. Maybe try to set a completely wrong time and then trigger a reboot?

okurz wrote:

all those approaches sound good but are only useful to look into after we can actually reproduce the problem more easily. Maybe try to set a completely wrong time and then trigger a reboot?

I'm not sure how setting the wrong time on purpose would help.

The point I was trying to make was related to saving the synched time. Or rather it getting overwritten during shutdown i.e. as described in the balena-os issue the clock is reset to the wrong time at shutdown. I assume we'd want either systemd-timesyncd or soft-hwclock because they deal with the shutdown case.

cdywan wrote:

okurz wrote:

all those approaches sound good but are only useful to look into after we can actually reproduce the problem more easily. Maybe try to set a completely wrong time and then trigger a reboot?

I'm not sure how setting the wrong time on purpose would help.

It might help to more easily reproduce the problem so that afterwards you can try out your ideas for potential fixes

Maybe try to set a completely wrong time and then trigger a reboot?

sudo date -s "2 OCT 2006 18:00:00"
timedatectl
               Local time: Mon 2006-10-02 18:00:15 CEST
sudo journalctl -u chronyd
Oct 02 18:00:07 openqa-piworker chronyd[1650]: Backward time jump detected!
Oct 02 18:00:07 openqa-piworker chronyd[1650]: Can't synchronise: no selectable sources
Oct 02 18:03:20 openqa-piworker chronyd[1650]: Selected source 116.203.219.116 (2.suse.pool.ntp.org)
Oct 02 18:03:20 openqa-piworker chronyd[1650]: System clock wrong by 525622822.628523 seconds
sudo systemctl reboot
Oct 02 18:20:57 openqa-piworker chronyd[1650]: chronyd exiting
Oct 02 18:20:57 openqa-piworker systemd[1]: Stopping NTP client/server...
Oct 02 18:20:57 openqa-piworker systemd[1]: chronyd.service: Deactivated successfully.
Oct 02 18:20:57 openqa-piworker systemd[1]: Stopped NTP client/server.
-- Boot fcf5cbf3a5ac41d7bc926518fadd717b --
Feb 28 13:00:43 openqa-piworker systemd[1]: Starting NTP client/server...
Feb 28 13:00:43 openqa-piworker chronyd[1655]: chronyd version 4.1 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER +SIGND +ASYN>
Feb 28 13:00:43 openqa-piworker chronyd[1655]: Frequency 9.831 +/- 0.490 ppm read from /var/lib/chrony/drift
Feb 28 13:00:44 openqa-piworker systemd[1]: Started NTP client/server.
Feb 28 13:00:49 openqa-piworker chronyd[1655]: Selected source 10.160.255.254 (ntp3.suse.de)
Feb 28 13:00:49 openqa-piworker chronyd[1655]: System clock wrong by 7843246.825184 seconds
May 30 08:41:36 openqa-piworker chronyd[1655]: System clock was stepped by 7843246.825184 seconds
May 30 08:42:42 openqa-piworker chronyd[1655]: Selected source 10.160.0.45 (ntp2.suse.de

I got the delivery notification today. Given my previous experience with pollin.de, I don't expect the item to arrive before Monday.

Discussed in daily 2023-06-12 @nicksinger will add an alert silence and during the course of this week assemble the RTC setup.

RTC mounted and currently manually configured for testing:

# cat extraconfig.txt
dtparam=i2c_arm=on
device_tree=bcm2711-rpi-4-b.dtb
dtoverlay=i2c-rtc,ds1307

after a reboot the changes worked as expected and the RTC was detected by the system:

# dmesg | grep rtc
[   15.793539] rtc-ds1307 1-0068: registered as rtc0
[   15.796070] rtc-ds1307 1-0068: hctosys: unable to read the hardware clock

had to do "hwclock -w" to "flash" the current system time onto the RTC. After another reboot the warning regarding "unable to read" went away too:

# dmesg | grep rtc
[   15.455293] rtc-ds1307 1-0068: registered as rtc0
[   15.456510] rtc-ds1307 1-0068: setting system clock to 2023-06-13T13:00:01 UTC (1686661201)

so the only missing part is adding this to salt and enabling the alert again.

https://gitlab.suse.de/openqa/salt-states-openqa/-/merge_requests/885
We currently face issues with the deployment but since I already configured it manually I will disable our alert silence again and see if we see improvements of the situation.