GNOME Bugzilla – Bug 763513
NM misinterprets RAs containing a valid prefix lifetime = 0 sec as 5 sec
Last modified: 2016-03-15 17:32:11 UTC
When receiving an RA that contains a prefix with a valid/preferred lifetime of 0, NM misinterprets this as being 5 seconds and proceeds to un-deprecate the address in question. This causes an oscillating effect: 1) The address is deprecated, 2) unsolicted RA arrives, 3) address becomes undeprecated, 4) five seconds pass, 5) goto 1. I include some logs that show this happening at the end of this bug report. The correct behaviour is of course to let the address retain its deprecated state (i.e., continue to have valid lifetime = 0) after the RA has been received. Note that a router is expected to generate RAs with a valid prefix lifetime of 0 in the case that the delegated prefix has been changed. This causes the hosts to instantly deprecate their addresses derived prefix, instructing them to use the addresses from the new prefix instead. See RFC7084, section 4.3, requirement L-13. This NM bug breaks this assumption, because the addresses from the non-functional prefix becomes un-deprecated and thus available for (attempted, but doomed to fail) use by applications on the host. Debugging info from when observing the problem with NM Git master 6dc431b0c9 (2016-02-16): We're starting with the arrival of an RA, as shown in tcpdump. Pay attention to the "pref. time 0s" for the 2a02:fe0:c420:15a3::/64 prefix: 18:32:08.910758 IP6 (hlim 255, next-header ICMPv6 (58) payload length: 248) gateway > ff02::1: [icmp6 sum ok] ICMP6, router advertisement, length 248 hop limit 64, Flags [managed, other stateful], pref medium, router lifetime 1800s, reachable time 0ms, retrans time 0ms source link-address option (1), length 8 (1): 10:0d:7f:6d:a5:93 mtu option (5), length 8 (1): 1500 prefix info option (3), length 32 (4): fd69:c1fd:56f:61::/64, Flags [onlink, auto], valid time 384s, pref. time 84s prefix info option (3), length 32 (4): 2a02:fe0:c420:9710::/64, Flags [onlink, auto], valid time 7200s, pref. time 1800s prefix info option (3), length 32 (4): 2a02:fe0:c420:15a3::/64, Flags [onlink, auto], valid time 6206s, pref. time 0s route info option (24), length 24 (3): fd69:c1fd:56f::/48, pref=medium, lifetime=384s route info option (24), length 24 (3): 2a02:fe0:c420:9710::/60, pref=medium, lifetime=7200s rdnss option (25), length 24 (3): lifetime 1800s, addr: y.home dnssl option (31), length 40 (5): lifetime 1200s, domain(s): w5.y.home. home. advertisement interval option (7), length 8 (1): 600000ms This is what was logged by NM during the same time. Pay close attention to the line saying "nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 [...] *5sec*": mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.910997] [rdisc/nm-lndp-rdisc.c:279] event_ready(): rdisc-lndp[0x55f26d901c00,"wwp0s26u1u5i6"]: processing libndp events mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911181] [rdisc/nm-lndp-rdisc.c:279] event_ready(): rdisc-lndp[0x55f26d901cc0,"wlo1"]: processing libndp events mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911255] [rdisc/nm-lndp-rdisc.c:118] receive_ra(): rdisc-lndp[0x55f26d901cc0,"wlo1"]: received router advertisement at 72892 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911385] [rdisc/nm-rdisc.c:123] complete_address(): rdisc[0x55f26d901cc0,"wlo1"]: complete-address: using an stable-privacy address mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911508] [rdisc/nm-rdisc.c:123] complete_address(): rdisc[0x55f26d901cc0,"wlo1"]: complete-address: using an stable-privacy address mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911589] [rdisc/nm-rdisc.c:123] complete_address(): rdisc[0x55f26d901cc0,"wlo1"]: complete-address: using an stable-privacy address mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911677] [rdisc/nm-rdisc.c:474] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: router discovery configuration changed [ASD]: mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911705] [rdisc/nm-rdisc.c:475] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dhcp-level managed mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911730] [rdisc/nm-rdisc.c:480] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: gateway fe80::120d:7fff:fe6d:a593 pref 2 exp 74692 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911755] [rdisc/nm-rdisc.c:486] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: address 2a02:fe0:c420:15a3:2f85:601d:e767:bcc exp 79098 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911879] [rdisc/nm-rdisc.c:486] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: address 2a02:fe0:c420:9710:edae:91c0:5d3:29ce exp 80092 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911925] [rdisc/nm-rdisc.c:486] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: address fd69:c1fd:56f:61:f919:bcb7:45c1:be9e exp 73276 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.911962] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route fd69:c1fd:56f::/48 via fe80::120d:7fff:fe6d:a593 pref 2 exp 73276 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.912482] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route fd69:c1fd:56f:61::/64 via :: pref 0 exp 73276 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.913217] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route 2a02:fe0:c420:9710::/60 via fe80::120d:7fff:fe6d:a593 pref 2 exp 80092 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.913807] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route 2a02:fe0:c420:9710::/64 via :: pref 0 exp 80092 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.914515] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route 2a02:fe0:c420:15a0::/60 via fe80::120d:7fff:fe6d:a593 pref 2 exp 79098 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.915317] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route 2a02:fe0:c420:15a3::/64 via :: pref 0 exp 79098 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.916103] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server 2a02:fe0:c420:15a3::4c exp 79098 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.916841] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server fd7f:23b6:672e:61::4c exp 78944 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.917549] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server fd52:b325:aa36:61::4c exp 79129 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.918309] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server fd7e:bf5a:253e:61::4c exp 79313 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.919145] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server 2a02:fe0:c420:9710::4c exp 80092 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.920133] [rdisc/nm-rdisc.c:505] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_domain w5.y.home exp 80092 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.921242] [rdisc/nm-rdisc.c:505] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_domain home exp 80092 mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.922196] [devices/nm-device.c:3300] activation_source_schedule(): [0x55f26d893560] (wlo1): activation-stage: schedule activate_stage5_ip6_config_commit,10 (id 14900) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.923255] [rdisc/nm-rdisc.c:640] check_timestamps(): rdisc[0x55f26d901cc0,"wlo1"]: scheduling next now/lifetime check: 384 seconds mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.923377] [devices/nm-device.c:3262] activation_source_handle_cb(): [0x55f26d893560] (wlo1): activation-stage: invoke activate_stage5_ip6_config_commit,10 (id 14900) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.924193] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 lft 6211sec pref 5sec lifetime 72892-0[5,6211] dev 4 flags noprefixroute src unknown mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.924462] [platform/nm-platform.c:3976] log_ip6_address(): platform: signal: address 6 changed: 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 lft 6211sec pref 5sec lifetime 72892-72892[5,6211] dev 4 flags noprefixroute src kernel mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.925258] [devices/nm-device.c:8934] device_ipx_changed(): [0x55f26d893560] (wlo1): queued IP6 config change mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.925970] [nm-default-route-manager.c:1318] _resync_idle_reschedule(): default-route: resync: schedule on idle mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.926685] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: 2a02:fe0:c420:15a3:2f85:601d:e767:bcc]: success mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.927386] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: 2a02:fe0:c420:9710:edae:91c0:5d3:29ce/64 lft 7205sec pref 1805sec lifetime 72892-0[1805,7205] dev 4 flags noprefixroute src unknown mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.928145] [platform/nm-platform.c:3976] log_ip6_address(): platform: signal: address 6 changed: 2a02:fe0:c420:9710:edae:91c0:5d3:29ce/64 lft 7205sec pref 1805sec lifetime 72892-72892[1805,7205] dev 4 flags noprefixroute src kernel mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.928918] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: 2a02:fe0:c420:9710:edae:91c0:5d3:29ce]: success mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.929243] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: fd69:c1fd:56f:61:f919:bcb7:45c1:be9e/64 lft 389sec pref 89sec lifetime 72892-0[89,389] dev 4 flags noprefixroute src unknown mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.930121] [platform/nm-platform.c:3976] log_ip6_address(): platform: signal: address 6 changed: fd69:c1fd:56f:61:f919:bcb7:45c1:be9e/64 lft 389sec pref 89sec lifetime 72892-72892[89,389] dev 4 flags noprefixroute src kernel mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.930701] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: fd69:c1fd:56f:61:f919:bcb7:45c1:be9e]: success mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.931231] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: 2a02:fe0:c420:15a3::c68/128 lft 1204929sec pref 600129sec lifetime 72892-0[600129,1204929] dev 4 src unknown mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.931889] [platform/nm-platform.c:3976] log_ip6_address(): platform: signal: address 6 changed: 2a02:fe0:c420:15a3::c68/128 lft 1204929sec pref 600129sec lifetime 72892-72892[600129,1204929] dev 4 src kernel mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.932372] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: 2a02:fe0:c420:15a3::c68]: success mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.932879] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: fe80::c58d:1731:43e3:5e4b/64 lft forever pref forever lifetime 72892-0[4294967295,4294967295] dev 4 flags permanent src unknown mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.933504] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: fe80::c58d:1731:43e3:5e4b]: success mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.934007] [nm-route-manager.c:466] _vx_route_sync(): route-mgr6: 4: sync 6 IPv6 routes mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.936698] [devices/nm-device.c:7998] nm_device_set_ip6_config(): [0x55f26d893560] (wlo1): update IP6Config instance (/org/freedesktop/NetworkManager/IP6Config/23) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.936753] [nm-default-route-manager.c:663] _entry_at_idx_update(): default-route: entry[0/dev:0x55f26d893560:wlo1:1:+sync]: record:update ::/0 via fe80::120d:7fff:fe6d:a593 dev 4 metric 600 mss 0 src user (600) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.936791] [nm-default-route-manager.c:1294] _resync_idle_cancel(): default-route: resync: cancelled (14906) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.936843] [nm-default-route-manager.c:581] _resync_all(): default-route: entry[0/dev:0x55f26d893560:wlo1:1:+sync]: sync:update ::/0 via fe80::120d:7fff:fe6d:a593 dev 4 metric 600 mss 0 src user (600 -> 600) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.936868] [platform/nm-platform.c:2808] nm_platform_ip6_route_add(): platform: route: adding or updating IPv6 route: ::/0 via fe80::120d:7fff:fe6d:a593 dev 4 metric 600 mss 0 src user mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.937570] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-route[4: ::/0 600]: success mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.937774] [dns-manager/nm-dns-manager.c:1284] nm_dns_manager_begin_updates(): dns-mgr: (device_ip6_config_changed): queueing DNS updates (1) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.938338] [dns-manager/nm-dns-manager.c:1302] nm_dns_manager_end_updates(): dns-mgr: (device_ip6_config_changed): DNS configuration did not change mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.938841] [dns-manager/nm-dns-manager.c:1306] nm_dns_manager_end_updates(): dns-mgr: (device_ip6_config_changed): no DNS changes to commit (0) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.939405] [devices/nm-device.c:9843] nm_device_remove_pending_action(): [0x55f26d893560] (wlo1): remove_pending_action (0): 'dhcp6' not pending (expected) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.939845] [devices/nm-device.c:9843] nm_device_remove_pending_action(): [0x55f26d893560] (wlo1): remove_pending_action (0): 'autoconf6' not pending (expected) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.940356] [devices/nm-device.c:3267] activation_source_handle_cb(): [0x55f26d893560] (wlo1): activation-stage: complete activate_stage5_ip6_config_commit,10 (id 14900) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.944661] [devices/nm-device.c:7998] nm_device_set_ip6_config(): [0x55f26d893560] (wlo1): update IP6Config instance (/org/freedesktop/NetworkManager/IP6Config/23) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.944726] [nm-default-route-manager.c:663] _entry_at_idx_update(): default-route: entry[0/dev:0x55f26d893560:wlo1:1:-sync]: record:update ::/0 via fe80::120d:7fff:fe6d:a593 dev 4 metric 600 mss 0 src user (600) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.944797] [dns-manager/nm-dns-manager.c:1284] nm_dns_manager_begin_updates(): dns-mgr: (device_ip6_config_changed): queueing DNS updates (1) mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.944916] [dns-manager/nm-dns-manager.c:1302] nm_dns_manager_end_updates(): dns-mgr: (device_ip6_config_changed): DNS configuration did not change mars 11 18:32:08 envy NetworkManager[1046]: <debug> [1457717528.944950] [dns-manager/nm-dns-manager.c:1306] nm_dns_manager_end_updates(): dns-mgr: (device_ip6_config_changed): no DNS changes to commit (0) This is what showed up in 'ip -6 monitor | ts', confirming that the address was indeed updated to have a bogus valid lifetime of 5s: Mar 11 18:32:08 4: wlo1 inet6 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 scope global noprefixroute dynamic Mar 11 18:32:08 valid_lft 6211sec preferred_lft 5sec Mar 11 18:32:08 4: wlo1 inet6 2a02:fe0:c420:9710:edae:91c0:5d3:29ce/64 scope global noprefixroute dynamic Mar 11 18:32:08 valid_lft 7205sec preferred_lft 1805sec Mar 11 18:32:08 4: wlo1 inet6 fd69:c1fd:56f:61:f919:bcb7:45c1:be9e/64 scope global noprefixroute dynamic Mar 11 18:32:08 valid_lft 389sec preferred_lft 89sec Mar 11 18:32:08 4: wlo1 inet6 2a02:fe0:c420:15a3::c68/128 scope global dynamic Mar 11 18:32:08 valid_lft 1204929sec preferred_lft 600129sec Mar 11 18:32:08 4: wlo1 inet6 fe80::c58d:1731:43e3:5e4b/64 scope link Mar 11 18:32:08 valid_lft forever preferred_lft forever Five seconds later it becomes deprecated (as expected). NM notices: mars 11 18:32:13 envy NetworkManager[1046]: <debug> [1457717533.931288] [platform/nm-platform.c:3976] log_ip6_address(): platform: signal: address 6 changed: 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 lft 6206sec pref 0sec lifetime 72897-72892[5,6211] dev 4 flags deprecated,noprefixroute src kernel mars 11 18:32:13 envy NetworkManager[1046]: <debug> [1457717533.931514] [devices/nm-device.c:8934] device_ipx_changed(): [0x55f26d893560] (wlo1): queued IP6 config change mars 11 18:32:13 envy NetworkManager[1046]: <debug> [1457717533.931664] [nm-default-route-manager.c:1318] _resync_idle_reschedule(): default-route: resync: schedule on idle mars 11 18:32:13 envy NetworkManager[1046]: <debug> [1457717533.933225] [nm-default-route-manager.c:1264] _resync_idle_now(): default-route: resync: sync now (14915) (IPv4 changes: no, IPv6 changes: yes) And so does 'ip -6 monitor': Mar 11 18:32:13 4: wlo1 inet6 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 scope global deprecated noprefixroute dynamic Mar 11 18:32:13 valid_lft 6206sec preferred_lft 0sec Half a minute later, a new (unsolicted RA) arrives. The prefix in question is still being advertised with a preferred lifetime of 0: 18:32:39.513030 IP6 (hlim 255, next-header ICMPv6 (58) payload length: 248) gateway > ff02::1: [icmp6 sum ok] ICMP6, router advertisement, length 248 hop limit 64, Flags [managed, other stateful], pref medium, router lifetime 1800s, reachable time 0ms, retrans time 0ms source link-address option (1), length 8 (1): 10:0d:7f:6d:a5:93 mtu option (5), length 8 (1): 1500 prefix info option (3), length 32 (4): fd69:c1fd:56f:61::/64, Flags [onlink, auto], valid time 353s, pref. time 53s prefix info option (3), length 32 (4): 2a02:fe0:c420:9710::/64, Flags [onlink, auto], valid time 7200s, pref. time 1800s prefix info option (3), length 32 (4): 2a02:fe0:c420:15a3::/64, Flags [onlink, auto], valid time 6175s, pref. time 0s route info option (24), length 24 (3): fd69:c1fd:56f::/48, pref=medium, lifetime=353s route info option (24), length 24 (3): 2a02:fe0:c420:9710::/60, pref=medium, lifetime=7200s rdnss option (25), length 24 (3): lifetime 1800s, addr: y.home dnssl option (31), length 40 (5): lifetime 1200s, domain(s): w5.y.home. home. advertisement interval option (7), length 8 (1): 600000ms But NM inexplicably adds back 5 seconds of spurious valid lifetime: mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.513232] [rdisc/nm-lndp-rdisc.c:279] event_ready(): rdisc-lndp[0x55f26d901c00,"wwp0s26u1u5i6"]: processing libndp events mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.513423] [rdisc/nm-lndp-rdisc.c:279] event_ready(): rdisc-lndp[0x55f26d901cc0,"wlo1"]: processing libndp events mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.513494] [rdisc/nm-lndp-rdisc.c:118] receive_ra(): rdisc-lndp[0x55f26d901cc0,"wlo1"]: received router advertisement at 72922 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.513616] [rdisc/nm-rdisc.c:123] complete_address(): rdisc[0x55f26d901cc0,"wlo1"]: complete-address: using an stable-privacy address mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.513732] [rdisc/nm-rdisc.c:123] complete_address(): rdisc[0x55f26d901cc0,"wlo1"]: complete-address: using an stable-privacy address mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.513848] [rdisc/nm-rdisc.c:123] complete_address(): rdisc[0x55f26d901cc0,"wlo1"]: complete-address: using an stable-privacy address mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.513933] [rdisc/nm-rdisc.c:474] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: router discovery configuration changed [ASD]: mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.513960] [rdisc/nm-rdisc.c:475] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dhcp-level managed mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.513986] [rdisc/nm-rdisc.c:480] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: gateway fe80::120d:7fff:fe6d:a593 pref 2 exp 74722 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.514009] [rdisc/nm-rdisc.c:486] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: address 2a02:fe0:c420:15a3:2f85:601d:e767:bcc exp 79097 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.514030] [rdisc/nm-rdisc.c:486] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: address 2a02:fe0:c420:9710:edae:91c0:5d3:29ce exp 80122 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.514052] [rdisc/nm-rdisc.c:486] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: address fd69:c1fd:56f:61:f919:bcb7:45c1:be9e exp 73275 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.514079] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route fd69:c1fd:56f::/48 via fe80::120d:7fff:fe6d:a593 pref 2 exp 73275 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.514889] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route fd69:c1fd:56f:61::/64 via :: pref 0 exp 73275 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.515418] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route 2a02:fe0:c420:9710::/60 via fe80::120d:7fff:fe6d:a593 pref 2 exp 80122 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.515997] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route 2a02:fe0:c420:9710::/64 via :: pref 0 exp 80122 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.516488] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route 2a02:fe0:c420:15a0::/60 via fe80::120d:7fff:fe6d:a593 pref 2 exp 79098 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.517127] [rdisc/nm-rdisc.c:494] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: route 2a02:fe0:c420:15a3::/64 via :: pref 0 exp 79097 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.517665] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server 2a02:fe0:c420:15a3::4c exp 79098 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.518247] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server fd7f:23b6:672e:61::4c exp 78944 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.518801] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server fd52:b325:aa36:61::4c exp 79129 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.519429] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server fd7e:bf5a:253e:61::4c exp 79313 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.520144] [rdisc/nm-rdisc.c:500] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_server 2a02:fe0:c420:9710::4c exp 80122 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.520648] [rdisc/nm-rdisc.c:505] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_domain w5.y.home exp 80122 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.521190] [rdisc/nm-rdisc.c:505] config_changed(): rdisc[0x55f26d901cc0,"wlo1"]: dns_domain home exp 80122 mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.521838] [devices/nm-device.c:3300] activation_source_schedule(): [0x55f26d893560] (wlo1): activation-stage: schedule activate_stage5_ip6_config_commit,10 (id 14922) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.522245] [rdisc/nm-rdisc.c:640] check_timestamps(): rdisc[0x55f26d901cc0,"wlo1"]: scheduling next now/lifetime check: 353 seconds mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.522760] [devices/nm-device.c:3262] activation_source_handle_cb(): [0x55f26d893560] (wlo1): activation-stage: invoke activate_stage5_ip6_config_commit,10 (id 14922) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.523423] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 lft 6180sec pref 5sec lifetime 72922-0[5,6180] dev 4 flags noprefixroute src unknown mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.523904] [platform/nm-platform.c:3976] log_ip6_address(): platform: signal: address 6 changed: 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 lft 6180sec pref 5sec lifetime 72922-72922[5,6180] dev 4 flags noprefixroute src kernel mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.524646] [devices/nm-device.c:8934] device_ipx_changed(): [0x55f26d893560] (wlo1): queued IP6 config change mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.525257] [nm-default-route-manager.c:1318] _resync_idle_reschedule(): default-route: resync: schedule on idle mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.525846] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: 2a02:fe0:c420:15a3:2f85:601d:e767:bcc]: success mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.526353] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: 2a02:fe0:c420:9710:edae:91c0:5d3:29ce/64 lft 7205sec pref 1805sec lifetime 72922-0[1805,7205] dev 4 flags noprefixroute src unknown mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.526938] [platform/nm-platform.c:3976] log_ip6_address(): platform: signal: address 6 changed: 2a02:fe0:c420:9710:edae:91c0:5d3:29ce/64 lft 7205sec pref 1805sec lifetime 72922-72922[1805,7205] dev 4 flags noprefixroute src kernel mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.527384] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: 2a02:fe0:c420:9710:edae:91c0:5d3:29ce]: success mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.527888] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: fd69:c1fd:56f:61:f919:bcb7:45c1:be9e/64 lft 358sec pref 58sec lifetime 72922-0[58,358] dev 4 flags noprefixroute src unknown mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.529003] [platform/nm-platform.c:3976] log_ip6_address(): platform: signal: address 6 changed: fd69:c1fd:56f:61:f919:bcb7:45c1:be9e/64 lft 358sec pref 58sec lifetime 72922-72922[58,358] dev 4 flags noprefixroute src kernel mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.529518] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: fd69:c1fd:56f:61:f919:bcb7:45c1:be9e]: success mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.529981] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: 2a02:fe0:c420:15a3::c68/128 lft 1204899sec pref 600099sec lifetime 72922-0[600099,1204899] dev 4 src unknown mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.530437] [platform/nm-platform.c:3976] log_ip6_address(): platform: signal: address 6 changed: 2a02:fe0:c420:15a3::c68/128 lft 1204899sec pref 600099sec lifetime 72922-72922[600099,1204899] dev 4 src kernel mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.530918] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: 2a02:fe0:c420:15a3::c68]: success mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.531367] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: fe80::c58d:1731:43e3:5e4b/64 lft forever pref forever lifetime 72922-0[4294967295,4294967295] dev 4 flags permanent src unknown mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.531927] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-address[4: fe80::c58d:1731:43e3:5e4b]: success mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.532320] [nm-route-manager.c:466] _vx_route_sync(): route-mgr6: 4: sync 6 IPv6 routes mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.535387] [devices/nm-device.c:7998] nm_device_set_ip6_config(): [0x55f26d893560] (wlo1): update IP6Config instance (/org/freedesktop/NetworkManager/IP6Config/23) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.535424] [nm-default-route-manager.c:663] _entry_at_idx_update(): default-route: entry[0/dev:0x55f26d893560:wlo1:1:+sync]: record:update ::/0 via fe80::120d:7fff:fe6d:a593 dev 4 metric 600 mss 0 src user (600) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.535442] [nm-default-route-manager.c:1294] _resync_idle_cancel(): default-route: resync: cancelled (14928) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.535471] [nm-default-route-manager.c:581] _resync_all(): default-route: entry[0/dev:0x55f26d893560:wlo1:1:+sync]: sync:update ::/0 via fe80::120d:7fff:fe6d:a593 dev 4 metric 600 mss 0 src user (600 -> 600) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.535669] [platform/nm-platform.c:2808] nm_platform_ip6_route_add(): platform: route: adding or updating IPv6 route: ::/0 via fe80::120d:7fff:fe6d:a593 dev 4 metric 600 mss 0 src user mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.536208] [platform/nm-linux-platform.c:3781] do_add_addrroute(): platform-linux: do-add-ip6-route[4: ::/0 600]: success mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.536428] [dns-manager/nm-dns-manager.c:1284] nm_dns_manager_begin_updates(): dns-mgr: (device_ip6_config_changed): queueing DNS updates (1) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.536719] [dns-manager/nm-dns-manager.c:1302] nm_dns_manager_end_updates(): dns-mgr: (device_ip6_config_changed): DNS configuration did not change mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.537013] [dns-manager/nm-dns-manager.c:1306] nm_dns_manager_end_updates(): dns-mgr: (device_ip6_config_changed): no DNS changes to commit (0) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.537304] [devices/nm-device.c:9843] nm_device_remove_pending_action(): [0x55f26d893560] (wlo1): remove_pending_action (0): 'dhcp6' not pending (expected) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.537553] [devices/nm-device.c:9843] nm_device_remove_pending_action(): [0x55f26d893560] (wlo1): remove_pending_action (0): 'autoconf6' not pending (expected) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.537841] [devices/nm-device.c:3267] activation_source_handle_cb(): [0x55f26d893560] (wlo1): activation-stage: complete activate_stage5_ip6_config_commit,10 (id 14922) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.540759] [devices/nm-device.c:7998] nm_device_set_ip6_config(): [0x55f26d893560] (wlo1): update IP6Config instance (/org/freedesktop/NetworkManager/IP6Config/23) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.540812] [nm-default-route-manager.c:663] _entry_at_idx_update(): default-route: entry[0/dev:0x55f26d893560:wlo1:1:-sync]: record:update ::/0 via fe80::120d:7fff:fe6d:a593 dev 4 metric 600 mss 0 src user (600) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.540856] [dns-manager/nm-dns-manager.c:1284] nm_dns_manager_begin_updates(): dns-mgr: (device_ip6_config_changed): queueing DNS updates (1) mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.540890] [dns-manager/nm-dns-manager.c:1302] nm_dns_manager_end_updates(): dns-mgr: (device_ip6_config_changed): DNS configuration did not change mars 11 18:32:39 envy NetworkManager[1046]: <debug> [1457717559.540905] [dns-manager/nm-dns-manager.c:1306] nm_dns_manager_end_updates(): dns-mgr: (device_ip6_config_changed): no DNS changes to commit (0) ip -6 monitor confirms the address is no longer deprecated: Mar 11 18:32:39 4: wlo1 inet6 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 scope global noprefixroute dynamic Mar 11 18:32:39 valid_lft 6180sec preferred_lft 5sec Mar 11 18:32:39 4: wlo1 inet6 2a02:fe0:c420:9710:edae:91c0:5d3:29ce/64 scope global noprefixroute dynamic Mar 11 18:32:39 valid_lft 7205sec preferred_lft 1805sec Mar 11 18:32:39 4: wlo1 inet6 fd69:c1fd:56f:61:f919:bcb7:45c1:be9e/64 scope global noprefixroute dynamic Mar 11 18:32:39 valid_lft 358sec preferred_lft 58sec Mar 11 18:32:39 4: wlo1 inet6 2a02:fe0:c420:15a3::c68/128 scope global dynamic Mar 11 18:32:39 valid_lft 1204899sec preferred_lft 600099sec Mar 11 18:32:39 4: wlo1 inet6 fe80::c58d:1731:43e3:5e4b/64 scope link Mar 11 18:32:39 valid_lft forever preferred_lft forever This cycle will keep on repeating for as long as the prefix is included in the router's RAs.
[1457717559.523423] [platform/nm-platform.c:2472] nm_platform_ip6_address_add(): platform: address: adding or updating IPv6 address: 2a02:fe0:c420:15a3:2f85:601d:e767:bcc/64 lft 6180sec pref 5sec lifetime 72922-0[5,6180] dev 4 flags noprefixroute src unknown Probably related to ADDRESS_LIFETIME_PADDING in nm_platform_ip6_address_sync(); perhaps we shouldn't be padding 'preferred' at all here. Thomas should probably take this one...
Hm, indeed... I see now that the both lifetimes are getting five seconds added to them. What is the reason for the existence of this ADDRESS_LIFETIME_PADDING? It seems to me that the only obvious thing to do (as well as the only standards-compliant thing to do, afaik) would be to simply respect the exact lifetimes in the RA (perform no such padding).
Fixed in master: https://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=6cb73224652e4b59f9c2d6e91e61b6e61a76c4a6 Thanks Tore, for finding this.