Network Manager 1.0.X Wi-Fi Autoconnect Issues

From: Matthew Starr <mstarr hedonline com>
To: "networkmanager-list gnome org" <networkmanager-list gnome org>
Subject: Network Manager 1.0.X Wi-Fi Autoconnect Issues
Date: Thu, 18 May 2017 15:54:22 +0000
I have tried using NetworkManager 1.0.0 and 1.0.12 on an embedded device built with buildroot that has 
Ethernet (eth0), Wi-Fi client (mlan0), Wi-Fi Access Point (uap0), and Cellular interfaces (ttyACM0 and ppp0). 
 The Wi-Fi AP (uap0) interface is ignored by Network Manager based on my NetworkManager.conf file. I am able 
to boot the device and Network Manager will automatically configure and connect with Ethernet, Wi-Fi Client, 
and Cellular interfaces every time.

If I move out of range of the Wi-Fi access point the device will disconnect and if I move back into range in 
under an hour, NetworkManager will reestablish the connection.  If I wait multiple hours before moving back 
into range of the Wi-Fi access point, Network Manager will not reestablish a connection automatically with 
the access point (I waited hours with the AP within range and visible in Wi-Fi scan results).  When Network 
Manager is not automatically reestablishing a connection to the access point I can use nmcli to bring up the 
profile associated with the access point and it connects immediately.

Why is Network Manager not able to auto connect to a Wi-Fi AP after a longer period of time of not seeing the 
AP?  Is there a timeout within Network Manager?  Is this a bug?

Below is the debug log output when Network Manager 1.0.12 is not auto reconnecting. The Wi-Fi client (mlan0) 
is scanning for access points every 60 seconds, but the autoactivate attempt only happens every 5 minutes but 
then appears to immediately remove the pending action of autoactivate on the mlan0 interface.  At the same 
time the cellular connection is attempting to connect and can't connect because of bad signal strength.

May 18 14:33:31 canect2 daemon.info NetworkManager[245]: <debug> [1495118011.701118] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x213c268] (mlan0): add_pending_action (1): 'scan'
May 18 14:33:31 canect2 daemon.info NetworkManager[245]: <debug> [1495118011.702526] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x213c268] (mlan0): remove_pending_action (0): 
'scan'
May 18 14:33:31 canect2 user.alert kernel: [149885.509332] wlan: mlan0 START SCAN
May 18 14:33:33 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (idle -> searching)
May 18 14:33:33 canect2 daemon.info NetworkManager[245]: <debug> [1495118013.317075] 
[platform/nm-linux-platform.c:1950] event_notification(): netlink event (type 16) for link: mlan0 (6, family 
0)
May 18 14:33:33 canect2 daemon.info NetworkManager[245]: <debug> [1495118013.317486] 
[platform/nm-linux-platform.c:426] get_kernel_object(): get_kernel_object for link: mlan0 (6, family 0)
May 18 14:33:33 canect2 daemon.info NetworkManager[245]: <debug> [1495118013.318059] 
[platform/nm-linux-platform.c:1950] event_notification(): netlink event (type 16) for link: mlan0 (6, family 
0)
May 18 14:33:33 canect2 daemon.info NetworkManager[245]: <debug> [1495118013.318402] 
[platform/nm-linux-platform.c:426] get_kernel_object(): get_kernel_object for link: mlan0 (6, family 0)
May 18 14:33:33 canect2 user.warn kernel: [149887.121037] wlan: SCAN COMPLETED: scanned AP count=12
May 18 14:33:33 canect2 user.err kernel: [149887.134455] Invalid sched_scan req parameter
May 18 14:33:47 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (searching -> idle)
May 18 14:33:52 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (idle -> searching)
May 18 14:33:52 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (searching -> idle)
May 18 14:33:57 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (idle -> searching)
May 18 14:33:57 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (searching -> idle)
May 18 14:34:02 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (idle -> searching)
May 18 14:34:03 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (searching -> idle)
May 18 14:34:08 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (idle -> searching)
May 18 14:34:08 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (searching -> idle)
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118052.692978] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x213c268] (mlan0): add_pending_action (1): 
'autoactivate'
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118052.693286] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (1): 
'autoactivate'
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118052.694239] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x213c268] (mlan0): remove_pending_action (0): 
'autoactivate'
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <info>  Auto-activating connection 'Aeris'.
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118052.695397] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (2): 
'activation::0x214ead8'
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118052.696054] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'autoactivate'
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: starting connection 
'Aeris'
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) scheduled...
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) started...
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: disconnected 
-> prepare (reason 'none') [30 40 0]
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <info>  NetworkManager state is now CONNECTING
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118052.703566] 
[nm-active-connection.c:480] check_master_ready(): (0x214ead8): not signalling master-ready (no master)
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118052.704510] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x213c268] (mlan0): add_pending_action (1): 
'autoactivate'
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118052.705149] [nm-manager.c:4328] 
policy_activating_device_changed(): ActivatingConnection now Aeris
May 18 14:34:12 canect2 daemon.info ModemManager[423]: <info>  Simple connect started...
May 18 14:34:12 canect2 daemon.info ModemManager[423]: <info>  Simple connect state (4/8): Wait to get fully 
enabled
May 18 14:34:12 canect2 daemon.info ModemManager[423]: <info>  Simple connect state (5/8): Register
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) complete.
May 18 14:34:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118052.719481] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x213c268] (mlan0): remove_pending_action (0): 
'autoactivate'
May 18 14:34:26 canect2 daemon.warn NetworkManager[245]: <warn>  (ttyACM0) failed to connect modem: Network 
timeout
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: prepare -> 
failed (reason 'gsm-registration-timeout') [40 120 32]
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  NetworkManager state is now DISCONNECTED
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.815371] 
[nm-active-connection.c:476] check_master_ready(): (0x214ead8): not signalling master-ready (not activating)
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.815498] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(0): 'activation::0x214ead8'
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.821710] [nm-policy.c:1125] 
device_state_changed(): Connection 'Aeris' failed to autoconnect; 4 tries left
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.823492] [nm-manager.c:4328] 
policy_activating_device_changed(): ActivatingConnection now (none)
May 18 14:34:26 canect2 daemon.warn NetworkManager[245]: <warn>  (ttyACM0): Activation: failed for connection 
'Aeris'
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.824589] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (1): 
'queued state change to disconnected'
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.824887] 
[devices/nm-device.c:7768] nm_device_queue_state(): [0x21602f0] (ttyACM0): queued state change to 
disconnected due to none (id 100254)
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.830540] 
[devices/nm-device.c:7717] queued_set_state(): [0x21602f0] (ttyACM0): running queued state change to 
disconnected (id 100254)
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: failed -> 
disconnected (reason 'none') [120 30 0]
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): deactivating device (reason 
'none') [0]
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.831611] 
[nm-firewall-manager.c:256] nm_firewall_manager_remove_from_zone(): (ttyACM0) firewall zone remove skipped 
(not running)
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.831838] 
[devices/nm-device.c:7066] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'dhcp6' not pending (expected)
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.832001] 
[devices/nm-device.c:7066] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'autoconf6' not pending (expected)
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.832268] 
[platform/nm-linux-platform.c:2085] sysctl_set(): sysctl: failed to open 
'/proc/sys/net/ipv6/conf/ttyACM0/accept_ra': (2) No such file or directory
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.833005] 
[platform/nm-linux-platform.c:2085] sysctl_set(): sysctl: failed to open 
'/proc/sys/net/ipv6/conf/ttyACM0/use_tempaddr': (2) No such file or directory
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.834941] 
[dns-manager/nm-dns-manager.c:1005] nm_dns_manager_begin_updates(): (update_routing_and_dns): queueing DNS 
updates (1)
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.835743] 
[dns-manager/nm-dns-manager.c:1023] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS 
configuration did not change
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.835996] 
[dns-manager/nm-dns-manager.c:1027] nm_dns_manager_end_updates(): (update_routing_and_dns): no DNS changes to 
commit (0)
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.836210] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (2): 
'autoactivate'
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.836591] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'queued state change to disconnected'
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  Auto-activating connection 'Aeris'.
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.841524] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (2): 
'activation::0x214ea68'
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.842155] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'autoactivate'
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: starting connection 
'Aeris'
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) scheduled...
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) started...
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: disconnected 
-> prepare (reason 'none') [30 40 0]
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  NetworkManager state is now CONNECTING
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.849794] 
[nm-active-connection.c:480] check_master_ready(): (0x214ea68): not signalling master-ready (no master)
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.850420] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x213c268] (mlan0): add_pending_action (1): 
'autoactivate'
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.851354] [nm-manager.c:4328] 
policy_activating_device_changed(): ActivatingConnection now Aeris
May 18 14:34:26 canect2 daemon.info ModemManager[423]: <info>  Simple connect started...
May 18 14:34:26 canect2 daemon.info ModemManager[423]: <info>  Simple connect state (4/8): Wait to get fully 
enabled
May 18 14:34:26 canect2 daemon.info ModemManager[423]: <info>  Simple connect state (5/8): Register
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) complete.
May 18 14:34:26 canect2 daemon.info NetworkManager[245]: <debug> [1495118066.865174] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x213c268] (mlan0): remove_pending_action (0): 
'autoactivate'
May 18 14:34:34 canect2 daemon.info NetworkManager[245]: <debug> [1495118074.699024] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x213c268] (mlan0): add_pending_action (1): 'scan'
May 18 14:34:34 canect2 daemon.info NetworkManager[245]: <debug> [1495118074.706568] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x213c268] (mlan0): remove_pending_action (0): 
'scan'
May 18 14:34:34 canect2 user.alert kernel: [149948.513688] wlan: mlan0 START SCAN
May 18 14:34:36 canect2 daemon.info NetworkManager[245]: <debug> [1495118076.319880] 
[platform/nm-linux-platform.c:1950] event_notification(): netlink event (type 16) for link: mlan0 (6, family 
0)
May 18 14:34:36 canect2 daemon.info NetworkManager[245]: <debug> [1495118076.320455] 
[platform/nm-linux-platform.c:426] get_kernel_object(): get_kernel_object for link: mlan0 (6, family 0)
May 18 14:34:36 canect2 user.warn kernel: [149950.125867] wlan: SCAN COMPLETED: scanned AP count=13
May 18 14:34:36 canect2 daemon.info NetworkManager[245]: <debug> [1495118076.323873] 
[platform/nm-linux-platform.c:1950] event_notification(): netlink event (type 16) for link: mlan0 (6, family 
0)
May 18 14:34:36 canect2 daemon.info NetworkManager[245]: <debug> [1495118076.324530] 
[platform/nm-linux-platform.c:426] get_kernel_object(): get_kernel_object for link: mlan0 (6, family 0)
May 18 14:34:36 canect2 user.err kernel: [149950.149321] Invalid sched_scan req parameter
May 18 14:34:42 canect2 daemon.warn NetworkManager[245]: <warn>  (ttyACM0) failed to connect modem: Network 
timeout
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: prepare -> 
failed (reason 'gsm-registration-timeout') [40 120 32]
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  NetworkManager state is now DISCONNECTED
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.304548] 
[nm-active-connection.c:476] check_master_ready(): (0x214ea68): not signalling master-ready (not activating)
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.306184] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(0): 'activation::0x214ea68'
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.311499] [nm-policy.c:1125] 
device_state_changed(): Connection 'Aeris' failed to autoconnect; 3 tries left
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.313228] [nm-manager.c:4328] 
policy_activating_device_changed(): ActivatingConnection now (none)
May 18 14:34:42 canect2 daemon.warn NetworkManager[245]: <warn>  (ttyACM0): Activation: failed for connection 
'Aeris'
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.314330] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (1): 
'queued state change to disconnected'
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.314601] 
[devices/nm-device.c:7768] nm_device_queue_state(): [0x21602f0] (ttyACM0): queued state change to 
disconnected due to none (id 100296)
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.320755] 
[devices/nm-device.c:7717] queued_set_state(): [0x21602f0] (ttyACM0): running queued state change to 
disconnected (id 100296)
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: failed -> 
disconnected (reason 'none') [120 30 0]
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): deactivating device (reason 
'none') [0]
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.321522] 
[nm-firewall-manager.c:256] nm_firewall_manager_remove_from_zone(): (ttyACM0) firewall zone remove skipped 
(not running)
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.321699] 
[devices/nm-device.c:7066] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'dhcp6' not pending (expected)
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.322312] 
[devices/nm-device.c:7066] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'autoconf6' not pending (expected)
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.322615] 
[platform/nm-linux-platform.c:2085] sysctl_set(): sysctl: failed to open 
'/proc/sys/net/ipv6/conf/ttyACM0/accept_ra': (2) No such file or directory
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.322898] 
[platform/nm-linux-platform.c:2085] sysctl_set(): sysctl: failed to open 
'/proc/sys/net/ipv6/conf/ttyACM0/use_tempaddr': (2) No such file or directory
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.325179] 
[dns-manager/nm-dns-manager.c:1005] nm_dns_manager_begin_updates(): (update_routing_and_dns): queueing DNS 
updates (1)
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.325639] 
[dns-manager/nm-dns-manager.c:1023] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS 
configuration did not change
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.325856] 
[dns-manager/nm-dns-manager.c:1027] nm_dns_manager_end_updates(): (update_routing_and_dns): no DNS changes to 
commit (0)
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.326468] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (2): 
'autoactivate'
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.326925] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'queued state change to disconnected'
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  Auto-activating connection 'Aeris'.
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.331420] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (2): 
'activation::0x214ecb0'
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.332443] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'autoactivate'
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: starting connection 
'Aeris'
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) scheduled...
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) started...
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: disconnected 
-> prepare (reason 'none') [30 40 0]
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  NetworkManager state is now CONNECTING
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.339800] 
[nm-active-connection.c:480] check_master_ready(): (0x214ecb0): not signalling master-ready (no master)
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.340892] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x213c268] (mlan0): add_pending_action (1): 
'autoactivate'
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.341418] [nm-manager.c:4328] 
policy_activating_device_changed(): ActivatingConnection now Aeris
May 18 14:34:42 canect2 daemon.info ModemManager[423]: <info>  Simple connect started...
May 18 14:34:42 canect2 daemon.info ModemManager[423]: <info>  Simple connect state (4/8): Wait to get fully 
enabled
May 18 14:34:42 canect2 daemon.info ModemManager[423]: <info>  Simple connect state (5/8): Register
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) complete.
May 18 14:34:42 canect2 daemon.info NetworkManager[245]: <debug> [1495118082.355410] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x213c268] (mlan0): remove_pending_action (0): 
'autoactivate'
May 18 14:34:57 canect2 daemon.warn NetworkManager[245]: <warn>  (ttyACM0) failed to connect modem: Network 
timeout
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: prepare -> 
failed (reason 'gsm-registration-timeout') [40 120 32]
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  NetworkManager state is now DISCONNECTED
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.743190] 
[nm-active-connection.c:476] check_master_ready(): (0x214ecb0): not signalling master-ready (not activating)
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.743312] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(0): 'activation::0x214ecb0'
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.750386] [nm-policy.c:1125] 
device_state_changed(): Connection 'Aeris' failed to autoconnect; 2 tries left
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.752532] [nm-manager.c:4328] 
policy_activating_device_changed(): ActivatingConnection now (none)
May 18 14:34:57 canect2 daemon.warn NetworkManager[245]: <warn>  (ttyACM0): Activation: failed for connection 
'Aeris'
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.753897] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (1): 
'queued state change to disconnected'
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.754295] 
[devices/nm-device.c:7768] nm_device_queue_state(): [0x21602f0] (ttyACM0): queued state change to 
disconnected due to none (id 100317)
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.761287] 
[devices/nm-device.c:7717] queued_set_state(): [0x21602f0] (ttyACM0): running queued state change to 
disconnected (id 100317)
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: failed -> 
disconnected (reason 'none') [120 30 0]
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): deactivating device (reason 
'none') [0]
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.762605] 
[nm-firewall-manager.c:256] nm_firewall_manager_remove_from_zone(): (ttyACM0) firewall zone remove skipped 
(not running)
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.762945] 
[devices/nm-device.c:7066] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'dhcp6' not pending (expected)
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.763152] 
[devices/nm-device.c:7066] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'autoconf6' not pending (expected)
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.763869] 
[platform/nm-linux-platform.c:2085] sysctl_set(): sysctl: failed to open 
'/proc/sys/net/ipv6/conf/ttyACM0/accept_ra': (2) No such file or directory
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.764264] 
[platform/nm-linux-platform.c:2085] sysctl_set(): sysctl: failed to open 
'/proc/sys/net/ipv6/conf/ttyACM0/use_tempaddr': (2) No such file or directory
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.766860] 
[dns-manager/nm-dns-manager.c:1005] nm_dns_manager_begin_updates(): (update_routing_and_dns): queueing DNS 
updates (1)
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.767372] 
[dns-manager/nm-dns-manager.c:1023] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS 
configuration did not change
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.768067] 
[dns-manager/nm-dns-manager.c:1027] nm_dns_manager_end_updates(): (update_routing_and_dns): no DNS changes to 
commit (0)
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.768387] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (2): 
'autoactivate'
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.768927] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'queued state change to disconnected'
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  Auto-activating connection 'Aeris'.
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.774851] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (2): 
'activation::0x214ed20'
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.775661] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'autoactivate'
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: starting connection 
'Aeris'
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) scheduled...
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) started...
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: disconnected 
-> prepare (reason 'none') [30 40 0]
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  NetworkManager state is now CONNECTING
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.785006] 
[nm-active-connection.c:480] check_master_ready(): (0x214ed20): not signalling master-ready (no master)
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.786105] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x213c268] (mlan0): add_pending_action (1): 
'autoactivate'
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.786794] [nm-manager.c:4328] 
policy_activating_device_changed(): ActivatingConnection now Aeris
May 18 14:34:57 canect2 daemon.info ModemManager[423]: <info>  Simple connect started...
May 18 14:34:57 canect2 daemon.info ModemManager[423]: <info>  Simple connect state (4/8): Wait to get fully 
enabled
May 18 14:34:57 canect2 daemon.info ModemManager[423]: <info>  Simple connect state (5/8): Register
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): Activation: Stage 1 of 5 (Device 
Prepare) complete.
May 18 14:34:57 canect2 daemon.info NetworkManager[245]: <debug> [1495118097.803973] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x213c268] (mlan0): remove_pending_action (0): 
'autoactivate'
May 18 14:35:12 canect2 daemon.warn NetworkManager[245]: <warn>  (ttyACM0) failed to connect modem: Network 
timeout
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: prepare -> 
failed (reason 'gsm-registration-timeout') [40 120 32]
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <info>  NetworkManager state is now DISCONNECTED
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.191531] 
[nm-active-connection.c:476] check_master_ready(): (0x214ed20): not signalling master-ready (not activating)
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.191884] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(0): 'activation::0x214ed20'
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.198446] [nm-policy.c:1125] 
device_state_changed(): Connection 'Aeris' failed to autoconnect; 1 tries left
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <info>  Disabling autoconnect for connection 'Aeris'.
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.201007] [nm-manager.c:4328] 
policy_activating_device_changed(): ActivatingConnection now (none)
May 18 14:35:12 canect2 daemon.warn NetworkManager[245]: <warn>  (ttyACM0): Activation: failed for connection 
'Aeris'
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.202306] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (1): 
'queued state change to disconnected'
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.203023] 
[devices/nm-device.c:7768] nm_device_queue_state(): [0x21602f0] (ttyACM0): queued state change to 
disconnected due to none (id 100339)
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.209650] 
[devices/nm-device.c:7717] queued_set_state(): [0x21602f0] (ttyACM0): running queued state change to 
disconnected (id 100339)
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): device state change: failed -> 
disconnected (reason 'none') [120 30 0]
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <info>  (ttyACM0): deactivating device (reason 
'none') [0]
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.211004] 
[nm-firewall-manager.c:256] nm_firewall_manager_remove_from_zone(): (ttyACM0) firewall zone remove skipped 
(not running)
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.211233] 
[devices/nm-device.c:7066] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'dhcp6' not pending (expected)
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.211435] 
[devices/nm-device.c:7066] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'autoconf6' not pending (expected)
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.212109] 
[platform/nm-linux-platform.c:2085] sysctl_set(): sysctl: failed to open 
'/proc/sys/net/ipv6/conf/ttyACM0/accept_ra': (2) No such file or directory
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.212562] 
[platform/nm-linux-platform.c:2085] sysctl_set(): sysctl: failed to open 
'/proc/sys/net/ipv6/conf/ttyACM0/use_tempaddr': (2) No such file or directory
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.215277] 
[dns-manager/nm-dns-manager.c:1005] nm_dns_manager_begin_updates(): (update_routing_and_dns): queueing DNS 
updates (1)
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.215712] 
[dns-manager/nm-dns-manager.c:1023] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS 
configuration did not change
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.216003] 
[dns-manager/nm-dns-manager.c:1027] nm_dns_manager_end_updates(): (update_routing_and_dns): no DNS changes to 
commit (0)
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.216721] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x21602f0] (ttyACM0): add_pending_action (2): 
'autoactivate'
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.217263] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(1): 'queued state change to disconnected'
May 18 14:35:12 canect2 daemon.info NetworkManager[245]: <debug> [1495118112.221731] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x21602f0] (ttyACM0): remove_pending_action 
(0): 'autoactivate'
May 18 14:35:17 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (idle -> searching)
May 18 14:35:22 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (searching -> idle)
May 18 14:35:27 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (idle -> searching)
May 18 14:35:27 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (searching -> idle)
May 18 14:35:32 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (idle -> searching)
May 18 14:35:32 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (searching -> idle)
May 18 14:35:37 canect2 daemon.info NetworkManager[245]: <debug> [1495118137.696288] 
[devices/nm-device.c:7019] nm_device_add_pending_action(): [0x213c268] (mlan0): add_pending_action (1): 'scan'
May 18 14:35:37 canect2 daemon.info NetworkManager[245]: <debug> [1495118137.704049] 
[devices/nm-device.c:7052] nm_device_remove_pending_action(): [0x213c268] (mlan0): remove_pending_action (0): 
'scan'
May 18 14:35:37 canect2 user.alert kernel: [150011.510693] wlan: mlan0 START SCAN
May 18 14:35:37 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (idle -> searching)
May 18 14:35:38 canect2 daemon.info ModemManager[423]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP Registration state changed (searching -> idle)
May 18 14:35:39 canect2 daemon.info NetworkManager[245]: <debug> [1495118139.330325] 
[platform/nm-linux-platform.c:1950] event_notification(): netlink event (type 16) for link: mlan0 (6, family 
0)
May 18 14:35:39 canect2 daemon.info NetworkManager[245]: <debug> [1495118139.330734] 
[platform/nm-linux-platform.c:426] get_kernel_object(): get_kernel_object for link: mlan0 (6, family 0)
May 18 14:35:39 canect2 daemon.info NetworkManager[245]: <debug> [1495118139.331451] 
[platform/nm-linux-platform.c:1950] event_notification(): netlink event (type 16) for link: mlan0 (6, family 
0)
May 18 14:35:39 canect2 daemon.info NetworkManager[245]: <debug> [1495118139.331801] 
[platform/nm-linux-platform.c:426] get_kernel_object(): get_kernel_object for link: mlan0 (6, family 0)
May 18 14:35:39 canect2 user.warn kernel: [150013.133087] wlan: SCAN COMPLETED: scanned AP count=13

Best regards,
 
Matthew Starr
Sr. Software Engineer
HED Inc.
mstarr hedonline com
http://hedonline.com
Follow-Ups:
- Re: Network Manager 1.0.X Wi-Fi Autoconnect Issues
  - From: Dan Williams
[Date Prev][Date Next] [Thread Prev][Thread Next] [Thread Index] [Date Index] [Author Index]