Bug 1042402

+++ This bug was initially created as a clone of Bug #1029213 +++

Description of problem:

NetworkManager starts to use 100% cpu and print
NetworkManager[959]: <error> [1384207571.670130] [platform/nm-linux-platform.c:1109] add_object(): Netlink error: Invalid address for specified address family
over and over into the system log.

I have attached backtraces of all threads in network manager and parts of the system log.

Might be related to: https://bugzilla.redhat.com/show_bug.cgi?id=1020068

Version-Release number of selected component (if applicable):
kernel-3.11.7-300.fc20.x86_64
NetworkManager-0.9.9.0-15.git20131003.fc20.x86_64
NetworkManager-openvpn-0.9.8.2-3.fc20.x86_64
NetworkManager-vpnc-0.9.8.2-2.fc20.x86_64
NetworkManager-l2tp-0.9.8-4.fc20.x86_64
NetworkManager-glib-0.9.9.0-15.git20131003.fc20.i686
NetworkManager-glib-0.9.9.0-15.git20131003.fc20.x86_64
NetworkManager-pptp-0.9.8.2-3.fc20.x86_64
NetworkManager-openvpn-gnome-0.9.8.2-3.fc20.x86_64
NetworkManager-debuginfo-0.9.9.0-15.git20131003.fc20.x86_64
NetworkManager-openconnect-0.9.8.0-2.fc20.x86_64
NetworkManager-vpnc-gnome-0.9.8.2-2.fc20.x86_64
NetworkManager-pptp-gnome-0.9.8.2-3.fc20.x86_64


How reproducible:
Hard to say. It happens during normal use of the system.

--- Additional comment from Julian Stecklina on 2013-11-11 16:11:20 CST ---



--- Additional comment from Julian Stecklina on 2013-11-11 16:12:38 CST ---

This bug has accumulated about 4G of log data during the last couple of days.

--- Additional comment from Simon Gerhards on 2013-11-13 10:49:01 CST ---

I'm hitting this bug too. For me it sometimes only repeats the log entry that Julian posted. But most of the time I get a constant repetition of the following lines:
"""
Nov 13 17:20:32 simon-desktop.local NetworkManager[407]: <info> Activation (em1) Stage 5 of 5 (IPv6 Commit) scheduled...
Nov 13 17:20:32 simon-desktop.local NetworkManager[407]: <info> Activation (em1) Stage 5 of 5 (IPv6 Commit) started...
Nov 13 17:20:32 simon-desktop.local NetworkManager[407]: <error> [1384359632.637356] [platform/nm-linux-platform.c:1109] add_object(): Netlink error: Invalid address for specified address family
Nov 13 17:20:32 simon-desktop.local NetworkManager[407]: <info> Activation (em1) Stage 5 of 5 (IPv6 Commit) complete.
"""

--- Additional comment from Dan Williams on 2013-11-13 20:30:43 CST ---

Can people experiencing this problem grab the following RPMs from:

http://people.redhat.com/dcbw/NetworkManager/fedora/netlink-error/

install them, and then see if you can reproduce the problem, and if so, what else gets printed to the logs.  These builds have additional debugging in them which should print out the address/route which cannot be added to the kernel.  This will help us debug the problem further.  Thanks!

--- Additional comment from Simon Gerhards on 2013-11-14 03:24:16 CST ---

After installing NetworkManager-0.9.9.0-16.git20131003.fc20.x86_64.rpm and NetworkManager-glib-0.9.9.0-16.git20131003.fc20.x86_64.rpm the log now repeats the following lines:
"""
Nov 14 10:15:46 simon-desktop.local NetworkManager[418]: <info> Activation (em1) Stage 5 of 5 (IPv6 Commit) scheduled...
Nov 14 10:15:46 simon-desktop.local NetworkManager[418]: <info> Activation (em1) Stage 5 of 5 (IPv6 Commit) started...
Nov 14 10:15:46 simon-desktop.local NetworkManager[418]: <error> [1384420546.28308] [platform/nm-linux-platform.c:1113] add_object(): Netlink error: Invalid address for specified address family
Nov 14 10:15:46 simon-desktop.local NetworkManager[418]: :: inet6 dev 3 scope nowhere
Nov 14 10:15:46 simon-desktop.local NetworkManager[418]: valid-lifetime forever preferred-lifetime forever
Nov 14 10:15:46 simon-desktop.local NetworkManager[418]: [54B blob data]
Nov 14 10:15:46 simon-desktop.local NetworkManager[418]: <info> Activation (em1) Stage 5 of 5 (IPv6 Commit) complete.
"""

--- Additional comment from Björn "besser82" Esser on 2013-11-14 03:43:33 CST ---

This happenes for me, too, when I'm using a dual-stack setup.  The logs show the exact output as pasted above.  When the repeated "Netlink error" appears in logs, there's no IPv6 connection anymore, but NM-applet shows a correctly assigned global IPv6-Adress.  IPv4 connections are not affected by this.

After toggling my connection with the hw-switch (or re-plugging the LAN-Cable) everything runs smooth again for some uncertain amount of time (30 mins to 2 h) and "the game" starts again...

--- Additional comment from Björn "besser82" Esser on 2013-11-14 03:46:36 CST ---

I forgot to mention: At the moment global IPv6-connection fails, NM starts to use some address from link-local/ULA fe80::-scope as default route, which actually blocks every WAN / LAN v6-traffic.

--- Additional comment from Björn "besser82" Esser on 2013-11-14 04:48:24 CST ---

This is an additional output on failure of the debugging pkgs previously mentioned:

Nov 14 11:45:51 p170hm NetworkManager[950]: nm_platform_ip6_address_add: assertion 'lifetime > 0' failed
Nov 14 11:45:51 p170hm rsyslogd-2177: imjournal: begin to drop messages due to rate-limiting

--- Additional comment from Dan Williams on 2013-11-14 10:22:16 CST ---

(In reply to Björn "besser82" Esser from comment #7)
> I forgot to mention: At the moment global IPv6-connection fails, NM starts
> to use some address from link-local/ULA fe80::-scope as default route, which
> actually blocks every WAN / LAN v6-traffic.

This may be your default IPv6 router.  Since the IPv6 router is on the same link, it's normal that your system would use the link-local address of the router as the default route.  Is there a chance you can check with wireshark and see where the IPv6 Router Advertisements come from, and if the source address of the Router Advertisements corresponds to the IPv6 address that NetworkManager uses as the default IPv6 gateway?

--- Additional comment from Björn "besser82" Esser on 2013-11-14 11:25:07 CST ---

No, the fe80::-scope isn't advertised by my IPv6-router.  My router advertises ULAs / link-local routes to fdbe:dead:beef:197::/64

But this fe80::-scope is applied by NM even if there is no IPv6-router present in the network...

--- Additional comment from Dan Williams on 2013-11-14 14:19:41 CST ---

Björn, would you mind running NM with more debugging?

nmcli g logging level debug domains device,ip4,ip6,dhcp4,dhcp6

and then lets try reconnecting the connection that causes the problem with:

nmcli con show active
<find the connection uuid or name>
nmcli dev disconnect em1
nmcli con up <uuid or name>

And you should get a lot more journal spew, including IPv6 stuff that's going to be very interesting to us.

--- Additional comment from Simon Gerhards on 2013-11-15 04:40:18 CST ---

I did the following (with output):
"""
# nmcli g logging level debug domains device,ip4,ip6,dhcp4,dhcp6
** (process:25329): CRITICAL **: nm_ip6_route_set_prefix: assertion 'prefix > 0' failed

# nmcli con show active
** (process:25483): CRITICAL **: nm_ip6_route_set_prefix: assertion 'prefix > 0' failed
NAME  UUID                                  DEVICES  DEFAULT  VPN  MASTER-PATH 
Auto  c90bccd1-3de6-41a7-823c-e03508f4221c  em1      yes      no   --          

# nmcli dev disconnect em1
** (process:25490): CRITICAL **: nm_ip6_route_set_prefix: assertion 'prefix > 0' failed

# nmcli con up c90bccd1-3de6-41a7-823c-e03508f4221c
** (process:25534): CRITICAL **: nm_ip6_route_set_prefix: assertion 'prefix > 0' failed
Connection successfully activated (D-Bus active path: /org/freedesktop/NetworkManager/ActiveConnection/1)
"""

I waited until the bug got triggered and NM used 100 % CPU. Then I disconnected em1 and extracted the log approximately since i brought the connection up.

--- Additional comment from Dan Williams on 2013-11-19 23:31:40 CST ---

(In reply to Simon Gerhards from comment #12)
> Created attachment 824466 [details]
> Debug NM log

Bizarre, your IPv6 Router is sending you a default route:

Nov 15 11:29:09 simon-desktop.local NetworkManager[401]: <debug> [1384511349.912493] [rdisc/nm-rdisc.c:123] config_changed():   route ::/0 pref 3 exp 9360

which NetworkManager should completely ignore, but isn't currently doing.  Can anyone else confirm that their IPv6 router is also doing this?

--- Additional comment from Simon Gerhards on 2013-11-20 04:06:56 CST ---

For documentation puroses:
My router is an AVM "FRITZ!Box 6320 v2 Cable (um)" on firmware version "110.05.51". The "(um)" in the name indicates that it is running a custom firmware from my ISP (Unitymedia, Germany).

--- Additional comment from Julian Stecklina on 2013-11-20 06:11:47 CST ---

I have a Fritz!Box 7312 running firmware version 117.05.51. I'll try to reproduce the problem with tcpdump enabled.

--- Additional comment from Julian Stecklina on 2013-11-20 06:17:44 CST ---

This is tcpdump output for icmpv6 traffic when network manager goes crazy. Network manager sends router solicitations in a loop!

--- Additional comment from Julian Stecklina on 2013-11-20 06:23:44 CST ---

And yes, my router also announces a ::/0 route.

--- Additional comment from Dan Williams on 2013-11-20 14:25:08 CST ---

commit 8586353b09460ec0a619058421743dd7d424a75d upstream now ignores the default route in router advertisements, like the kernel does.

--- Additional comment from Julian Stecklina on 2013-11-27 08:08:49 CST ---

Any idea whether this will be fixed until the Fedora 20 release?