Bug 87505

Summary: systemd-timesyncd "Network configuration changed" spam on IPv6 router advertisements
Product: systemd Reporter: Laurentiu Nicola <lnicola>
Component: generalAssignee: systemd-bugs
Status: RESOLVED FIXED QA Contact: systemd-bugs
Severity: normal    
Priority: medium CC: daniel.schoemer, moebius282, radek, saintdev, teg
Version: unspecified   
Hardware: x86-64 (AMD64)   
OS: Linux (All)   
Whiteboard:
i915 platform: i915 features:
Attachments: Log of IPv6 router advertisements
Log of systemd-timesyncd
ip monitor log
networkd debug log
timesyncd debug log
tshark -f ip6 log

Description Laurentiu Nicola 2014-12-19 18:38:42 UTC
I'm running Arch Linux with systemd-networkd and systemd-timesyncd on a wired network.

After upgrading today to what Arch calls systemd 218-1, I'm getting a lot of messages in journal:

Dec 19 20:09:04 q1900 systemd-timesyncd[457]: Using NTP server 89.36.93.9:123 (2.arch.pool.ntp.org).
Dec 19 20:09:04 q1900 systemd-timesyncd[457]: interval/delta/delay/jitter/drift 2048s/-0.006s/0.006s/0.000s/+6ppm
Dec 19 20:09:14 q1900 systemd-timesyncd[457]: Network configuration changed, trying to establish connection.
Dec 19 20:09:14 q1900 systemd-timesyncd[457]: Using NTP server 89.36.93.9:123 (2.arch.pool.ntp.org).
Dec 19 20:09:14 q1900 systemd-timesyncd[457]: interval/delta/delay/jitter/drift 2048s/-0.005s/0.006s/0.000s/+6ppm
Dec 19 20:09:23 q1900 systemd-timesyncd[457]: Network configuration changed, trying to establish connection.
Dec 19 20:09:23 q1900 systemd-timesyncd[457]: Using NTP server 89.36.93.9:123 (2.arch.pool.ntp.org).
Dec 19 20:09:23 q1900 systemd-timesyncd[457]: interval/delta/delay/jitter/drift 2048s/-0.006s/0.006s/0.000s/+6ppm
Dec 19 20:09:32 q1900 systemd-timesyncd[457]: Network configuration changed, trying to establish connection.


I'm pretty much sure that my network doesn't go up and down that often and I've never seen those before, so I suspect it's a regression in the latest version. In the meanwhile I disabled timesyncd to reduce the load on my NTP server.
Comment 1 Daniel Schömer 2014-12-20 12:30:18 UTC
I notice the same behaviour of systemd-timesyncd after upgrading from 217 to 218.

To me it seems to be related to the event(s) received by timesyncd (sent by networkd?) on IPv6 router advertisements.

Each time my home router sends a router advertisment, timesyncd "thinks" the network configuration has changed. See attached ipv6-router-advertisment.log and systemd-timesyncd.log.

My home router is using radvd 1.13. radvd is sents router advertisements every few seconds. As far as I understood, this is the default behaviour of radvd.
Comment 2 Daniel Schömer 2014-12-20 12:30:45 UTC
Created attachment 111081 [details]
Log of IPv6 router advertisements
Comment 3 Daniel Schömer 2014-12-20 12:30:58 UTC
Created attachment 111082 [details]
Log of systemd-timesyncd
Comment 4 Daniel Schömer 2014-12-20 13:10:08 UTC
I compared running combinations of networkd and timesyncd of systemd 217 and 218:

networkd | timesyncd | result
-------- | --------- | ------
   217   |    217    | OK
   218   |    218    | timesyncd "net conf changed" on IPv6 router adv.
   217   |    218    | timesyncd "net conf changed" on IPv6 router adv.
   218   |    217    | OK
Comment 5 Laurentiu Nicola 2014-12-20 15:42:55 UTC
Daniel Schömer's analysis is correct, I can confirm the link between IPv6 router advertisements and the "network configuration changed" messages.
Comment 6 Lennart Poettering 2015-02-04 16:01:16 UTC
Fixed in git.
Comment 7 Lennart Poettering 2015-02-04 17:10:07 UTC
Actually, as Zbigniew pointed out to the ML my fix of just suppressing the log output is not really enough, we should also not constantly restart the NTP query logic when the system gets an IPv6 RA packet... This would mean we'd send a bunch of NTP packets for each RA packet, and that would be bad.

Reopening hence.

Not sure what the best strategy for this is though... If the kernel wakes us up even on each RA, then we kinda need to compare the whole network config before doing anything. And I am not sure I want that...
Comment 8 Zbigniew Jedrzejewski-Szmek 2015-02-09 17:42:40 UTC
Tom, would it be possible to filter those messages on systemd-networkd side by detecting state changes which do not change anything? Based on attachment #1 [details] [review], those router advertisements are actually all the same.
Comment 9 Tom Gundersen 2015-02-10 15:24:31 UTC
Hm, if networkd is causing this we should definitely filter it. Looking at the code I could not figure out what is causing us to send these repeated announcements though... We send messages on state changes and when an interface gets a new address (but not when we change an existing address).

Could someone who can reproduce this please run both networkd and timesyncd with SYSTEMD_LOG_LEVEL=debug and upload the logs? Would also be useful to run "ip monitor" at the same time as that will catch any spurious NEW_ADDR / NEW_LINK messages that we may be mishandling.
Comment 10 Daniel Schömer 2015-02-14 09:23:14 UTC
Created attachment 113482 [details]
ip monitor log
Comment 11 Daniel Schömer 2015-02-14 09:23:31 UTC
Created attachment 113483 [details]
networkd debug log
Comment 12 Daniel Schömer 2015-02-14 09:23:46 UTC
Created attachment 113484 [details]
timesyncd debug log
Comment 13 Daniel Schömer 2015-02-14 09:24:02 UTC
Created attachment 113485 [details]
tshark -f ip6 log
Comment 14 Daniel Schömer 2015-02-14 09:25:08 UTC
I uploaded the logs of ip monior, networkd, timesyncd and tshark.
Comment 15 Daniel Schömer 2015-03-08 11:02:35 UTC
As of systemd 219, timesyncd is syncing at expected intervals (64s, ...)
Comment 16 Zbigniew Jedrzejewski-Szmek 2015-03-13 04:44:23 UTC
Closing then. Please reopen if you see the issue again.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.