Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 820752 - Log flooded with IN6_ARE_ADDR_EQUAL assertion failures
Summary: Log flooded with IN6_ARE_ADDR_EQUAL assertion failures
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: NetworkManager
Version: 17
Hardware: x86_64
OS: Linux
unspecified
low
Target Milestone: ---
Assignee: Dan Williams
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-05-10 21:14 UTC by Andrew Potter
Modified: 2012-05-29 10:28 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2012-05-15 20:28:24 UTC


Attachments (Terms of Use)
NetworkManager Debug log (deleted)
2012-05-11 22:48 UTC, Andrew Potter
no flags Details
patch (deleted)
2012-05-14 16:34 UTC, Dan Winship
no flags Details | Diff
New debug log, NetworkManager.service only (deleted)
2012-05-14 19:35 UTC, Andrew Potter
no flags Details

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.


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