Bug 753482

Summary: wifi drops every 15 minutes (ip-config-unavailable) because of IPv6 RDNSS timeout
Product: [Fedora] Fedora Reporter: Bill C. Riemers <briemers>
Component: NetworkManagerAssignee: Dan Williams <dcbw>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 16CC: cra, danw, dcbw, gansalmon, gbauman, ggillies, itamar, jonathan, kernel-maint, madhu.chinakonda, mathieu-acct, mishu, psimerda, ricky, satellitgo, the.ridikulus.rat
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-01-17 00:25:32 UTC Type: ---
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
excerpt from syslog (daemon.debug)
none
Comment none

Description Bill C. Riemers 2011-11-12 21:38:18 UTC
Description of problem:

About every 15 minuets

Version-Release number of selected component (if applicable):

kernel-3.1.0-7.fc16.x86_64

How reproducible:

100%

Steps to Reproduce:
1.  Connect to wifi and wait about 20 minutes.
2.
3.
  
Actual results:


Expected results:


Additional info:

I only really notice this because of the "Activation Failed" alerts, and occasionally it causes a delay in loading web pages.   So this is more an annoying bug than a critical must solve problem.
 
Nov 12 16:07:12 briemersw kernel: [12204.139598] iwlagn 0000:03:00.0: Tx aggregation enabled on ra = 48:5b:39:25:01:00 tid = 0
Nov 12 16:26:04 briemersw NetworkManager[1230]: <info> (wlan0): device state change: activated -> failed (reason 'ip-config-unavailable') [100 120 5]
Nov 12 16:26:04 briemersw NetworkManager[1230]: <warn> Activation (wlan0) failed for access point (foxtrot)
Nov 12 16:26:04 briemersw NetworkManager[1230]: <warn> Activation (wlan0) failed.
Nov 12 16:26:04 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): device state change: activated -> failed (reason 'ip-config-unavailable') [100 120 5]
Nov 12 16:26:04 briemersw NetworkManager[1230]: NetworkManager[1230]: <warn> Activation (wlan0) failed for access point (foxtrot)
Nov 12 16:26:04 briemersw NetworkManager[1230]: NetworkManager[1230]: <warn> Activation (wlan0) failed.
Nov 12 16:26:04 briemersw NetworkManager[1230]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Nov 12 16:26:04 briemersw NetworkManager[1230]: <info> (wlan0): deactivating device (reason 'none') [0]
Nov 12 16:26:04 briemersw dbus[1262]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Nov 12 16:26:04 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Nov 12 16:26:04 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): deactivating device (reason 'none') [0]
Nov 12 16:26:04 briemersw dbus-daemon[1262]: dbus[1262]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Nov 12 16:26:04 briemersw dbus[1262]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 12 16:26:04 briemersw dbus-daemon[1262]: dbus[1262]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 12 16:26:04 briemersw NetworkManager[1230]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 6712
Nov 12 16:26:04 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 6712
Nov 12 16:26:04 briemersw kernel: [13332.973217] cfg80211: Calling CRDA to update world regulatory domain
Nov 12 16:26:04 briemersw NetworkManager[1230]: <warn> could not spawn process '/etc/init.d/nscd condrestart': Failed to execute child process "/etc/init.d/nscd" (No such file or directory)
Nov 12 16:26:04 briemersw NetworkManager[1230]: NetworkManager[1230]: <warn> could not spawn process '/etc/init.d/nscd condrestart': Failed to execute child process "/etc/init.d/nscd" (No such file or directory)
Nov 12 16:26:04 briemersw NetworkManager[1230]: <warn> could not spawn process '/etc/init.d/nscd condrestart': Failed to execute child process "/etc/init.d/nscd" (No such file or directory)
Nov 12 16:26:04 briemersw NetworkManager[1230]: NetworkManager[1230]: <warn> could not spawn process '/etc/init.d/nscd condrestart': Failed to execute child process "/etc/init.d/nscd" (No such file or directory)
Nov 12 16:26:04 briemersw kernel: [13332.989578] cfg80211: World regulatory domain updated:
Nov 12 16:26:04 briemersw kernel: [13332.989581] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Nov 12 16:26:04 briemersw kernel: [13332.989584] cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Nov 12 16:26:04 briemersw kernel: [13332.989586] cfg80211:     (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Nov 12 16:26:04 briemersw kernel: [13332.989588] cfg80211:     (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Nov 12 16:26:04 briemersw kernel: [13332.989590] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Nov 12 16:26:04 briemersw kernel: [13332.989592] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Nov 12 16:26:04 briemersw kernel: [13332.989605] cfg80211: Calling CRDA for country: CA
Nov 12 16:26:04 briemersw NetworkManager[1230]: <info> (wlan0): supplicant interface state: completed -> disconnected
Nov 12 16:26:04 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): supplicant interface state: completed -> disconnected
Nov 12 16:26:04 briemersw kernel: [13332.994315] cfg80211: Regulatory domain changed to country: CA
Nov 12 16:26:04 briemersw kernel: [13332.994319] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Nov 12 16:26:04 briemersw kernel: [13332.994322] cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
Nov 12 16:26:04 briemersw kernel: [13332.994325] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
Nov 12 16:26:04 briemersw kernel: [13332.994328] cfg80211:     (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Nov 12 16:26:04 briemersw kernel: [13332.994331] cfg80211:     (5490000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Nov 12 16:26:04 briemersw kernel: [13332.994333] cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
Nov 12 16:26:05 briemersw ntpd[1235]: Deleting interface #35 wlan0, 172.31.253.112#123, interface stats: received=0, sent=0, dropped=0, active_time=1442 secs
Nov 12 16:26:05 briemersw ntpd[1235]: Deleting interface #34 wlan0, 2001:470:1d:1c6:224:d7ff:fe2c:c914#123, interface stats: received=10, sent=10, dropped=0, active_time=1445 secs
Nov 12 16:26:05 briemersw ntpd[1235]: 2001:1868:213:5::2 interface 2001:470:1d:1c6:224:d7ff:fe2c:c914 -> (none)
Nov 12 16:26:05 briemersw ntpd[1235]: peers refreshed
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Auto-activating connection 'System foxtrot (wlan0)'.
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) starting connection 'System foxtrot (wlan0)'
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0/wireless): access point 'System foxtrot (wlan0)' has security, but secrets are required.
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Auto-activating connection 'System foxtrot (wlan0)'.
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) starting connection 'System foxtrot (wlan0)'
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0/wireless): access point 'System foxtrot (wlan0)' has security, but secrets are required.
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0/wireless): connection 'System foxtrot (wlan0)' has security, and secrets exist.  No new secrets needed.
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Config: added 'ssid' value 'foxtrot'
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Config: added 'scan_ssid' value '1'
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Config: added 'psk' value '<omitted>'
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Config: added 'proto' value 'WPA RSN'
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0/wireless): connection 'System foxtrot (wlan0)' has security, and secrets exist.  No new secrets needed.
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Config: added 'ssid' value 'foxtrot'
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Config: added 'scan_ssid' value '1'
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Config: added 'psk' value '<omitted>'
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Config: added 'proto' value 'WPA RSN'
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Config: set interface ap_scan to 1
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> Config: set interface ap_scan to 1
Nov 12 16:26:07 briemersw NetworkManager[1230]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Nov 12 16:26:07 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Nov 12 16:26:09 briemersw systemd[1]: Failed to read PID file /run/sendmail.pid after start. The service might be broken.
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> (wlan0): supplicant interface state: authenticating -> associating
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): supplicant interface state: authenticating -> associating
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> (wlan0): supplicant interface state: associating -> associated
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): supplicant interface state: associating -> associated
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'foxtrot'.
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'foxtrot'.
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> dhclient started with pid 7108
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> dhclient started with pid 7108
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Beginning IP6 addrconf.
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> Activation (wlan0) Beginning IP6 addrconf.
Nov 12 16:26:10 briemersw dnsmasq[1333]: no servers found in /etc/resolv.conf, will retry
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Nov 12 16:26:10 briemersw dhclient[7108]: Internet Systems Consortium DHCP Client 4.2.3
Nov 12 16:26:10 briemersw dhclient[7108]: Copyright 2004-2011 Internet Systems Consortium.
Nov 12 16:26:10 briemersw dhclient[7108]: All rights reserved.
Nov 12 16:26:10 briemersw dhclient[7108]: For info, please visit https://www.isc.org/software/dhcp/
Nov 12 16:26:10 briemersw dhclient[7108]: 
Nov 12 16:26:10 briemersw NetworkManager[1230]: Internet Systems Consortium DHCP Client 4.2.3
Nov 12 16:26:10 briemersw NetworkManager[1230]: Copyright 2004-2011 Internet Systems Consortium.
Nov 12 16:26:10 briemersw NetworkManager[1230]: All rights reserved.
Nov 12 16:26:10 briemersw NetworkManager[1230]: For info, please visit https://www.isc.org/software/dhcp/
Nov 12 16:26:10 briemersw NetworkManager[1230]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
Nov 12 16:26:10 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
Nov 12 16:26:10 briemersw dhclient[7108]: Listening on LPF/wlan0/00:24:d7:2c:c9:14
Nov 12 16:26:10 briemersw dhclient[7108]: Sending on   LPF/wlan0/00:24:d7:2c:c9:14
Nov 12 16:26:10 briemersw NetworkManager[1230]: Listening on LPF/wlan0/00:24:d7:2c:c9:14
Nov 12 16:26:10 briemersw NetworkManager[1230]: Sending on   LPF/wlan0/00:24:d7:2c:c9:14
Nov 12 16:26:10 briemersw dhclient[7108]: Sending on   Socket/fallback
Nov 12 16:26:10 briemersw NetworkManager[1230]: Sending on   Socket/fallback
Nov 12 16:26:10 briemersw dhclient[7108]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 12 16:26:10 briemersw NetworkManager[1230]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 12 16:26:11 briemersw ntpd[1235]: Deleting interface #33 wlan0, fe80::224:d7ff:fe2c:c914#123, interface stats: received=0, sent=1, dropped=0, active_time=1453 secs
Nov 12 16:26:11 briemersw ntpd[1235]: peers refreshed
Nov 12 16:26:13 briemersw ntpd[1235]: Listen normally on 36 wlan0 fe80::224:d7ff:fe2c:c914 UDP 123
Nov 12 16:26:13 briemersw ntpd[1235]: peers refreshed
Nov 12 16:26:14 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) scheduled...
Nov 12 16:26:14 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) started...
Nov 12 16:26:14 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) scheduled...
Nov 12 16:26:14 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) started...
Nov 12 16:26:14 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) complete.
Nov 12 16:26:14 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP6 Configure Get) complete.
Nov 12 16:26:15 briemersw dhclient[7108]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 12 16:26:15 briemersw NetworkManager[1230]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 12 16:26:15 briemersw dhclient[7108]: DHCPACK from 172.31.253.1
Nov 12 16:26:15 briemersw NetworkManager[1230]: DHCPACK from 172.31.253.1
Nov 12 16:26:15 briemersw dhclient[7108]: bound to 172.31.253.112 -- renewal in 41452 seconds.
Nov 12 16:26:15 briemersw NetworkManager[1230]: bound to 172.31.253.112 -- renewal in 41452 seconds.
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info> (wlan0): DHCPv4 state changed preinit -> reboot
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) started...
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): DHCPv4 state changed preinit -> reboot
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info>   address 172.31.253.112
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) started...
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info>   prefix 16 (255.255.0.0)
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info>   address 172.31.253.112
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info>   gateway 172.31.253.1
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info>   prefix 16 (255.255.0.0)
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info>   gateway 172.31.253.1
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info>   hostname 'briemersw'
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info>   hostname 'briemersw'
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info>   nameserver '172.31.253.1'
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info>   domain name 'docbill.info'
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info>   nameserver '172.31.253.1'
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info>   domain name 'docbill.info'
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) complete.
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) complete.
Nov 12 16:26:15 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
Nov 12 16:26:15 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
Nov 12 16:26:16 briemersw NetworkManager[1230]: <warn> could not spawn process '/etc/init.d/nscd condrestart': Failed to execute child process "/etc/init.d/nscd" (No such file or directory)
Nov 12 16:26:16 briemersw NetworkManager[1230]: NetworkManager[1230]: <warn> could not spawn process '/etc/init.d/nscd condrestart': Failed to execute child process "/etc/init.d/nscd" (No such file or directory)
Nov 12 16:26:16 briemersw ntpd[1235]: 0.0.0.0 0658 08 no_sys_peer
Nov 12 16:26:16 briemersw ntpd[1235]: Listen normally on 37 wlan0 172.31.253.112 UDP 123
Nov 12 16:26:16 briemersw ntpd[1235]: Listen normally on 38 wlan0 2001:470:1d:1c6:224:d7ff:fe2c:c914 UDP 123
Nov 12 16:26:16 briemersw ntpd[1235]: 2001:1868:213:5::2 interface fe80::224:d7ff:fe2c:c914 -> 2001:470:1d:1c6:224:d7ff:fe2c:c914
Nov 12 16:26:16 briemersw ntpd[1235]: peers refreshed
Nov 12 16:26:17 briemersw NetworkManager[1230]: <warn> Failed to add route Netlink Error (errno = No route to host)
Nov 12 16:26:17 briemersw NetworkManager[1230]: <error> [1321133177.52738] [nm-system.c:583] nm_system_apply_ip6_config(): (wlan0): failed to set IPv6 route: Netlink Error (errno = No route to host)
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <warn> Failed to add route Netlink Error (errno = No route to host)
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <error> [1321133177.52738] [nm-system.c:583] nm_system_apply_ip6_config(): (wlan0): failed to set IPv6 route: Netlink Error (errno = No route to host)
Nov 12 16:26:17 briemersw NetworkManager[1230]: <warn> could not spawn process '/etc/init.d/nscd condrestart': Failed to execute child process "/etc/init.d/nscd" (No such file or directory)
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <warn> could not spawn process '/etc/init.d/nscd condrestart': Failed to execute child process "/etc/init.d/nscd" (No such file or directory)
Nov 12 16:26:17 briemersw NetworkManager[1230]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Nov 12 16:26:17 briemersw NetworkManager[1230]: <info> Policy set 'System foxtrot (wlan0)' (wlan0) as default for IPv4 routing and DNS.
Nov 12 16:26:17 briemersw dnsmasq[1333]: reading /etc/resolv.conf
Nov 12 16:26:17 briemersw dnsmasq[1333]: using nameserver 2001:470:1d:1c6::1#53
Nov 12 16:26:17 briemersw dnsmasq[1333]: using nameserver 172.31.253.1#53
Nov 12 16:26:17 briemersw dnsmasq[1333]: using nameserver 10.11.255.27#53 for domain lrn.com
Nov 12 16:26:17 briemersw NetworkManager[1230]: <warn> Failed to add route Netlink Error (errno = File exists)
Nov 12 16:26:17 briemersw dnsmasq[1333]: using nameserver 10.11.255.27#53 for domain redhat.com
Nov 12 16:26:17 briemersw dnsmasq[1333]: using nameserver 172.16.52.28#53 for domain lrn.com
Nov 12 16:26:17 briemersw NetworkManager[1230]: <error> [1321133177.139479] [nm-system.c:1039] nm_system_replace_default_ip6_route(): (wlan0): failed to set IPv6 default route: -1
Nov 12 16:26:17 briemersw dnsmasq[1333]: using nameserver 172.16.52.28#53 for domain redhat.com
Nov 12 16:26:17 briemersw dnsmasq[1333]: cleared cache
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Policy set 'System foxtrot (wlan0)' (wlan0) as default for IPv4 routing and DNS.
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <warn> Failed to add route Netlink Error (errno = File exists)
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <error> [1321133177.139479] [nm-system.c:1039] nm_system_replace_default_ip6_route(): (wlan0): failed to set IPv6 default route: -1
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Policy set 'System foxtrot (wlan0)' (wlan0) as default for IPv6 routing and DNS.
Nov 12 16:26:17 briemersw NetworkManager[1230]: <info> Policy set 'System foxtrot (wlan0)' (wlan0) as default for IPv6 routing and DNS.
Nov 12 16:26:17 briemersw NetworkManager[1230]: <info> Activation (wlan0) successful, device activated.
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) successful, device activated.
Nov 12 16:26:17 briemersw NetworkManager[1230]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 12 16:26:17 briemersw NetworkManager[1230]: NetworkManager[1230]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 12 16:26:17 briemersw dbus-daemon[1262]: dbus[1262]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Nov 12 16:26:17 briemersw dbus[1262]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Nov 12 16:26:17 briemersw dbus-daemon[1262]: dbus[1262]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 12 16:26:17 briemersw dbus[1262]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 12 16:26:17 briemersw dbus-daemon[1262]: Mounting other filesystems:  [  OK  ]

Comment 1 Bill C. Riemers 2011-11-12 22:08:55 UTC
There is actually a fairly good chance this is not a problem in Fedora at all.  It just occurred to me a few days before I upgraded to Fedora 16, my router crashed and reset itself to factor settings.   I manually reset the router back to the right configuration, but I just remembered previously I had the router unclocked as I had found at normal speed processes were dieing regularly.  Now I don't remember that ever including wifi drops, but it could well be a system.

I have just underclocked my router again.  If the wifi works normally again, then I'll close this bug.  I'll mark this as need info from myself as a reminder.

Comment 2 Bill C. Riemers 2011-11-12 22:21:26 UTC
No luck.  The disconnect still happening with about the same frequency.

Comment 3 Bill C. Riemers 2011-11-12 22:58:23 UTC
Although not the same problem, this looks very similar to bug 590202.

Comment 4 Bill C. Riemers 2011-11-12 23:51:41 UTC
After reading the comments for bug 590202 I tried turning off IPv6 on the laptop wireless, and sure enough the connection has maintained itself for over an hour.  This is really strange since the IPv6 configuration works...

Comment 5 Bill C. Riemers 2011-11-12 23:55:37 UTC
Strangely enough IPv6 has continued to work on my wifi connection with it turned off.  I even have the correct IPv6 IP address.  It seems much more likely this is a network manager bug than a kernel bug.

Comment 6 Bill C. Riemers 2011-11-13 00:05:55 UTC
If this is truly IPv6 related the following might help.

[briemers@briemersw Games]$ sudo radvdump|sed 's,2001:...:..:..,2001:xxx:xx:xxx,'
#
# radvd configuration generated by radvdump 1.8.2
# based on Router Advertisement from fe80::4a5b:39ff:fe25:fe
# received by interface wlan0
#

interface wlan0
{
	AdvSendAdvert on;
	# Note: {Min,Max}RtrAdvInterval cannot be obtained with radvdump
	AdvManagedFlag off;
	AdvOtherConfigFlag off;
	AdvReachableTime 0;
	AdvRetransTimer 0;
	AdvCurHopLimit 64;
	AdvDefaultLifetime 180;
	AdvHomeAgentFlag off;
	AdvDefaultPreference medium;
	AdvLinkMTU 1480;
	AdvSourceLLAddress on;

	prefix 2001:xxx:xx:xxx::/64
	{
		AdvValidLifetime 86400;
		AdvPreferredLifetime 14400;
		AdvOnLink on;
		AdvAutonomous on;
		AdvRouterAddr off;
	}; # End of prefix definition


	RDNSS 2001:xxx:xx:xxx::1
	{
		AdvRDNSSLifetime 60;
	}; # End of RDNSS definition

}; # End of interface definition

Comment 7 Bill C. Riemers 2011-11-15 19:32:39 UTC
Something I noticed that is really strange, is despite turning off IPv6 for the wireless connection in the configuration dialog, even across reboots IPv6 is still successfully configured.   It seems turning off IPv6 in the network configuration dialog only changes the setting IPV6INIT to no.   But even with that value as no, IPv6 is configured for the device, it just doesn't do what ever step is causing a failure 15-20 minutes later.   Here are the settings in ifcfg-wlan0 that work:

IPV6INIT=no
IPV6_AUTOCONF=yes
IPV6_DEFROUTE=yes
IPV6_FAILURE_FATAL=no

Here are the settings in ifcfg-wlan0 that do not work:

IPV6INIT=yes
IPV6_AUTOCONF=yes
IPV6_DEFROUTE=yes
IPV6_FAILURE_FATAL=no

Comment 8 Bill C. Riemers 2011-11-15 19:56:15 UTC
I suspect what is happening is the IPV6INIT flag is controlling if DHCPv6 is used, not if IPv6 in enabled for the device.  Since I am using router advertisements, there is no need use DHCPv6 so it works.  On the other hand if IPV6INIT is yes, it hangs around and eventually reports a failure because there is no DHCPv6 server.

Basically this looks like a problem of applying flags and settings that were designed for IPV4 to IPV6.

The following seems to map what the "IPV6" Methods drop downs really do:

Ignore -> Configure with Router Advertisements
Automatic -> Configure with Router Advertisements and then reconfigure with DHCPv6.  If DHCPv6 fails recycle the connection after a long timeout.


Here is what is expected:

Ignore -> Configure with private address, or disable IPv6 for the device
Automatic -> Configure with Router Advertisements or DHCPv6.  (Whichever succeeds first.)

Comment 9 Emanuel-Emeric Andrasi 2011-11-18 15:01:58 UTC
Same thing happened to me too but after I've changed the settings according to the 7th comment the the connection working as expected, perfectly.

IPV6INIT=no
IPV6_AUTOCONF=yes
IPV6_DEFROUTE=yes
IPV6_FAILURE_FATAL=no

Actually the only thing I've changed from my initial settings was the IPV6INIT parameter which was set to 'yes'. After it was set to 'no' the connection remains up and running. This report is after 48++ hours and a few reboots after the change.


OS: Fedora 16 x86_64 KDE, kernel 3.1.1
Box: Dell Vostro 1720
WiFi card:
:0e:00.0 Network controller: Intel Corporation WiFi Link 5100
        Subsystem: Intel Corporation WiFi Link 5100 AGN

Internet Connection: PPPoE with IPv6; DHCPv6 with prefix delegation on a Netgear 3500NL with Tomato.

Comment 10 Pavel Šimerda (pavlix) 2012-01-21 20:19:19 UTC
Created attachment 556711 [details]
excerpt from syslog (daemon.debug)

I'm confirming this bug on Fedora 17 with the attached messages from syslog's daemon.debug.

Note this line:

Jan 21 20:48:57 surikata NetworkManager[11993]: NetworkManager[11993]: <info> (em2): device state change: activated -> failed (reason 'ip-config-unavailable') [100 120 5]

The “reason” is somewhat cryptic to me.

Comment 11 Pavel Šimerda (pavlix) 2012-01-21 20:20:42 UTC
I've forgotten to include the version:

NetworkManager-0.9.2-1.fc16.i686

Comment 12 Pavel Šimerda (pavlix) 2012-01-21 21:27:49 UTC
I'm confirming the workaround of setting IPV6INIT=no in /etc/sysconfig/network-scripts/ifcfg-* works. I've been without disconnect and even IP reconfigurations for at least an hour now.

Comment 13 Pavel Šimerda (pavlix) 2012-03-09 21:10:57 UTC
I'm adjusting the summary of this bug to reflect its relation to IPv6 and IPV6INIT.

Comment 14 Pavel Šimerda (pavlix) 2012-03-09 21:17:24 UTC
Let me please correct Bill:

“Ignore -> Configure with private address, or disable IPv6 for the device
Automatic -> Configure with Router Advertisements or DHCPv6.  (Whichever
succeeds first.)”

It is not whichever succeeds first. Router Advertisements should always be used to configure IPv6 information. AdvManaged and AdvOtherConfig are RA flags that
instruct hosts to use DHCPv6 to configure addressing and/or other configuration.

As DHCPv6 can't be used to configure the default gateway (unless I missed something), it is not suitable for complete network configuration.

That said, on a network with AdvManaged off and AdvOtherConfig off, the DHCPv6 client should not be run at all, and therefore it should not be able to fail.

Comment 15 satellitgo 2012-03-09 21:22:08 UTC
Related?
https://bugzilla.redhat.com/show_bug.cgi?id=801052#c12

Comment 16 Bill C. Riemers 2012-03-12 12:21:35 UTC
(In reply to comment #15)
> Related?
> https://bugzilla.redhat.com/show_bug.cgi?id=801052#c12

Probably not.  The frequency of the drops is much higher in that bug, and not from the same cause.

Comment 17 Pavel Šimerda (pavlix) 2012-03-17 02:26:51 UTC
This bug is also present in Fedora 17 including some stuff from updates-testing.

Versions:

kernel-3.3.0-0.rc7.git0.3.fc17.x86_64
NetworkManager-0.9.3.995-0.6.git20120314.fc17.x86_64
wpa_supplicant-1.0-0.2.fc17.x86_64
dhclient-4.2.3-18.P2.fc17.x86_64

Output:

Mar 17 03:05:18 dragon NetworkManager[2555]: <warn> Activation (wlan0) failed.
Mar 17 03:05:18 dragon NetworkManager[2555]: <debug> [1331949918.650768] [nm-device.c:4422] nm_device_queue_state(): (wlan0): queued state change to disconnected (id 618)
Mar 17 03:05:18 dragon dbus[738]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Mar 17 03:05:18 dragon NetworkManager[2555]: <debug> [1331949918.663988] [nm-device.c:4390] queued_set_state(): (wlan0): running queued state change to disconnected (id 618)
Mar 17 03:05:18 dragon NetworkManager[2555]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Mar 17 03:05:18 dragon NetworkManager[2555]: <info> (wlan0): deactivating device (reason 'none') [0]
Mar 17 03:05:18 dragon dbus-daemon[738]: dbus[738]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Mar 17 03:05:18 dragon dbus-daemon[738]: dbus[738]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Mar 17 03:05:18 dragon dbus[738]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
--
Mar 17 03:15:33 dragon NetworkManager[2555]: <debug> [1331950533.579819] [nm-device-wifi.c:542] get_active_ap():     AP: 'Ivanka'  00:4f:62:05:d2:b9
Mar 17 03:15:33 dragon NetworkManager[2555]: <debug> [1331950533.579913] [nm-device-wifi.c:550] get_active_ap():       BSSID mismatch
Mar 17 03:15:33 dragon NetworkManager[2555]: <debug> [1331950533.580011] [nm-device-wifi.c:542] get_active_ap():     AP: 'TP-LINK_E73380'  b0:48:7a:e7:33:80
Mar 17 03:15:33 dragon NetworkManager[2555]: <debug> [1331950533.580143] [nm-device-wifi.c:550] get_active_ap():       BSSID mismatch
Mar 17 03:15:33 dragon NetworkManager[2555]: <debug> [1331950533.585399] [nm-device-wifi.c:542] get_active_ap():     AP: '09be447'  00:21:63:e2:06:74
Mar 17 03:15:33 dragon NetworkManager[2555]: <debug> [1331950533.588281] [nm-device-wifi.c:550] get_active_ap():       BSSID mismatch
Mar 17 03:15:33 dragon NetworkManager[2555]: <debug> [1331950533.591264] [nm-device-wifi.c:542] get_active_ap():     AP: 'wifi.pavlix.net/krymska/3'  f4:ec:38:a5:4f:84
Mar 17 03:15:33 dragon NetworkManager[2555]: <debug> [1331950533.594682] [nm-device-wifi.c:582] get_active_ap():       matched
Mar 17 03:15:37 dragon NetworkManager[2555]: <debug> [1331950537.575186] [nm-ip6-manager.c:277] rdnss_expired(): (wlan0): IPv6 RDNSS information expired
Mar 17 03:15:37 dragon NetworkManager[2555]: <debug> [1331950537.575365] [nm-ip6-manager.c:312] set_rdnss_timeout(): (wlan0): removing expired RA-provided nameserver fe80::20c:42ff:fe13:857b
Mar 17 03:15:37 dragon NetworkManager[2555]: <info> (wlan0): device state change: activated -> failed (reason 'ip-config-unavailable') [100 120 5]
Mar 17 03:15:37 dragon NetworkManager[2555]: <warn> Activation (wlan0) failed for access point (wifi.pavlix.net/krymska/3)
Mar 17 03:15:37 dragon NetworkManager[2555]: <warn> Activation (wlan0) failed.

Comment 18 Pavel Šimerda (pavlix) 2012-03-17 02:35:09 UTC
Now that I look at it again, it seems the connection could be dropped as a reaction to IPv6 RDNSS information expiry:

Mar 17 03:15:37 dragon NetworkManager[2555]: <debug> [1331950537.575186]
[nm-ip6-manager.c:277] rdnss_expired(): (wlan0): IPv6 RDNSS information expired
Mar 17 03:15:37 dragon NetworkManager[2555]: <debug> [1331950537.575365]
[nm-ip6-manager.c:312] set_rdnss_timeout(): (wlan0): removing expired
RA-provided nameserver fe80::20c:42ff:fe13:857b
Mar 17 03:15:37 dragon NetworkManager[2555]: <info> (wlan0): device state
change: activated -> failed (reason 'ip-config-unavailable') [100 120 5]

Comment 19 Pavel Šimerda (pavlix) 2012-03-17 03:28:21 UTC
In my case, the problem is definitely caused by the server configuration.

radvd (1.6, on OpenWRT) by default sets AdvRDNSSLifetime to the value of
MaxRtrAdvInterval. This is a bug and a race condition, as RDNSS can expire before it is renewed.

Setting AdvRDNSSLifetime explicitely to 2*MaxRtrAdvInterval should fix the problem.

It would be a good idea to make NetworkManager proactively send Router Solicitation when it's getting near when the timeout is coming. This would make the router send Router Advertisement and thus refresh the RDNSS before the timeout comes.

Comment 20 Pavel Šimerda (pavlix) 2012-03-17 03:43:07 UTC
Bill, can you please provide the radvd.conf or at least the value of MaxRtrAdvInterval?

Comment 21 Bill C. Riemers 2012-03-19 14:23:33 UTC
(In reply to comment #20)
> Bill, can you please provide the radvd.conf or at least the value of
> MaxRtrAdvInterval?

See comment 6.

Comment 22 Bill C. Riemers 2012-03-19 14:29:46 UTC
Oh.  It looks like MaxRtrAdvInterval is not available by radvddump.  I logged into my router and this is what I found as /etc/radvd.conf:

$ sed 's,2001:...:..:...::,2001:xxx:xx:xxx::,' < /etc/radvd.conf
interface br0
{
 IgnoreIfMissing on;
 AdvSendAdvert on;
 MaxRtrAdvInterval 60;
 AdvHomeAgentFlag off;
 AdvManagedFlag off;
 AdvLinkMTU 1480;
 prefix 2001:xxx:xx:xxx::/64 
 {
  AdvOnLink on;
  AdvAutonomous on;
 };
 RDNSS 2001:xxx:xx:xxx::1 { };
};

Comment 23 Pavel Šimerda (pavlix) 2012-03-19 22:10:56 UTC
„It looks like MaxRtrAdvInterval is not available by radvddump.“

It's because it's not included in RA packets. Thank you very much,
this means you have MaxRtrAdvInterval equal to AdvRDNSSLifetime and the latter is unspecified.

radvd on your router defaults AdvRDNSSLifetime to MaxRtrAdvInterval instead of 2*MaxRtrAdvInterval. This is a bug in radvd in your router. As a workaround,
you can set AdvRDNSSLifetime manually. I had exactly the same problem (see above).

NetworkManager definitely *should* handle it more gracefully, e.g. by sending Router Solicitation in advance, so that the router sends the information sooner.

Comment 24 Pavel Šimerda (pavlix) 2012-03-20 02:18:05 UTC
I have new information from my testing environment:

The router sends RA very often (MaxRtrAdvInterval = 20). But the laptop
doesn't recieve all af toe RA's.

Router:

02:08:24.743294 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:08:34.797071 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:08:49.119685 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:09:02.470117 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:09:13.628787 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:09:25.657116 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:09:40.277749 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:09:59.972750 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:10:14.359851 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:10:26.035442 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:10:42.185823 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:10:53.216682 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:11:10.938389 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
02:11:22.856247 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80


Host:

03:08:24.827817 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
03:08:49.199251 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
03:09:13.673073 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
03:09:25.758868 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
03:09:40.302810 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
03:10:14.402542 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
03:10:26.075967 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
03:10:53.309190 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80
03:11:22.908488 IP6 fe80::20c:42ff:fe13:857b > ff02::1: ICMP6, router advertisement, length 80

Please ignore the timezone difference.

This testing was performed by tcpdump on OpenWRT router and Fedora 17 host. Even though the local wireless connection looks pretty stable, you can see that the router is sending many more RAs than the host is recieving.

This means setting AdvRDNSSLifetime to a higer value on the router side was a good workaround.

Finally, this info suggests problems in the wifi connection and not exactly in NetworkManager or radvd.

Wireless ping test:

--- fe80::20c:42ff:fe13:857b ping statistics ---
66 packets transmitted, 64 received, 3% packet loss, time 65068ms
rtt min/avg/max/mdev = 2.429/28.293/1092.005/138.295 ms, pipe 2

Comment 25 Pavel Šimerda (pavlix) 2012-03-20 20:28:25 UTC
Possible NetworkManager debugging configuration:

$ cat /etc/NetworkManager/NetworkManager.conf 
[main]
plugins=ifcfg-rh
[logging]
level=DEBUG
domains=IP4,IP6,DHCP4,DHCP6,WIFI,HW,BT,SUPPLICANT,SUSPEND,CORE,DEVICE

$ cat /etc/rsyslog.conf | grep debug
*.*						/tmp/debug

The best way to test this bug's behavior is to grep 'RDNSS' from the debug.

Comment 26 Pavel Šimerda (pavlix) 2012-03-29 19:39:38 UTC
Regression in NetworkManager-0.9.4.0-1.git20120328.fc17.x86_64 (related bug 808203).

Comment 27 Ricky Burgin 2012-04-13 18:33:00 UTC
Created attachment 915441 [details]
Comment

(This comment was longer than 65,535 characters and has been moved to an attachment by Red Hat Bugzilla).

Comment 28 Ricky Burgin 2012-04-13 18:37:11 UTC
Hmm, that log was slightly larger than I had intended. Sorry about that.

Comment 29 Pavel Šimerda (pavlix) 2012-04-13 20:55:35 UTC
Hi Ricky,

your network seems to reconfigure too often. You are probably not experiencing this particular bug.

Pavel

Comment 30 Ricky Burgin 2012-04-13 20:58:16 UTC
Perhaps not, but disabling v6 appears to have fixed it. Peculiar.

Comment 31 Pavel Šimerda (pavlix) 2012-04-14 08:18:28 UTC
Ricky, please try to get a more thorough log, as I described in comment 25:

https://bugzilla.redhat.com/show_bug.cgi?id=753482#c25

And file a new bug report and link it here.

Comment 32 Dan Winship 2012-04-19 14:38:47 UTC

*** This bug has been marked as a duplicate of bug 785772 ***

Comment 33 Pavel Šimerda (pavlix) 2012-04-19 20:38:36 UTC
I believe this bugreport was closed duplicate by mistake. I don't see any relation between this bug and bug 785772.

Comment 34 Dan Winship 2012-04-19 21:14:21 UTC
as explained in the other bug, the issue is that NM's behavior is causing the kernel to drop all RAs after the first one, resulting in the RDNSS timeout eventually triggering.

*** This bug has been marked as a duplicate of bug 785772 ***

Comment 35 Pavel Šimerda (pavlix) 2012-04-19 21:20:45 UTC
I'm leaving reopening this bugreport on you now. But I believe this bug is not duplicate to the two others for the following reasons:

1) It has existed before them

2) It is *not* caused by RA not being accepted by NM

3) It is reproduced differently

4) It gives different errors

Comment 36 Pavel Šimerda (pavlix) 2012-04-19 21:24:07 UTC
One more thing, this bug is probably related to a problem present in RFC 6106 itself that I am trying to report to the IETF guys.

Comment 37 Dan Winship 2012-04-19 21:27:23 UTC
Hm... indeed. I was misreading the "nm_system_replace_default_ip6_route(): (wlan0): failed to set IPv6 default route" message in these logs as being the kernel message from the other bug

Comment 38 Pavel Šimerda (pavlix) 2012-04-19 21:37:18 UTC
Thank you, Dan. I'm adding text of my e-mail to ipv6 (I hope this was the right place). I hope it helps.

--

Hello,

I'm starting my work on linux NetworkManager. I've been following
several bugreports during the recent months that all lead to problems
with maintaining the list of recursive nameservers.

I've already spent quite some time analyzing RDNSS problems and I came
to a conclusion that the problem actually lives in the RFC itself.

Please look at section 5.1. in RFC 6106. It states:

MaxRtrAdvInterval <= Lifetime <= 2*MaxRtrAdvInterval

Considering MaxRtrAdvInterval the maximum time between RAs, setting
Lifetime to MaxRtrAdvInterval IMO constitutes a race condition.
Moreover, any Lifetime in this interval can timeout with just one or two
lost RAs.

This makes RA-based IPv6-only networks drop RDNSS regularly. In many
implementations IPv6 and IPv4 are bound together so that if one of them
fails, the whole link is restarted. This is also the case in
NetworkManager.

In the current situation, it's not advisable to use RFC 6106 in
production because it can cause problems even to IPv4 applications.

In the real world, radvd uses Lifetime=MaxRtrAdvInterval by default and
NetworkManager internally adds 10s to the lifetime, that only helps to
avoid the race condition but not lost packets that are common on
wireless networks.

I appreciate any help to get this right both in the standards and in the
software.

Cheers,

Pavel Šimerda

Comment 39 Pavel Šimerda (pavlix) 2012-04-19 23:27:03 UTC
I confirmed this problem with NetworkManager-0.9.4-5.git20120403.fc17.x86_64 (from koji, you won't update to it because of version 0.9.4.0).

MinRtrAdvInterval = 10
MaxRtrAdvInterval = 20
AdvRDNSSLifetime = 20 (equals to MaxRtrAdvInterval by default in radvd and in accord with RFC 6106)

Comment 40 Dan Winship 2012-04-24 20:31:31 UTC
OK, so...

1. If AdvRDNSSLifetime is about to expire, and we haven't gotten another RA, we should send out a solicitation. But there's no way to trick the kernel into doing that for us, so we'd have to build and send it by hand... (Perhaps there needs to be some kernel API for this though.)

2. If AdvRDNSSLifetime is less than AdvDefaultLifetime (the lifetime of the default route), we could decide to just ignore AdvRDNSSLifetime, and use AdvDefaultLifetime for the RDNSS lifetime too. That seems vaguely plausible; both pieces of information are coming from the same router, so if we haven't received any new RAs from it, it seems reasonable to assume that they're both still good. The kernel does expose AdvDefaultLifetime as part of the netlink information on the default route, but, alas, libnl doesn't expose it to us, so we have no easy way to do this either...

3. So... we could just ignore AdvRDNSSLifetime, and say that we only drop that information if we receive a new RA that doesn't refresh it, or if the kernel drops the corresponding route?

Comment 41 Pavel Šimerda (pavlix) 2012-04-25 08:54:30 UTC
1. Yes. We should (according to common sense) and MAY (according to RFC 6106).

We should try to fix all three things:

a) The RFC
b) radvd
c) NetworkManager

2. We could cheat a little bit, yes. We are already cheating about the 10 seconds. But...

If there's not a *real* reason not to, I would like to keep the behavior as close to RFC as possible. Actually, when we fix these issues and start sending RS, I would like to try to remove the +10s trick. What about sending RS at expiry-10s?

3. We could. But this is clearly against the RFC. So if we do that, I think we should clearly document and communicate the reason.

We have a unique change to document SLAAC including RDNSS in the real world.

Comment 42 Dan Winship 2012-05-02 15:30:21 UTC
Test packages at http://koji.fedoraproject.org/koji/taskinfo?taskID=4045080 implement #1 (5 seconds before expiring the data, it will send out an RS to try to refresh it). Try it out...

Comment 43 Dan Winship 2012-05-09 12:42:35 UTC
Pavel, can you try that koji build and see if it fixes things?

Comment 44 Pavel Šimerda (pavlix) 2012-05-09 16:27:03 UTC
Ah, sorry, I cannot try it here in Brno, as I don't have access to radvd configuration. I'll let you know when I'm at my home lab with better equipment ;).

Comment 45 Pavel Šimerda (pavlix) 2012-05-18 08:22:38 UTC
Still no opportunity to test.

Comment 46 Mathieu Chouquet-Stringer 2012-05-18 11:05:27 UTC
I've been experiencing the same issue but looking at the koji web page, I fail to see where to find the test packages...

Comment 47 Dan Winship 2012-05-18 13:16:39 UTC
(In reply to comment #46)
> I've been experiencing the same issue but looking at the koji web page, I fail
> to see where to find the test packages...

Ah, yeah, test builds get garbage-collected after a while, so those packages are no longer there. New build at http://koji.fedoraproject.org/koji/taskinfo?taskID=4086354. (follow the x86_64 or i686 link, then download the relevant rpm links at the bottom)

Comment 48 Mathieu Chouquet-Stringer 2012-05-26 19:18:00 UTC
I guess we're on the right track.  I reverted the changes I had so I have IPV6INIT=yes and I was able to reproduce this bug without updating NetworkManager.

So now, I just updated it with the packages from koji and well it failed because of SELinux:
May 26 21:14:01 somehost setroubleshoot: SELinux is preventing /usr/sbin/NetworkManager from create access on the rawip_socket . For complete SELinux messages. run sealert -l d555fc9e-b54a-4404-9567-908c1482e9a3
May 26 21:14:06 somehost NetworkManager[10219]: <info> (wlan0): device state change: activated -> failed (reason 'ip-config-unavailable') [100 120 5]

So the good news is NetworkManager did try to create the sollicitation packet, the bad news is it got smacked by SELinux.

I'm going permissive to see if it fails again.

Comment 49 Mathieu Chouquet-Stringer 2012-05-26 20:48:43 UTC
It still fails, even in permissive mode:

May 26 22:36:27 somehost setroubleshoot: SELinux is preventing /usr/sbin/NetworkManager from create access on the rawip_socket . For complete SELinux messages. run sealert -l d555fc9e-b54a-4404-9567-908c1482e9a3
May 26 22:36:27 somehost setroubleshoot: SELinux is preventing /usr/sbin/NetworkManager from setopt access on the rawip_socket . For complete SELinux messages. run sealert -l a8834f78-b069-4ad8-a197-a04349a2486d
May 26 22:36:32 somehost NetworkManager[10219]: <info> (wlan0): device state change: activated -> failed (reason 'ip-config-unavailable') [100 120 5]

Comment 50 Pavel Šimerda (pavlix) 2012-05-30 15:15:07 UTC
After talking with Dan Winship, I'm coming up with an alternative solution:

http://git.pavlix.net/gitweb/?p=NetworkManager.git;a=commitdiff;h=62f135d519fadd883cf72e0cd67f35269bae1d57;hp=9bf3c01e27f865cb93ed5115ed9c2ac260b53ecc

This is much easier for the beginning and whe can revisit the lifetime problem after IETF takes action.

Comment 51 Fedora End Of Life 2013-01-16 22:34:28 UTC
This message is a reminder that Fedora 16 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 16. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '16'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 16's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 16 is end of life. If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora, you are encouraged to click on 
"Clone This Bug" and open it against that version of Fedora.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping