Bug 820752 - Log flooded with IN6_ARE_ADDR_EQUAL assertion failures
Log flooded with IN6_ARE_ADDR_EQUAL assertion failures
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: NetworkManager (Show other bugs)
17
x86_64 Linux
unspecified Severity low
: ---
: ---
Assigned To: Dan Williams
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-05-10 17:14 EDT by Andrew Potter
Modified: 2012-05-29 06:28 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-05-15 16:28:24 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
NetworkManager Debug log (85.36 KB, text/plain)
2012-05-11 18:48 EDT, Andrew Potter
no flags Details
patch (4.17 KB, patch)
2012-05-14 12:34 EDT, Dan Winship
no flags Details | Diff
New debug log, NetworkManager.service only (244.45 KB, text/plain)
2012-05-14 15:35 EDT, Andrew Potter
no flags Details

  None (edit)
Description Andrew Potter 2012-05-10 17:14:43 EDT
Description of problem:
This is a wired ethernet network. Is connected to an Apple airport with IPv6 tunneling turned on; the tunneling is provided by Comcast/Xfinity.

While the network seems to work okay (including ipv6.google.com), journald is filled up with this representative sample:
 
May 10 10:39:35 mithos.talinet.net dnsmasq[997]: reading /etc/resolv.conf
May 10 10:39:35 mithos.talinet.net dnsmasq[997]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 10 10:39:35 mithos.talinet.net dnsmasq[997]: using nameserver 10.0.1.1#53
May 10 10:39:35 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:40:31 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:41:18 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:41:18 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 10 10:41:18 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 10 10:41:18 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:41:27 mithos.talinet.net dnsmasq[997]: reading /etc/resolv.conf
May 10 10:41:27 mithos.talinet.net dnsmasq[997]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 10 10:41:27 mithos.talinet.net dnsmasq[997]: using nameserver 10.0.1.1#53
May 10 10:41:27 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:43:31 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:44:26 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:44:26 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 10 10:44:26 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 10 10:44:26 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:45:11 mithos.talinet.net dnsmasq[997]: reading /etc/resolv.conf
May 10 10:45:11 mithos.talinet.net dnsmasq[997]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 10 10:45:11 mithos.talinet.net dnsmasq[997]: using nameserver 10.0.1.1#53
May 10 10:45:11 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:45:17 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:45:17 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 10 10:45:17 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 10 10:45:17 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:46:01 mithos.talinet.net dnsmasq[997]: reading /etc/resolv.conf
May 10 10:46:01 mithos.talinet.net dnsmasq[997]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 10 10:46:01 mithos.talinet.net dnsmasq[997]: using nameserver 10.0.1.1#53
May 10 10:46:01 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:46:14 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:46:14 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 10 10:46:14 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 10 10:46:14 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed

May 10 10:46:36 mithos.talinet.net dnsmasq[997]: reading /etc/resolv.conf
May 10 10:46:36 mithos.talinet.net dnsmasq[997]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 10 10:46:36 mithos.talinet.net dnsmasq[997]: using nameserver 10.0.1.1#53
May 10 10:46:36 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
May 10 10:46:36 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 10 10:46:36 mithos.talinet.net NetworkManager[787]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 10 10:46:36 mithos.talinet.net NetworkManager[787]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed


Version-Release number of selected component (if applicable):
Fedora 17, NetworkManager 0.9.4.0.7.git20120403.fc17

How reproducible:
Every reboot by default

Steps to Reproduce:
1. Have ethernet plugged in
2. Boot
3. Monitor journald
  
Actual results:
Log flooded

Expected results:
Assertion-failure free operation.

Additional info:
Comment 1 Andrew Potter 2012-05-11 18:48:39 EDT
Created attachment 583945 [details]
NetworkManager Debug log

Turned on debug logging on NetworkManager and captured the output.
Comment 2 Dan Winship 2012-05-14 10:22:22 EDT
OK, so the problem is that your IPv6 tunnel is telling you it has 2 IPv6 nameservers, but it's just actually the same server listed twice, which NM wasn't expecting and so it does something dumb, causing the warning.
Comment 3 Dan Winship 2012-05-14 12:34:53 EDT
Created attachment 584407 [details]
patch
Comment 4 Andrew Potter 2012-05-14 15:35:44 EDT
Created attachment 584453 [details]
New debug log, NetworkManager.service only

I applied the patch against the upstream NetworkManager 0e262e04e1800f312d4c40c07b6394ffacb2d34d.

While there are no assertions as expected, there is still something screwy going on causing a repetative reconfiguration, shown below. I've also attached the output of journalctl _SYSTEMD_UNIT=NetworkManager.service although it looks to be relatively the same as the previous log. 

I've also noticed that this isn't a problem when the IPv6 configuration is set to 'DHCP only', but that's probably expected.

May 14 12:10:49 mithos.talinet.net dnsmasq[796]: reading /etc/resolv.conf
May 14 12:10:49 mithos.talinet.net dnsmasq[796]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 14 12:10:49 mithos.talinet.net dnsmasq[796]: using nameserver 10.0.1.1#53
May 14 12:11:18 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 14 12:11:18 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 14 12:14:24 mithos.talinet.net dnsmasq[796]: reading /etc/resolv.conf
May 14 12:14:24 mithos.talinet.net dnsmasq[796]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 14 12:14:24 mithos.talinet.net dnsmasq[796]: using nameserver 10.0.1.1#53
May 14 12:14:28 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 14 12:14:28 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 14 12:14:36 mithos.talinet.net dnsmasq[796]: reading /etc/resolv.conf
May 14 12:14:36 mithos.talinet.net dnsmasq[796]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 14 12:14:36 mithos.talinet.net dnsmasq[796]: using nameserver 10.0.1.1#53
May 14 12:14:36 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 14 12:14:36 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 14 12:14:36 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 14 12:14:36 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 14 12:14:37 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 14 12:14:37 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 14 12:15:19 mithos.talinet.net dnsmasq[796]: reading /etc/resolv.conf
May 14 12:15:19 mithos.talinet.net dnsmasq[796]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 14 12:15:19 mithos.talinet.net dnsmasq[796]: using nameserver 10.0.1.1#53
May 14 12:16:05 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 14 12:16:05 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 14 12:17:01 mithos.talinet.net /USR/SBIN/CROND[2725]: (agpotter) CMD (/usr/bin/flexget --cron)
May 14 12:17:04 mithos.talinet.net dnsmasq[796]: reading /etc/resolv.conf
May 14 12:17:04 mithos.talinet.net dnsmasq[796]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 14 12:17:04 mithos.talinet.net dnsmasq[796]: using nameserver 10.0.1.1#53
May 14 12:17:04 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv4 routing and DNS.
May 14 12:17:04 mithos.talinet.net NetworkManager[651]: <info> Policy set 'System p5p1' (p5p1) as default for IPv6 routing and DNS.
May 14 12:21:16 mithos.talinet.net dnsmasq[796]: reading /etc/resolv.conf
May 14 12:21:16 mithos.talinet.net dnsmasq[796]: using nameserver 2002:62f4:3669:0:21e:52ff:fef1:811a#53
May 14 12:21:16 mithos.talinet.net dnsmasq[796]: using nameserver 10.0.1.1#53
Comment 5 Dan Winship 2012-05-14 15:45:38 EDT
(In reply to comment #4)
> Created attachment 584453 [details]
> New debug log, NetworkManager.service only
> 
> I applied the patch against the upstream NetworkManager

Oh! Cool, I was just putting it here for the other maintainers to look at. :)

> While there are no assertions as expected, there is still something screwy
> going on causing a repetative reconfiguration

Oh, yeah, it wasn't expected to change that; for some reason, your IPv6 tunnel is configured to send out router advertisements extremely frequently. So each time it gets one, NM checks the data in it to see if anything changed since the last one. I guess we're not checking whether we actually need to update dnsmasq or not, so it's getting "updated" even when nothing changed.
Comment 6 Dan Winship 2012-05-15 11:52:08 EDT
Pavel, see above; another thing to look at in your NMIP6Manager fixes (we're apparently emitting config-changed on RDNSS announcements even when nothing changed, resulting in unnecessary syslog spew)
Comment 7 Dan Winship 2012-05-15 16:28:24 EDT
fixed in git. since it doesn't actually affect functionality, I'm not going to worry about getting it into F17
Comment 8 Pavel Šimerda (pavlix) 2012-05-18 04:17:41 EDT
Thank you, Dan. I'll look into it.
Comment 9 Fedora Update System 2012-05-21 13:11:35 EDT
NetworkManager-0.9.4.0-9.git20120521.fc17 has been submitted as an update for Fedora 17.
https://admin.fedoraproject.org/updates/NetworkManager-0.9.4.0-9.git20120521.fc17
Comment 10 Fedora Update System 2012-05-21 13:17:37 EDT
NetworkManager-0.9.4-6.git20120521.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/NetworkManager-0.9.4-6.git20120521.fc16
Comment 11 Fedora Update System 2012-05-27 21:23:33 EDT
NetworkManager-0.9.4-6.git20120521.fc16 has been pushed to the Fedora 16 stable repository.  If problems still persist, please make note of it in this bug report.
Comment 12 Fedora Update System 2012-05-29 06:28:42 EDT
NetworkManager-0.9.4.0-9.git20120521.fc17 has been pushed to the Fedora 17 stable repository.  If problems still persist, please make note of it in this bug report.

Note You need to log in before you can comment on or make changes to this bug.