GNOME.org
 

Re: Network Manager 1.0.X Wi-Fi Autoconnect Issues

On Thu, 2017-05-18 at 15:54 +0000, Matthew Starr wrote:

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?


Like you say, it does look like NM is trying to auto-activate the
connection, but it's not doing it correctly.  The most likely thing
happening is that it does try to activate, but it's not able to find
the "best" connection for the device.  Somehow the existing WiFi
connection profile isn't matching.

Can you run 'nmcli con show <name of connection you expect to start>'?

Also, 'iw dev mlan0 scan dump', find the block for the expected AP, and
report that.  Feel free to replace the BSSID with xs or something if
you want to hide it.

My best guess is a mismatch between the AP's beacon/properties and the
connection somehow.

Dan


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

_______________________________________________
networkmanager-list mailing list
networkmanager-list gnome org
https://mail.gnome.org/mailman/listinfo/networkmanager-list
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]