Bug 820752

Summary: Log flooded with IN6_ARE_ADDR_EQUAL assertion failures
Product: [Fedora] Fedora Reporter: Andrew Potter <agpotter>
Component: NetworkManagerAssignee: Dan Williams <dcbw>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: low Docs Contact:
Priority: unspecified    
Version: 17CC: danw, dcbw, psimerda
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-05-15 20:28:24 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
NetworkManager Debug log
none
patch
none
New debug log, NetworkManager.service only none

Description Andrew Potter 2012-05-10 21:14:43 UTC
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 22:48:39 UTC
Created attachment 583945 [details]
NetworkManager Debug log

Turned on debug logging on NetworkManager and captured the output.

Comment 2 Dan Winship 2012-05-14 14:22:22 UTC
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 16:34:53 UTC
Created attachment 584407 [details]
patch

Comment 4 Andrew Potter 2012-05-14 19:35:44 UTC
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 19:45:38 UTC
(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 15:52:08 UTC
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 20:28:24 UTC
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 08:17:41 UTC
Thank you, Dan. I'll look into it.

Comment 9 Fedora Update System 2012-05-21 17:11:35 UTC
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 17:17:37 UTC
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-28 01:23:33 UTC
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 10:28:42 UTC
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.