git bisect says:

d37b7bed305dbed7b5351038850ef6bbb7ed9c59 is the first bad commit
commit d37b7bed305dbed7b5351038850ef6bbb7ed9c59
Author: Dan Williams <dcbw@redhat.com>
Date:   Thu Oct 2 15:58:44 2014 -0500

    core: let kernel add IPv6LL address when method=ignore (rh #1132938)
    
    The IPv6LL address handling in userspace patches failed to handle the
    case where the IPv6 method was 'ignore'.  Previously the kernel would
    usually add the IPv6LL address itself, but if NM has turned off kernel
    IPv6LL then obviously this wouldn't happen.  So when the method is
    'ignore', turn off userspace IPv6LL handling and bounce disable_ipv6
    to make the kernel add the IPv6LL address if it wants to.

The following shell script reproduces the problem easily on my F21 system running NM git master (f6fba86984):

while :; do
  ip link del TESTDEV 2>/dev/null # clean up from previous iteration
  ip link add TESTDEV type bridge
  ip -6 route add 2001:db8::1 dev TESTDEV
  sleep 0.1 # give NM time to do its evil deed
  if ip -6 route list dev TESTDEV | grep -q 2001:db8::1; then
    echo 'OK (the route is still there)'
  else
    echo 'FAIL (the route has been removed)'
  fi
done

Keep an "ip -6 monitor route | grep TESTDEV" running in another xterm to see what's going on. I see it resulting in these two lines being repeated:

2001:db8::1 dev TESTDEV  metric 1024 
Deleted 2001:db8::1 dev TESTDEV  metric 1024 

It doesn't always fail, just most of the time. I therefore suspect there's a race condition at the heart of this issue.

Tore

Few notes: Does not seem to happen for dummy interfaces, happens with bridges. A short delay between the device creation and route addition mitigates the issue.

For what it's worth, clatd uses tun interfaces and is impacted, so it's not only bridges. The reason I used link type 'bridge' in the reproducing script is simply that it was the first one listed in ip-link(8)...

Tore, which kernel are you running?

3.17.4-301.fc21.x86_64. (This is a fully updated F21 with NM git master.)

Tore

Hmm, this looks like a kernel problem to me.

If a route addition immediately follows link addition, get_kernel_object() for the route will not find the object.

nl_cache_alloc_and_fill() won't see it either, looks like the kernel does not include in the dump at all.

The route gets deleted when we disable ipv6:

 0xffffffff816fb152 : fib6_del+0xa2/0x390 [kernel]
 0xffffffff816fb4bc : fib6_clean_node+0x7c/0x100 [kernel]
 0xffffffff816f8d16 : fib6_walk_continue+0x196/0x1d0 [kernel]
 0xffffffff816f9783 : fib6_walk+0x53/0x90 [kernel]
 0xffffffff816fb5e6 : fib6_clean_all+0xa6/0x100 [kernel]
 0xffffffff816f86ae : rt6_ifdown+0x3e/0x100 [kernel]
 0xffffffff816eddd0 : addrconf_ifdown+0x40/0x410 [kernel]
 0xffffffff816f16ca : addrconf_notify+0x7a/0xa80 [kernel]
 0xffffffff816f2117 : dev_disable_change+0x47/0x80 [kernel]
 0xffffffff816f225d : addrconf_sysctl_disable+0x10d/0x1c0 [kernel]
 0xffffffff812823c3 : proc_sys_call_handler+0xd3/0xf0 [kernel]
 0xffffffff812823f4 : proc_sys_write+0x14/0x20 [kernel]
 0xffffffff8120c597 : vfs_write+0xb7/0x1f0 [kernel]
 0xffffffff8120d1c5 : sys_write+0x55/0xd0 [kernel]
 0xffffffff81746ae9 : system_call_fastpath+0x16/0x1b [kernel]

(I don't think this should block nm-1.0, bug 682947)

I think this should be fixed by bug 734149, merge http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=4e530adf60d65e76252ad9e32ee1788c028abb27


Note that it needs kernel and libnl support.

3.17.4-301.fc21.x86_64 should have support for IFLA_INET6_ADDR_GEN_MODE,
but libnl3 doesn't...


doing libnl3 update for F21 now...

(In reply to comment #9)

> doing libnl3 update for F21 now...

http://koji.fedoraproject.org/koji/buildinfo?buildID=598009

Thomas, with 3.17.4-301.fc21.x86_64, libnl3-3.2.25-5.fc21.x86_64, and NM git master (e439478c, built *after* libnl3[-devel] was upgraded), I can still reproduce the problem after a full reboot, both with my shell loop in comment #2 and with clatd. No apparent improvement wrt. frequency of failures either.

That this issue breaks third-party software is IMHO a pretty good reason to get it fixed before nm-1.0...

Tore

Tore, if you run NM with 'debug' log level, do you see messages about NM enabling "userspace IPv6LL"?

Created attachment 292663 [details]
NM debug output

Dan, I see both "[devices/nm-device.c:4241] set_nm_ipv6ll(): [0x7f6e806d6ca0] (TESTDEV): will disable userland IPv6LL" and "[devices/nm-device.c:4241] set_nm_ipv6ll(): [0x7f6e806d6990] (TESTDEV): will enable userland IPv6LL" when I run the shell script to reproduce. Debug-level log of a few seconds runtime attached.

Tore

*** Bug 741489 has been marked as a duplicate of this bug. ***

maybe it's caused by:

http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=70f227f5528d74957f397f7e431cd15677fd95e4

I think we should not set sysctl values for assumed connections:
https://bugzilla.redhat.com/show_bug.cgi?id=1173087#c3


(similarly, set_nm_ipv6ll() should be a NOP on assumed connections)

(In reply to comment #15)
> maybe it's caused by:
> 
> http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=70f227f5528d74957f397f7e431cd15677fd95e4

No, it's caused by:

http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=d37b7bed305dbed7b5351038850ef6bbb7ed9c59

I bisected it, see comment #1.

Tore

(In reply to comment #16)
> (In reply to comment #15)
> > maybe it's caused by:
> > 
> > http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=70f227f5528d74957f397f7e431cd15677fd95e4
> 
> No, it's caused by:
> 
> http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=d37b7bed305dbed7b5351038850ef6bbb7ed9c59
> 
> I bisected it, see comment #1.
> 
> Tore

oh, you are right. Btw, there is also related:

http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=9a6e1e86cc6fa1353f3231fbc2783d237a520039


So, seems like the solutions is:

diff --git i/src/devices/nm-device.c w/src/devices/nm-device.c
index cd548d2..b3464ca 100644
--- i/src/devices/nm-device.c
+++ w/src/devices/nm-device.c
@@ -4415,9 +4415,11 @@ act_stage3_ip6_config_start (NMDevice *self,
                * to kernel IPv6LL, but the kernel won't actually assign an address
                * to the interface until disable_ipv6 is bounced.
                */
-              set_nm_ipv6ll (self, FALSE);
-              nm_device_ipv6_sysctl_set (self, "disable_ipv6", "1");
-              restore_ip6_properties (self);
+              if (!nm_device_uses_assumed_connection (self))
+                   set_nm_ipv6ll (self, FALSE);
+                   nm_device_ipv6_sysctl_set (self, "disable_ipv6", "1");
+                   restore_ip6_properties (self);
+              }
          }
          return NM_ACT_STAGE_RETURN_STOP;
     }

(In reply to comment #17)
> (In reply to comment #16)
> > (In reply to comment #15)
> > > maybe it's caused by:
> > > 
> > > http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=70f227f5528d74957f397f7e431cd15677fd95e4
> > 
> > No, it's caused by:
> > 
> > http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=d37b7bed305dbed7b5351038850ef6bbb7ed9c59
> > 
> > I bisected it, see comment #1.
> > 
> > Tore
> 
> oh, you are right. Btw, there is also related:
> 
> http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=9a6e1e86cc6fa1353f3231fbc2783d237a520039
> 
> 
> So, seems like the solutions is:

no, this alone does not fix it yet.
We need to avoid setting sysctl more carefully.
I'd go with https://bugzilla.redhat.com/show_bug.cgi?id=1173087#c3

We have to be careful though, because if NM itself manages the interface, and then you restart NM, userland IPv6LL will still be enabled on the interface.  Then NM takes over the interface again, but doesn't touch userland IPvLL.  If something happens to the IPv6 address, then NM wont' re-add it, and the kernel won't re-add it either.

That was the reason that act_stage3_ip6_config_start() didn't check nm_device_uses_assumed_connection() in the first place...  but yeah, I guess NM shouldn't bounce disable_ipv6 if there's already a LL address on the interface?

(In reply to comment #19)
> I guess NM shouldn't bounce disable_ipv6 if there's already a LL address on the interface?

Not sure if that helps in all cases. At least when TAYGA creates its TUN interface, no IPv6 LL address is configured automatically, yet it is the bouncing of disable_ipv6 on that interface that breaks it.

Tore

Created attachment 292797 [details]
[PATCH] device: Don't touch sysctls when the device is becoming managed

I'm wondering if this looks right?

11:26 < lrintel> thaller: the skip_assumed patch won't fix tore_'s ipv6_disabled bounce issue, as at the point we touch the sysctls (two places in transition from unmanaged to unavailable with NOW_MANAGED reason) there's no assumed connection
11:26 < lrintel> thaller: I can't figure out why do we run the device cleanup at that point. this would certainly fix the problem, but I can't really tell whether it doesn't break anything else
11:35 < thaller> lrintel, I don't know either... It looks right to me though...

Created attachment 292823 [details]
debug-level logs from reproducing problem with clatd+nm with patch applied

(In reply to comment #21)
> [PATCH] device: Don't touch sysctls when the device is becoming managed

I tried this patch on top of today's git master. It doesn't quite fix the problem. I can no longer reproduce it using the shell loop in comment #2, but TAYGA (and thus clatd) still has problems.

I'm attaching a debug log. Note thatit does bounce disable_ipv6 still:

des. 16 12:43:08 envy.fud.no NetworkManager[18536]: <debug> [1418730188.292041] [platform/nm-linux-platform.c:2052] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/clat/disable_ipv6' to '1' (current value is '0')
des. 16 12:43:08 envy.fud.no NetworkManager[18536]: <debug> [1418730188.293408] [platform/nm-linux-platform.c:2052] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/clat/disable_ipv6' to '0' (current value is '1')

It's not 100% reproducable though, so it's probably some race condition.

Tore

Tore, any chance you can try dcbw/external-managed-iffup-rh1030947 and see if that fixes the issue?  If not, could you grab debug logs from when the itnerface is created to when it gets touched improperly?

Created attachment 292847 [details]
debug log with dcbw/external-managed-iffup-rh1030947

(In reply to comment #23)
> Tore, any chance you can try dcbw/external-managed-iffup-rh1030947 and see if
> that fixes the issue?  If not, could you grab debug logs from when the
> itnerface is created to when it gets touched improperly?

Tried it, it does *not* fix the issue. fc16bd4787 *without* the patch from comment #21. Debug log attached, it shows disable_ipv6 being bounced.

Tore

(In reply to comment #24)
> Created an attachment (id=292847) [details]
> debug log with dcbw/external-managed-iffup-rh1030947
> 
> (In reply to comment #23)
> > Tore, any chance you can try dcbw/external-managed-iffup-rh1030947 and see if
> > that fixes the issue?  If not, could you grab debug logs from when the
> > itnerface is created to when it gets touched improperly?
> 
> Tried it, it does *not* fix the issue. fc16bd4787 *without* the patch from
> comment #21. Debug log attached, it shows disable_ipv6 being bounced.

Thanks; it looks like the external-managed-iffup branch does make things better earlier, probably due to the changes that prevent some of the IPv6 setup for assumed connections and the !IFF_UP blocking assumption.

But it toggles disable_ipv6 here:

act_stage3_ip6_config_start():

	if (strcmp (method, NM_SETTING_IP6_CONFIG_METHOD_IGNORE) == 0) {
		if (!priv->master) {
			/* When activating an IPv6 'ignore' connection we need to revert back
			 * to kernel IPv6LL, but the kernel won't actually assign an address
			 * to the interface until disable_ipv6 is bounced.
			 */
---->			set_nm_ipv6ll (self, FALSE);
			nm_device_ipv6_sysctl_set (self, "disable_ipv6", "1");
			restore_ip6_properties (self);
		}
		return NM_ACT_STAGE_RETURN_STOP;
	}

Tore, what if you do this to nm-device.c::act_stage3_ip6_config_start():

	if (strcmp (method, NM_SETTING_IP6_CONFIG_METHOD_IGNORE) == 0) {
		if (!priv->master) {
			/* When activating an IPv6 'ignore' connection we need to revert back
			 * to kernel IPv6LL, but the kernel won't actually assign an address
			 * to the interface until disable_ipv6 is bounced.
			 */
			set_nm_ipv6ll (self, FALSE);
--->			if (!have_ip6_address (priv->ip6_config, TRUE))
--->				nm_device_ipv6_sysctl_set (self, "disable_ipv6", "1");
			restore_ip6_properties (self);
		}
		return NM_ACT_STAGE_RETURN_STOP;
	}

(In reply to comment #21)
> Created an attachment (id=292797) [details]
> [PATCH] device: Don't touch sysctls when the device is becoming managed
> 
> I'm wondering if this looks right?
> 
> 11:26 < lrintel> thaller: the skip_assumed patch won't fix tore_'s
> ipv6_disabled bounce issue, as at the point we touch the sysctls (two places in
> transition from unmanaged to unavailable with NOW_MANAGED reason) there's no
> assumed connection
> 11:26 < lrintel> thaller: I can't figure out why do we run the device cleanup
> at that point. this would certainly fix the problem, but I can't really tell
> whether it doesn't break anything else
> 11:35 < thaller> lrintel, I don't know either... It looks right to me though...

The only reasons for the UNMANAGED to UNAVAILABLE state transition currently are:

1) CONNECTION_ASSUMED - assuming unmanaged devices when they get config
2) NOW_MANAGED - nm-managed devices that don't have any config to assume
3) VLANs that become managed when their parent does (for the parent's reason)

Unless I'm mis-reading the patch, it will effectively disable setting a known device state (including preventing kernel IPv6LL, and turning off kernel RA) for case #2 now.  Case #3 will still have the previous behavior (depending on the parent interface state reason).

I think that will make normally-managed devices (like wired) have some pretty odd behavior though, since kernel IPv6LL and RA aren't turned off for normally-managed ethernet.  Wouldn't that cause the kernel to assign an LL address and then listen for IPv6 RA on connected ethernet interface, even if no connection is set autoconnect=yes?  NM would then see the IP config and "assume" the IPv6 connection that the kernel created, which we currently try to prevent to ensure there isn't any IP connectivity unless the user wanted some.

Created attachment 292856 [details]
debug log with dcbw/external-managed-iffup-rh1030947 + patch from comment #25

(In reply to comment #25)

> Tore, what if you do this to nm-device.c::act_stage3_ip6_config_start():

Doesn't help, disable_ipv6 still gets bounced after clatd has added the IPv6 route. Debug log attached.

Tore

Created attachment 292859 [details] [review]
0001-core-don-t-bounce-disable_ipv6-if-NM-IPv6LL-wasn-t-e.patch

Comment on attachment 292859 [details] [review]
0001-core-don-t-bounce-disable_ipv6-if-NM-IPv6LL-wasn-t-e.patch

looks right

I have tested 0001-core-don-t-bounce-disable_ipv6-if-NM-IPv6LL-wasn-t-e.patch. I tried it both on top of of master (b169f222) and dcbw/external-managed-iffup-rh1030947 (b86c511d), the resul
ts were identical.

The clatd test is now successful, the IPv6 route does not get removed by NM anymore. However, I noted that I get the following warning in the NM log every time clatd starts:

nm_device_set_initial_unmanaged_flag: assertion 'priv->path == NULL' failed

The synthetic test case in comment #2 still fails, so I guess there's still some corner cases to work out. Every time "ip link add TESTDEV type bridge" is run, the following warnings show up in the log:

nm_device_set_initial_unmanaged_flag: assertion 'priv->path == NULL' failed
(devices/nm-device.c:7426):_set_state_full: runtime check failed: (priv->in_state_changed == FALSE)

Tore

(In reply to comment #30)
> I have tested 0001-core-don-t-bounce-disable_ipv6-if-NM-IPv6LL-wasn-t-e.patch.
> I tried it both on top of of master (b169f222) and
> dcbw/external-managed-iffup-rh1030947 (b86c511d), the resul
> ts were identical.
> 
> The clatd test is now successful, the IPv6 route does not get removed by NM
> anymore. However, I noted that I get the following warning in the NM log every
> time clatd starts:
> 
> nm_device_set_initial_unmanaged_flag: assertion 'priv->path == NULL' failed

Noticed that too. Shouldn't make any harm though.
http://paste.fedoraproject.org/160503/18810831

> The synthetic test case in comment #2 still fails, so I guess there's still
> some corner cases to work out.

It works for me and I don't see anything suspicious in my log. I'm running e099433b01955fd8b3087053c03b547fee25fc6a (the nm-1-0 branch).

I'm wondering if you could attach your log with --debug --log-level=DEBUG?

Thank you!

Oh, my tree was not clean -- I had the aforementioned patch applied and it indeed seems to make difference. Sorry for the confusion.

Could you please confirm if it fixes the test for you?

Thanks!

(In reply to comment #30)
> I have tested 0001-core-don-t-bounce-disable_ipv6-if-NM-IPv6LL-wasn-t-e.patch.
> I tried it both on top of of master (b169f222) and
> dcbw/external-managed-iffup-rh1030947 (b86c511d), the resul
> ts were identical.
> 
> The clatd test is now successful, the IPv6 route does not get removed by NM
> anymore. However, I noted that I get the following warning in the NM log every
> time clatd starts:
> 
> nm_device_set_initial_unmanaged_flag: assertion 'priv->path == NULL' failed

The branch was merged and that function is no longer there, so I think this warning should be gone on git master (and 1.0).

(In reply to comment #33)
> (In reply to comment #30)
> > I have tested 0001-core-don-t-bounce-disable_ipv6-if-NM-IPv6LL-wasn-t-e.patch.
> > I tried it both on top of of master (b169f222) and
> > dcbw/external-managed-iffup-rh1030947 (b86c511d), the resul
> > ts were identical.
> > 
> > The clatd test is now successful, the IPv6 route does not get removed by NM
> > anymore. However, I noted that I get the following warning in the NM log every
> > time clatd starts:
> > 
> > nm_device_set_initial_unmanaged_flag: assertion 'priv->path == NULL' failed
> 
> The branch was merged and that function is no longer there, so I think this
> warning should be gone on git master (and 1.0).

lubomir is correct and I mis-merged the branch.  So git master and 1.0 will have this warning.  Fixing...

(In reply to comment #31)
> (In reply to comment #30)
> > I have tested 0001-core-don-t-bounce-disable_ipv6-if-NM-IPv6LL-wasn-t-e.patch.
> > I tried it both on top of of master (b169f222) and
> > dcbw/external-managed-iffup-rh1030947 (b86c511d), the resul
> > ts were identical.
> > 
> > The clatd test is now successful, the IPv6 route does not get removed by NM
> > anymore. However, I noted that I get the following warning in the NM log every
> > time clatd starts:
> > 
> > nm_device_set_initial_unmanaged_flag: assertion 'priv->path == NULL' failed
> 
> Noticed that too. Shouldn't make any harm though.
> http://paste.fedoraproject.org/160503/18810831

This patch does fix the issue, but it gets run too early to figure out if the device is NM owned or not, unfortunately.  I think we actually need an internal NMDevice boolean for 'initialized' which nm_device_finish_init() sets, and nm_device_set_initial_unmanaged_flag() checks instead of priv->path.

Created attachment 292916 [details] [review]
0001-core-fix-setting-initial-EXTERNAL_DOWN-unmanaged-fla.patch

I pushed  0001-core-fix-setting-initial-EXTERNAL_DOWN-unmanaged-fla.patch to git master and 1.0 since it had positive review...

Lets continue to work on not touching sysctls though since I think there's still cases where NM could do that, though with not as bad consequences anymore.

Lubomir, could you rework the patch re comment 26?  Or does the sysctl branch that you posted supercede that patch?

(In reply to comment #37)
> I pushed  0001-core-fix-setting-initial-EXTERNAL_DOWN-unmanaged-fla.patch to
> git master and 1.0 since it had positive review...

Grr, I meant  0001-core-don-t-bounce-disable_ipv6-if-NM-IPv6LL-wasn-t-e.patch

tore says:

(12:00:10 PM) tore_: dcbw: that combo does indeed look good. no route removals neither for clatd or the syntethic test with a bridge interface, and no error messages/assertion failures in the log

for the combo of nm-1-0 +  0001-core-fix-setting-initial-EXTERNAL_DOWN-unmanaged-fla.patch

Comment on attachment 292916 [details] [review]
0001-core-fix-setting-initial-EXTERNAL_DOWN-unmanaged-fla.patch

I'd commented on this on IRC yesterday, but this looks fine, other than the fact that we should update the nm_device_set_initial_unmanaged_flag() docs to clarify exactly what it means by "before the device is exported", since we are now calling it after we call nm_device_dbus_export().

(In reply to comment #40)
> (From update of attachment 292916 [details] [review])
> I'd commented on this on IRC yesterday, but this looks fine, other than the
> fact that we should update the nm_device_set_initial_unmanaged_flag() docs to
> clarify exactly what it means by "before the device is exported", since we are
> now calling it after we call nm_device_dbus_export().

Fixed up the docs for nm_device_set_initial_unmanaged_flag() and pushed to git master and 1.0.

(In reply to comment #41)
> Fixed up the docs for nm_device_set_initial_unmanaged_flag() and pushed to git
> master and 1.0.

closing then