Re: Timeout error adding wireless interface to supplicant with NM 1.14.4

From: Dan Williams <dcbw redhat com>
To: "Buzarra, Arturo" <Arturo Buzarra digi com>, 'Florin' <florin balena io>
Cc: "'networkmanager-list gnome org'" <networkmanager-list gnome org>
Subject: Re: Timeout error adding wireless interface to supplicant with NM 1.14.4
Date: Tue, 12 Feb 2019 12:32:56 -0600

On Tue, 2019-02-12 at 16:27 +0000, Buzarra, Arturo wrote:

Hi Florin,

This is the output when the NM fails adding the interface:


The supplicant really does have a 21 second delay while adding the
interface, and this is a supplicant or driver issue.

The logs show there is a delay in wpa_supplicant_init_iface() between
wpas_wps_init() and wpa_supplicant_init_eapol():

        if (wpas_wps_init(wpa_s))
                return -1;

#ifdef CONFIG_GAS_SERVER
        wpa_s->gas_server = gas_server_init(wpa_s, wpas_gas_server_tx);
        if (!wpa_s->gas_server) {
                wpa_printf(MSG_ERROR, "Failed to initialize GAS
server");
                return -1;
        }
#endif /* CONFIG_GAS_SERVER */

#ifdef CONFIG_DPP
        if (wpas_dpp_init(wpa_s) < 0)
                return -1;
#endif /* CONFIG_DPP */

        if (wpa_supplicant_init_eapol(wpa_s) < 0)
                return -1;

It could be something WPS- or DPP-related in the driver, or it could be
some kind of long timeout loading OpenSSL modules. But it's clearly in
the supplicant and unrelated to NetworkManager, at least judging by the
logs.

Dan

                Output for wpa_supplicant:

-- Logs begin at Tue 2019-02-12 15:23:05 UTC, end at Tue 2019-02-12
15:27:47 UTC. --
Feb 12 15:23:09  systemd[1]: Starting WPA supplicant...
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_supplicant v2.6
Feb 12 15:23:09  wpa_supplicant[3233]: random: Trying to read entropy
from /dev/random
Feb 12 15:23:09  wpa_supplicant[3233]: dbus: Register D-Bus object
'/fi/w1/wpa_supplicant1'
Feb 12 15:23:09  wpa_supplicant[3233]: Providing DBus service
'fi.w1.wpa_supplicant1'.
Feb 12 15:23:09  wpa_supplicant[3233]: Providing DBus service
'fi.epitest.hostap.WPASupplicant'.
Feb 12 15:23:09  wpa_supplicant[3233]: Successfully initialized
wpa_supplicant
Feb 12 15:23:09  wpa_supplicant[3233]: random: Got 9/20 bytes from
/dev/random
Feb 12 15:23:09  wpa_supplicant[3233]: dbus:
org.freedesktop.DBus.Properties.GetAll (/fi/w1/wpa_supplicant1) [s]
Feb 12 15:23:09  wpa_supplicant[3233]: dbus:
org.freedesktop.DBus.Properties.GetAll (/fi/w1/wpa_supplicant1) [s]
Feb 12 15:23:09  wpa_supplicant[3233]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:23:09  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:23:09  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:23:09  wpa_supplicant[3233]: Initializing interface 'wlan0'
conf 'N/A' driver 'nl80211,wext' ctrl_interface 'N/A' bridge 'N/A'
Feb 12 15:23:09  systemd[1]: Started WPA supplicant.
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Using driver-based
roaming
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: TDLS supported
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: TDLS external setup
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported cipher 00-
0f-ac:1
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported cipher 00-
0f-ac:5
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported cipher 00-
0f-ac:2
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported cipher 00-
40-96:254
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported cipher 00-
40-96:255
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported cipher 00-
0f-ac:4
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported cipher 00-
14-72:1
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported cipher 00-
0f-ac:6
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supports Probe
Response offload in AP mode
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Using driver-based
off-channel TX
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=11
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=12
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=13
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=20
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=21
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=22
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=23
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=24
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=29
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=30
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=32
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=33
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=69
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=16
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=14
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=15
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=34
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=35
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=36
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=38
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=39
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=40
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=42
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=54
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=55
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=50
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=74
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=75
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=64
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=70
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=71
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=61
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=92
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=93
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=94
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=95
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=96
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=97
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=98
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=99
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=76
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=63
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=62
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=78
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=101
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=77
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=79
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=80
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=82
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=105
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=83
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=84
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=85
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=81
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=116
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=117
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=10
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=118
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=121
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=9
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=109
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=115
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=138
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=127
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=10
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=12
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=13
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=20
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=21
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=23
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=24
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=25
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=26
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=27
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=28
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=29
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=30
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=31
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=32
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=33
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=14
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=15
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=16
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=17
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=18
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=19
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=127
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=37
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=54
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=51
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=56
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=57
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=58
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=59
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=60
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=41
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=72
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=73
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=100
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=63
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=80
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=81
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=148
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Use separate P2P
group interface (driver advertised support)
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Enable multi-channel
concurrent (driver advertised support)
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: interface wlan0 in
phy phy0
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Set mode ifindex 6
iftype 2 (STATION)
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Subscribe to mgmt
frames with non-AP handle 0xaaaacc9f2e70
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=040a
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=040b
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=040c
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=040d
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=090a
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=090b
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=090c
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=090d
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70
match=0409506f9a09
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70
match=7f506f9a09
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=06
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=0a07
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=0a11
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=1101
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=1102
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=0505
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaaacc9f2e70 match=0500
Feb 12 15:23:09  wpa_supplicant[3233]: rfkill: Cannot open RFKILL
control device
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: RFKILL status not
available
Feb 12 15:23:09  wpa_supplicant[3233]: netlink: Operstate: ifindex=6
linkmode=1 (userspace-control), operstate=5 (IF_OPER_DORMANT)
Feb 12 15:23:09  wpa_supplicant[3233]: Add interface wlan0 to a new
radio phy0
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Regulatory
information - country=00
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: 2402-2472 @ 40 MHz 20
mBm
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: 2457-2482 @ 20 MHz 20
mBm (no IR)
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: 2474-2494 @ 20 MHz 20
mBm (no OFDM) (no IR)
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: 5170-5250 @ 80 MHz 20
mBm (no IR)
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: 5250-5330 @ 80 MHz 20
mBm (DFS) (no IR)
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: 5490-5730 @ 160 MHz
20 mBm (DFS) (no IR)
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: 5735-5835 @ 80 MHz 20
mBm (no IR)
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: 57240-63720 @ 2160
MHz 0 mBm
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Added 802.11b mode
based on 802.11g information
Feb 12 15:23:09  wpa_supplicant[3233]: wlan0: Own MAC address:
00:04:8d:01:26:02
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_driver_nl80211_set_key:
ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0
key_len=0
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_driver_nl80211_set_key:
ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0
key_len=0
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_driver_nl80211_set_key:
ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0
key_len=0
Feb 12 15:23:09  wpa_supplicant[3233]: wpa_driver_nl80211_set_key:
ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=3 set_tx=0 seq_len=0
key_len=0
Feb 12 15:23:09  wpa_supplicant[3233]: wlan0: RSN: flushing PMKID
list in the driver
Feb 12 15:23:09  wpa_supplicant[3233]: nl80211: Flush PMKIDs
Feb 12 15:23:09  wpa_supplicant[3233]: wlan0: State: DISCONNECTED ->
INACTIVE
Feb 12 15:23:09  wpa_supplicant[3233]: wlan0: WPS: UUID based on MAC
address: 3f86a0f8-de5a-5a9e-960c-3ec84683397a
Feb 12 15:26:30  wpa_supplicant[3233]: ENGINE: Loading dynamic engine
Feb 12 15:26:30  wpa_supplicant[3233]: ENGINE: Loading dynamic engine
Feb 12 15:26:30  wpa_supplicant[3233]: EAPOL: SUPP_PAE entering state
DISCONNECTED
Feb 12 15:26:30  wpa_supplicant[3233]: EAPOL: Supplicant port status:
Unauthorized
Feb 12 15:26:30  wpa_supplicant[3233]: nl80211: Skip
set_supp_port(unauthorized) while not associated
Feb 12 15:26:30  wpa_supplicant[3233]: EAPOL: KEY_RX entering state
NO_KEY_RECEIVE
Feb 12 15:26:30  wpa_supplicant[3233]: EAPOL: SUPP_BE entering state
INITIALIZE
Feb 12 15:26:30  wpa_supplicant[3233]: EAP: EAP entering state
DISABLED
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: Add operating class 81
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: Channels -
hexdump(len=11): 01 02 03 04 05 06 07 08 09 0a 0b
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: Own listen channel: 81:1
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: Random operating channel:
81:1
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: initialized
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: channels:
81:1,2,3,4,5,6,7,8,9,10,11
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: cli_channels:
Feb 12 15:26:30  wpa_supplicant[3233]: dbus: Register interface
object '/fi/w1/wpa_supplicant1/Interfaces/1'
Feb 12 15:26:30  wpa_supplicant[3233]: wlan0: Added interface wlan0
Feb 12 15:26:30  wpa_supplicant[3233]: wlan0: State: INACTIVE ->
DISCONNECTED
Feb 12 15:26:30  wpa_supplicant[3233]: nl80211: Set wlan0 operstate
0->0 (DORMANT)
Feb 12 15:26:30  wpa_supplicant[3233]: netlink: Operstate: ifindex=6
linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Feb 12 15:26:30  wpa_supplicant[3233]: wlan0: Determining shared
radio frequencies (max len 2)
Feb 12 15:26:30  wpa_supplicant[3233]: wlan0: Shared frequencies
(len=0): completed iteration
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: Add operating class 81
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: Channels -
hexdump(len=11): 01 02 03 04 05 06 07 08 09 0a 0b
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: Update channel list
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: channels:
81:1,2,3,4,5,6,7,8,9,10,11
Feb 12 15:26:30  wpa_supplicant[3233]: P2P: cli_channels:
Feb 12 15:26:30  wpa_supplicant[3233]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:26:30  wpa_supplicant[3233]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:26:30  wpa_supplicant[3233]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:26:30  wpa_supplicant[3233]: RTM_NEWLINK: ifi_index=6
ifname=wlan0 operstate=2 linkmode=1 ifi_family=0 ifi_flags=0x1003
([UP])
Feb 12 15:26:31  wpa_supplicant[3233]: EAPOL: disable timer tick
Feb 12 15:27:47  wpa_supplicant[3233]: random: Got 6/11 bytes from
/dev/random


                Output for NM:
                Feb 12 15:23:09 NetworkManager[2809]:
<info>  [1549984989.1520] device (wlan0): supplicant interface state:
init -> starting
Feb 12 15:23:09 NetworkManager[2809]: <debug> [1549984989.1515]
supplicant: AP mode is supported
Feb 12 15:23:09 NetworkManager[2809]: <debug> [1549984989.1515]
supplicant: PMF is not supported
Feb 12 15:23:09 NetworkManager[2809]: <debug> [1549984989.1516]
supplicant: FILS is not supported
Feb 12 15:23:09 NetworkManager[2809]: <debug> [1549984989.1518]
supplicant: EAP-FAST is supported
Feb 12 15:23:09 NetworkManager[2809]: <debug> [1549984989.1519] sup-
iface[0xaaaae4330190,wlan0]: adding interface to supplicant
Feb 12 15:23:09 NetworkManager[2809]: <info>  [1549984989.1520]
device (wlan0): supplicant interface state: init -> starting
Feb 12 15:23:09 NetworkManager[2809]: <debug> [1549984989.1586]
sleep-monitor-sd: inhibit: inhibitor fd is 17
Feb 12 15:23:09 NetworkManager[2809]: <debug> [1549984989.1586]
sleep-monitor-sd: inhibit: inhibitor fd is 17
Feb 12 15:23:34 NetworkManager[2809]: <error> [1549985014.1636] sup-
iface[0xaaaae4330190,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:23:34 NetworkManager[2809]: <info>  [1549985014.1639]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:23:34 NetworkManager[2809]: <debug> [1549985014.1641]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:23:34 NetworkManager[2809]: <debug> [1549985014.1642]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:23:34 NetworkManager[2809]: <debug> [1549985014.1643]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:23:34 NetworkManager[2809]: <debug> [1549985014.1646]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:23:34 NetworkManager[2809]: <info>  [1549985014.1648]
manager: startup complete
Feb 12 15:23:34 NetworkManager[2809]: <error> [1549985014.1636] sup-
iface[0xaaaae4330190,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:23:34 NetworkManager[2809]: <info>  [1549985014.1639]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:23:34 NetworkManager[2809]: <debug> [1549985014.1641]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:23:34 NetworkManager[2809]: <debug> [1549985014.1642]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:23:34 NetworkManager[2809]: <debug> [1549985014.1643]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:23:34 NetworkManager[2809]: <debug> [1549985014.1646]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:23:34 NetworkManager[2809]: <info>  [1549985014.1648]
manager: startup complete
Feb 12 15:23:44 NetworkManager[2809]: <warn>  [1549985024.0675]
device (wlan0): re-acquiring supplicant interface (#1).
Feb 12 15:23:44 NetworkManager[2809]: <debug> [1549985024.0678]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:23:44 NetworkManager[2809]: <debug> [1549985024.0680] sup-
iface[0xaaaae4330240,wlan0]: adding interface to supplicant
Feb 12 15:23:44 NetworkManager[2809]: <debug> [1549985024.0684]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:23:44 NetworkManager[2809]: <warn>  [1549985024.0675]
device (wlan0): re-acquiring supplicant interface (#1).
Feb 12 15:23:44 NetworkManager[2809]: <debug> [1549985024.0678]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:23:44 NetworkManager[2809]: <debug> [1549985024.0680] sup-
iface[0xaaaae4330240,wlan0]: adding interface to supplicant
Feb 12 15:23:44 NetworkManager[2809]: <debug> [1549985024.0684]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:24:09 NetworkManager[2809]: <error> [1549985049.0977] sup-
iface[0xaaaae4330240,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:24:09 NetworkManager[2809]: <info>  [1549985049.0980]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:24:09 NetworkManager[2809]: <debug> [1549985049.0982]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:24:09 NetworkManager[2809]: <debug> [1549985049.0983]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:24:09 NetworkManager[2809]: <debug> [1549985049.0984]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:24:09 NetworkManager[2809]: <debug> [1549985049.0987]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:24:09 NetworkManager[2809]: <error> [1549985049.0977] sup-
iface[0xaaaae4330240,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:24:09 NetworkManager[2809]: <info>  [1549985049.0980]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:24:09 NetworkManager[2809]: <debug> [1549985049.0982]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:24:09 NetworkManager[2809]: <debug> [1549985049.0983]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:24:09 NetworkManager[2809]: <debug> [1549985049.0984]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:24:09 NetworkManager[2809]: <debug> [1549985049.0987]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:24:19 NetworkManager[2809]: <warn>  [1549985059.0720]
device (wlan0): re-acquiring supplicant interface (#2).
Feb 12 15:24:19 NetworkManager[2809]: <debug> [1549985059.0723]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:24:19 NetworkManager[2809]: <debug> [1549985059.0725] sup-
iface[0xaaaae43302f0,wlan0]: adding interface to supplicant
Feb 12 15:24:19 NetworkManager[2809]: <debug> [1549985059.0729]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:24:19 NetworkManager[2809]: <warn>  [1549985059.0720]
device (wlan0): re-acquiring supplicant interface (#2).
Feb 12 15:24:19 NetworkManager[2809]: <debug> [1549985059.0723]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:24:19 NetworkManager[2809]: <debug> [1549985059.0725] sup-
iface[0xaaaae43302f0,wlan0]: adding interface to supplicant
Feb 12 15:24:19 NetworkManager[2809]: <debug> [1549985059.0729]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:24:44 NetworkManager[2809]: <error> [1549985084.1024] sup-
iface[0xaaaae43302f0,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:24:44 NetworkManager[2809]: <error> [1549985084.1024] sup-
iface[0xaaaae43302f0,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:24:44 NetworkManager[2809]: <info>  [1549985084.1027]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:24:44 NetworkManager[2809]: <debug> [1549985084.1029]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:24:44 NetworkManager[2809]: <debug> [1549985084.1030]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:24:44 NetworkManager[2809]: <debug> [1549985084.1031]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:24:44 NetworkManager[2809]: <debug> [1549985084.1035]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:24:44 NetworkManager[2809]: <info>  [1549985084.1027]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:24:44 NetworkManager[2809]: <debug> [1549985084.1029]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:24:44 NetworkManager[2809]: <debug> [1549985084.1030]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:24:44 NetworkManager[2809]: <debug> [1549985084.1031]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:24:44 NetworkManager[2809]: <debug> [1549985084.1035]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:24:54 NetworkManager[2809]: <warn>  [1549985094.0717]
device (wlan0): re-acquiring supplicant interface (#3).
Feb 12 15:24:54 NetworkManager[2809]: <debug> [1549985094.0719]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:24:54 NetworkManager[2809]: <debug> [1549985094.0721] sup-
iface[0xaaaae43303a0,wlan0]: adding interface to supplicant
Feb 12 15:24:54 NetworkManager[2809]: <debug> [1549985094.0726]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:24:54 NetworkManager[2809]: <warn>  [1549985094.0717]
device (wlan0): re-acquiring supplicant interface (#3).
Feb 12 15:24:54 NetworkManager[2809]: <debug> [1549985094.0719]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:24:54 NetworkManager[2809]: <debug> [1549985094.0721] sup-
iface[0xaaaae43303a0,wlan0]: adding interface to supplicant
Feb 12 15:24:54 NetworkManager[2809]: <debug> [1549985094.0726]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:25:19 NetworkManager[2809]: <error> [1549985119.1019] sup-
iface[0xaaaae43303a0,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:25:19 NetworkManager[2809]: <info>  [1549985119.1022]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:25:19 NetworkManager[2809]: <debug> [1549985119.1024]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:25:19 NetworkManager[2809]: <debug> [1549985119.1025]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:25:19 NetworkManager[2809]: <debug> [1549985119.1026]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:25:19 NetworkManager[2809]: <debug> [1549985119.1030]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:25:19 NetworkManager[2809]: <error> [1549985119.1019] sup-
iface[0xaaaae43303a0,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:25:19 NetworkManager[2809]: <info>  [1549985119.1022]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:25:19 NetworkManager[2809]: <debug> [1549985119.1024]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:25:19 NetworkManager[2809]: <debug> [1549985119.1025]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:25:19 NetworkManager[2809]: <debug> [1549985119.1026]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:25:19 NetworkManager[2809]: <debug> [1549985119.1030]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:25:29 NetworkManager[2809]: <warn>  [1549985129.0722]
device (wlan0): re-acquiring supplicant interface (#4).
Feb 12 15:25:29 NetworkManager[2809]: <debug> [1549985129.0724]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:25:29 NetworkManager[2809]: <debug> [1549985129.0726] sup-
iface[0xaaaae4330450,wlan0]: adding interface to supplicant
Feb 12 15:25:29 NetworkManager[2809]: <debug> [1549985129.0730]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:25:29 NetworkManager[2809]: <warn>  [1549985129.0722]
device (wlan0): re-acquiring supplicant interface (#4).
Feb 12 15:25:29 NetworkManager[2809]: <debug> [1549985129.0724]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:25:29 NetworkManager[2809]: <debug> [1549985129.0726] sup-
iface[0xaaaae4330450,wlan0]: adding interface to supplicant
Feb 12 15:25:29 NetworkManager[2809]: <debug> [1549985129.0730]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:25:54 NetworkManager[2809]: <error> [1549985154.1025] sup-
iface[0xaaaae4330450,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:25:54 NetworkManager[2809]: <info>  [1549985154.1028]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:25:54 NetworkManager[2809]: <debug> [1549985154.1030]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:25:54 NetworkManager[2809]: <debug> [1549985154.1031]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:25:54 NetworkManager[2809]: <debug> [1549985154.1032]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:25:54 NetworkManager[2809]: <debug> [1549985154.1035]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:25:54 NetworkManager[2809]: <error> [1549985154.1025] sup-
iface[0xaaaae4330450,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:25:54 NetworkManager[2809]: <info>  [1549985154.1028]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:25:54 NetworkManager[2809]: <debug> [1549985154.1030]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:25:54 NetworkManager[2809]: <debug> [1549985154.1031]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:25:54 NetworkManager[2809]: <debug> [1549985154.1032]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:25:54 NetworkManager[2809]: <debug> [1549985154.1035]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:26:04 NetworkManager[2809]: <warn>  [1549985164.0718]
device (wlan0): re-acquiring supplicant interface (#5).
Feb 12 15:26:04 NetworkManager[2809]: <debug> [1549985164.0720]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:26:04 NetworkManager[2809]: <debug> [1549985164.0722] sup-
iface[0xaaaae4330500,wlan0]: adding interface to supplicant
Feb 12 15:26:04 NetworkManager[2809]: <debug> [1549985164.0726]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:26:04 NetworkManager[2809]: <warn>  [1549985164.0718]
device (wlan0): re-acquiring supplicant interface (#5).
Feb 12 15:26:04 NetworkManager[2809]: <debug> [1549985164.0720]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:26:04 NetworkManager[2809]: <debug> [1549985164.0722] sup-
iface[0xaaaae4330500,wlan0]: adding interface to supplicant
Feb 12 15:26:04 NetworkManager[2809]: <debug> [1549985164.0726]
device[0xaaaae43c4090] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:26:29 NetworkManager[2809]: <error> [1549985189.1020] sup-
iface[0xaaaae4330500,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:26:29 NetworkManager[2809]: <error> [1549985189.1020] sup-
iface[0xaaaae4330500,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:26:29 NetworkManager[2809]: <info>  [1549985189.1023]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:26:29 NetworkManager[2809]: <debug> [1549985189.1025]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:26:29 NetworkManager[2809]: <debug> [1549985189.1026]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:26:29 NetworkManager[2809]: <debug> [1549985189.1027]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:26:29 NetworkManager[2809]: <info>  [1549985189.1028]
device (wlan0): supplicant interface keeps failing, giving up
Feb 12 15:26:29 NetworkManager[2809]: <debug> [1549985189.1031]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:26:29 NetworkManager[2809]: <info>  [1549985189.1023]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:26:29 NetworkManager[2809]: <debug> [1549985189.1025]
device[0xaaaae43c4090] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:26:29 NetworkManager[2809]: <debug> [1549985189.1026]
device[0xaaaae43c4090] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:26:29 NetworkManager[2809]: <debug> [1549985189.1027]
device[0xaaaae43c4090] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:26:29 NetworkManager[2809]: <info>  [1549985189.1028]
device (wlan0): supplicant interface keeps failing, giving up
Feb 12 15:26:29 NetworkManager[2809]: <debug> [1549985189.1031]
device[0xaaaae43c4090] (wlan0): remove_pending_action (0): 'recheck-
available'



Also this is the output when the NM is able to add the wireless
interface to the supplicant with dbus:

                Output for wpa_supplicant:
                -- Logs begin at Tue 2019-02-12 15:18:09 UTC, end at
Tue 2019-02-12 15:21:19 UTC. --
Feb 12 15:18:12 systemd[1]: Starting WPA supplicant...
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_supplicant v2.6
Feb 12 15:18:12 wpa_supplicant[3102]: random: Trying to read entropy
from /dev/random
Feb 12 15:18:12 wpa_supplicant[3102]: dbus: Register D-Bus object
'/fi/w1/wpa_supplicant1'
Feb 12 15:18:12 wpa_supplicant[3102]: Providing DBus service
'fi.w1.wpa_supplicant1'.
Feb 12 15:18:12 wpa_supplicant[3102]: Providing DBus service
'fi.epitest.hostap.WPASupplicant'.
Feb 12 15:18:12 wpa_supplicant[3102]: Successfully initialized
wpa_supplicant
Feb 12 15:18:12 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll (/fi/w1/wpa_supplicant1) [s]
Feb 12 15:18:12 wpa_supplicant[3102]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:18:12 wpa_supplicant[3102]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:18:12 wpa_supplicant[3102]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:18:12 wpa_supplicant[3102]: Initializing interface 'wlan0'
conf 'N/A' driver 'nl80211,wext' ctrl_interface 'N/A' bridge 'N/A'
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Using driver-based
roaming
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: TDLS supported
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: TDLS external setup
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported cipher 00-
0f-ac:1
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported cipher 00-
0f-ac:5
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported cipher 00-
0f-ac:2
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported cipher 00-
40-96:254
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported cipher 00-
40-96:255
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported cipher 00-
0f-ac:4
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported cipher 00-
14-72:1
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported cipher 00-
0f-ac:6
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supports Probe
Response offload in AP mode
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Using driver-based
off-channel TX
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=11
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=12
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=13
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=20
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=21
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=22
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=23
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=24
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=29
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=30
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=32
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=33
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=69
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=16
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=14
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=15
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=34
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=35
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=36
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=38
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=39
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=40
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=42
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=54
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=55
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=50
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=74
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=75
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=64
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=70
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=71
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=61
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=92
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=93
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=94
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=95
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=96
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=97
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=98
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=99
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=76
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=63
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=62
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=78
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=101
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=77
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=79
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=80
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=82
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=105
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=83
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=84
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=85
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=81
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=116
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=117
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=10
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=118
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=121
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=9
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=109
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=115
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=138
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
command: vendor_id=0x1374 subcmd=127
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=10
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=12
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=13
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=20
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=21
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=23
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=24
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=25
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=26
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=27
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=28
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=29
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=30
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=31
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=32
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=33
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=14
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=15
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=16
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=17
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=18
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=19
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=127
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=37
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=54
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=51
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=56
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=57
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=58
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=59
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=60
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=41
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=72
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=73
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=100
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=63
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=80
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=81
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Supported vendor
event: vendor_id=0x1374 subcmd=148
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Use separate P2P group
interface (driver advertised support)
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Enable multi-channel
concurrent (driver advertised support)
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: interface wlan0 in phy
phy0
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Set mode ifindex 6
iftype 2 (STATION)
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Subscribe to mgmt
frames with non-AP handle 0xaaab186abe70
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=040a
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=040b
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=040c
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=040d
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=090a
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=090b
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=090c
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=090d
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70
match=0409506f9a09
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70
match=7f506f9a09
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=06
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=0a07
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=0a11
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=1101
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=1102
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=0505
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Register frame
type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0xaaab186abe70 match=0500
Feb 12 15:18:12 wpa_supplicant[3102]: rfkill: Cannot open RFKILL
control device
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: RFKILL status not
available
Feb 12 15:18:12 wpa_supplicant[3102]: netlink: Operstate: ifindex=6
linkmode=1 (userspace-control), operstate=5 (IF_OPER_DORMANT)
Feb 12 15:18:12 wpa_supplicant[3102]: Add interface wlan0 to a new
radio phy0
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Regulatory information
- country=00
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: 2402-2472 @ 40 MHz 20
mBm
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: 2457-2482 @ 20 MHz 20
mBm (no IR)
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: 2474-2494 @ 20 MHz 20
mBm (no OFDM) (no IR)
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: 5170-5250 @ 80 MHz 20
mBm (no IR)
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: 5250-5330 @ 80 MHz 20
mBm (DFS) (no IR)
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: 5490-5730 @ 160 MHz 20
mBm (DFS) (no IR)
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: 5735-5835 @ 80 MHz 20
mBm (no IR)
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: 57240-63720 @ 2160 MHz
0 mBm
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Added 802.11b mode
based on 802.11g information
Feb 12 15:18:12 wpa_supplicant[3102]: wlan0: Own MAC address:
00:04:8d:01:26:02
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_driver_nl80211_set_key:
ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0
key_len=0
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_driver_nl80211_set_key:
ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0
key_len=0
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_driver_nl80211_set_key:
ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0
key_len=0
Feb 12 15:18:12 wpa_supplicant[3102]: wpa_driver_nl80211_set_key:
ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=3 set_tx=0 seq_len=0
key_len=0
Feb 12 15:18:12 wpa_supplicant[3102]: wlan0: RSN: flushing PMKID list
in the driver
Feb 12 15:18:12 wpa_supplicant[3102]: nl80211: Flush PMKIDs
Feb 12 15:18:12 wpa_supplicant[3102]: wlan0: State: DISCONNECTED ->
INACTIVE
Feb 12 15:18:12 wpa_supplicant[3102]: wlan0: WPS: UUID based on MAC
address: 3f86a0f8-de5a-5a9e-960c-3ec84683397a
Feb 12 15:18:12 systemd[1]: Started WPA supplicant.
Feb 12 15:20:16 wpa_supplicant[3102]: ENGINE: Loading dynamic engine
Feb 12 15:20:16 wpa_supplicant[3102]: ENGINE: Loading dynamic engine
Feb 12 15:20:16 wpa_supplicant[3102]: EAPOL: SUPP_PAE entering state
DISCONNECTED
Feb 12 15:20:16 wpa_supplicant[3102]: EAPOL: Supplicant port status:
Unauthorized
Feb 12 15:20:16 wpa_supplicant[3102]: nl80211: Skip
set_supp_port(unauthorized) while not associated
Feb 12 15:20:16 wpa_supplicant[3102]: EAPOL: KEY_RX entering state
NO_KEY_RECEIVE
Feb 12 15:20:16 wpa_supplicant[3102]: EAPOL: SUPP_BE entering state
INITIALIZE
Feb 12 15:20:16 wpa_supplicant[3102]: EAP: EAP entering state
DISABLED
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: Add operating class 81
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: Channels -
hexdump(len=11): 01 02 03 04 05 06 07 08 09 0a 0b
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: Own listen channel: 81:11
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: Random operating channel:
81:1
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: initialized
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: channels:
81:1,2,3,4,5,6,7,8,9,10,11
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: cli_channels:
Feb 12 15:20:16 wpa_supplicant[3102]: dbus: Register interface object
'/fi/w1/wpa_supplicant1/Interfaces/1'
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: Added interface wlan0
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: State: INACTIVE ->
DISCONNECTED
Feb 12 15:20:16 wpa_supplicant[3102]: nl80211: Set wlan0 operstate 0-

0 (DORMANT)

Feb 12 15:20:16 wpa_supplicant[3102]: netlink: Operstate: ifindex=6
linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: Determining shared radio
frequencies (max len 2)
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: Shared frequencies
(len=0): completed iteration
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: Add operating class 81
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: Channels -
hexdump(len=11): 01 02 03 04 05 06 07 08 09 0a 0b
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: Update channel list
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: channels:
81:1,2,3,4,5,6,7,8,9,10,11
Feb 12 15:20:16 wpa_supplicant[3102]: P2P: cli_channels:
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:20:16 wpa_supplicant[3102]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:20:16 wpa_supplicant[3102]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:20:16 wpa_supplicant[3102]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:20:16 wpa_supplicant[3102]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
fi.w1.wpa_supplicant1.CreateInterface (/fi/w1/wpa_supplicant1)
[a{sv}]
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_open_read: start
reading a dict entry
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry key: Driver
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:20:16 wpa_supplicant[3102]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry key: Ifname
Feb 12 15:20:16 wpa_supplicant[3102]: wpa_dbus_dict_get_entry: dict
entry variant content type: s
Feb 12 15:20:16 wpa_supplicant[3102]:
_wpa_dbus_dict_fill_value_from_variant: string value: [omitted]
Feb 12 15:20:16 wpa_supplicant[3102]: RTM_NEWLINK: ifi_index=6
ifname=wlan0 operstate=2 linkmode=1 ifi_family=0 ifi_flags=0x1003
([UP])
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
fi.w1.wpa_supplicant1.GetInterface (/fi/w1/wpa_supplicant1) [s]
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1) [s]
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.Set
(/fi/w1/wpa_supplicant1/Interfaces/1) [ssv]
Feb 12 15:20:16 wpa_supplicant[3102]: properties_get_or_set:
Set(BSSExpireAge)
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: Setting bss expiration
age: 250 sec
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.Set
(/fi/w1/wpa_supplicant1/Interfaces/1) [ssv]
Feb 12 15:20:16 wpa_supplicant[3102]: properties_get_or_set:
Set(BSSExpireCount)
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: Setting bss expiration
scan count: 2
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
fi.w1.wpa_supplicant1.Interface.NetworkReply
(/fi/w1/wpa_supplicant1/Interfaces/1) [oss]
Feb 12 15:20:16 wpa_supplicant[3102]: RTM_NEWLINK: ifi_index=6
ifname=wlan0 operstate=2 linkmode=1 ifi_family=0 ifi_flags=0x1003
([UP])
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
fi.w1.wpa_supplicant1.Interface.Scan
(/fi/w1/wpa_supplicant1/Interfaces/1) [a{sv}]
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: Add radio work 
'scan'@0xaaab186db1b0
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: First radio work item in
the queue - schedule start immediately
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: Starting radio work 
'scan'@0xaaab186db1b0 after 0.000155 second wait
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: nl80211: scan request
Feb 12 15:20:16 wpa_supplicant[3102]: nl80211: Scan SSID -
hexdump_ascii(len=0): [NULL]
Feb 12 15:20:16 wpa_supplicant[3102]: Scan requested (ret=0) - scan
timeout 10 seconds
Feb 12 15:20:16 wpa_supplicant[3102]: nl80211: Event message
available
Feb 12 15:20:16 wpa_supplicant[3102]: nl80211: Drv Event 33
(NL80211_CMD_TRIGGER_SCAN) received for wlan0
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: nl80211: Scan trigger
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: Event SCAN_STARTED (47)
received
Feb 12 15:20:16 wpa_supplicant[3102]: wlan0: Own scan request started
a scan in 0.000153 seconds
Feb 12 15:20:16 wpa_supplicant[3102]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1
Feb 12 15:20:17 wpa_supplicant[3102]: EAPOL: disable timer tick
Feb 12 15:20:19 wpa_supplicant[3102]: nl80211: Event message
available
Feb 12 15:20:19 wpa_supplicant[3102]: nl80211: Drv Event 34
(NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: nl80211: New scan
results available
Feb 12 15:20:19 wpa_supplicant[3102]: nl80211: Scan included
frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462
2467 2472 2484 5180 5200 5220 5240 5260 5280 5300 5320 5500 5520 5540
5560 5580 5600 5620 5640 5660 5680 5700 5720 5745 5765 5785 5805 5825
5852 5855 5860 5865 5870 5875 5880 5885 5890 5895
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: Event SCAN_RESULTS (3)
received
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: Scan completed in
3.000402 seconds
Feb 12 15:20:19 wpa_supplicant[3102]: nl80211: Received scan results
(29 BSSes)
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Start scan result
update 1
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 0 BSSID
ec:e1:a9:9a:66:50 SSID 'test_5_ghz_disconnect' freq 5220
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/0'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 1 BSSID
6c:99:89:76:43:9d SSID 'DAP-GUEST' freq 5300
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/1'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 2 BSSID
6c:99:89:76:43:9f SSID '\x00' freq 5300
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/2'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 3 BSSID
68:7f:74:17:cc:c4 SSID 'HH1' freq 2432
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/3'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 4 BSSID
ec:e1:a9:96:6d:d0 SSID 'SARES_Cisco_2600' freq 2442
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/4'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 5 BSSID
6c:99:89:76:43:9e SSID '\x00' freq 5300
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/5'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 6 BSSID
6c:99:89:76:43:92 SSID 'DAP-GUEST' freq 2462
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/6'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 7 BSSID
6c:99:89:76:43:91 SSID '\x00' freq 2462
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/7'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 8 BSSID
6c:99:89:76:43:90 SSID '\x00' freq 2462
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/8'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 9 BSSID
00:1d:70:9c:eb:40 SSID 'Cisco_1200G_EAP_PEAP' freq 2442
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/9'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 10 BSSID
4c:e6:76:c4:5c:50 SSID 'Buffalo_AG300H_WPA2_AES' freq 2447
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/10'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 11 BSSID
e0:0e:da:38:c1:cd SSID 'DAP-GUEST' freq 5240
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/11'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 12 BSSID
e0:0e:da:38:c1:c2 SSID 'DAP-GUEST' freq 2412
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/12'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 13 BSSID
e0:0e:da:38:c1:c0 SSID '\x00' freq 2412
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/13'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 14 BSSID
e0:0e:da:38:c1:cf SSID '\x00' freq 5240
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/14'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 15 BSSID
58:6d:8f:ea:0e:7a SSID 'LINKSYSENG' freq 2462
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/15'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 16 BSSID
e0:0e:da:38:c1:c1 SSID '\x00' freq 2412
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/16'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 17 BSSID
34:57:60:9c:2c:da SSID 'DIGI' freq 2462
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/17'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 18 BSSID
50:64:2b:85:e1:7f SSID 'ONO2D59' freq 2462
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/18'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 19 BSSID
00:17:94:fd:99:c0 SSID 'SARES_Cisco_1200' freq 2432
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/19'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 20 BSSID
4c:1b:86:00:6d:b2 SSID 'Nebraska Milicias' freq 2412
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/20'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 21 BSSID
a0:21:b7:fe:0d:9c SSID 'ONO0D9C' freq 2452
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/21'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 22 BSSID
50:3d:e5:75:af:30 SSID 'SARES_Cisco_1250' freq 2432
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/22'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 23 BSSID
9c:d6:43:2d:1a:70 SSID 'SARES_Dlink_DAP2695' freq 2432
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/23'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 24 BSSID
c0:ac:54:00:5f:8a SSID 'Orange-f702' freq 2437
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/24'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 25 BSSID
6c:99:89:76:43:9c SSID '\x00' freq 5300
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/25'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 26 BSSID
e0:0e:da:38:c1:cc SSID '\x00' freq 5240
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/26'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 27 BSSID
e0:0e:da:38:c1:c3 SSID '\x00' freq 2412
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/27'
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: BSS: Add new id 28 BSSID
6c:99:89:76:43:93 SSID '\x00' freq 2462
Feb 12 15:20:19 wpa_supplicant[3102]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/28'
Feb 12 15:20:19 wpa_supplicant[3102]: BSS: last_scan_res_used=29/32
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: Scan-only results
received
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: Radio work 
'scan'@0xaaab186db1b0 done in 3.021671 seconds
Feb 12 15:20:19 wpa_supplicant[3102]: wlan0: radio_work_free(
'scan'@0xaaab186db1b0: num_active_works --> 0
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/0) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/1) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/3) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/4) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/5) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/6) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/2) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/7) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/8) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/9) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/10) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/11) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/12) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/13) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/14) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/15) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/16) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/17) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/18) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/19) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/20) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/21) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/22) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/23) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/24) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/25) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/26) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/27) [s]
Feb 12 15:20:19 wpa_supplicant[3102]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/28) [s]
Feb 12 15:20:20 wpa_supplicant[3102]: dbus:
fi.w1.wpa_supplicant1.Interface.Scan
(/fi/w1/wpa_supplicant1/Interfaces/1) [a{sv}]
Feb 12 15:20:20 wpa_supplicant[3102]: wlan0: Add radio work 
'scan'@0xaaab186ea760


Output for NM:
Feb 12 15:18:37 NetworkManager[2759]: <info>  [1549984717.8793]
manager: startup complete
Feb 12 15:18:48 NetworkManager[2759]: <warn>  [1549984728.0728]
device (wlan0): re-acquiring supplicant interface (#1).
Feb 12 15:18:48 NetworkManager[2759]: <debug> [1549984728.0731]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:18:48 NetworkManager[2759]: <debug> [1549984728.0733] sup-
iface[0xaaab119f6230,wlan0]: adding interface to supplicant
Feb 12 15:18:48 NetworkManager[2759]: <debug> [1549984728.0737]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:18:48 NetworkManager[2759]: <warn>  [1549984728.0728]
device (wlan0): re-acquiring supplicant interface (#1).
Feb 12 15:18:48 NetworkManager[2759]: <debug> [1549984728.0731]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:18:48 NetworkManager[2759]: <debug> [1549984728.0733] sup-
iface[0xaaab119f6230,wlan0]: adding interface to supplicant
Feb 12 15:18:48 NetworkManager[2759]: <debug> [1549984728.0737]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:19:13 NetworkManager[2759]: <error> [1549984753.1033] sup-
iface[0xaaab119f6230,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:19:13 NetworkManager[2759]: <info>  [1549984753.1036]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:19:13 NetworkManager[2759]: <debug> [1549984753.1038]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:19:13 NetworkManager[2759]: <debug> [1549984753.1039]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:19:13 NetworkManager[2759]: <debug> [1549984753.1040]
device[0xaaab11a9f0b0] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:19:13 NetworkManager[2759]: <debug> [1549984753.1043]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:19:13 NetworkManager[2759]: <error> [1549984753.1033] sup-
iface[0xaaab119f6230,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:19:13 NetworkManager[2759]: <info>  [1549984753.1036]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:19:13 NetworkManager[2759]: <debug> [1549984753.1038]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:19:13 NetworkManager[2759]: <debug> [1549984753.1039]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:19:13 NetworkManager[2759]: <debug> [1549984753.1040]
device[0xaaab11a9f0b0] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:19:13 NetworkManager[2759]: <debug> [1549984753.1043]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:19:23 NetworkManager[2759]: <warn>  [1549984763.0776]
device (wlan0): re-acquiring supplicant interface (#2).
Feb 12 15:19:23 NetworkManager[2759]: <debug> [1549984763.0779]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:19:23 NetworkManager[2759]: <debug> [1549984763.0781] sup-
iface[0xaaab119f62e0,wlan0]: adding interface to supplicant
Feb 12 15:19:23 NetworkManager[2759]: <debug> [1549984763.0785]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:19:23 NetworkManager[2759]: <warn>  [1549984763.0776]
device (wlan0): re-acquiring supplicant interface (#2).
Feb 12 15:19:23 NetworkManager[2759]: <debug> [1549984763.0779]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:19:23 NetworkManager[2759]: <debug> [1549984763.0781] sup-
iface[0xaaab119f62e0,wlan0]: adding interface to supplicant
Feb 12 15:19:23 NetworkManager[2759]: <debug> [1549984763.0785]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:19:48 NetworkManager[2759]: <error> [1549984788.1080] sup-
iface[0xaaab119f62e0,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:19:48 NetworkManager[2759]: <info>  [1549984788.1083]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:19:48 NetworkManager[2759]: <debug> [1549984788.1084]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:19:48 NetworkManager[2759]: <debug> [1549984788.1085]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:19:48 NetworkManager[2759]: <debug> [1549984788.1086]
device[0xaaab11a9f0b0] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:19:48 NetworkManager[2759]: <debug> [1549984788.1090]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:19:48 NetworkManager[2759]: <error> [1549984788.1080] sup-
iface[0xaaab119f62e0,wlan0]: error adding interface: Timeout was
reached
Feb 12 15:19:48 NetworkManager[2759]: <info>  [1549984788.1083]
device (wlan0): supplicant interface state: starting -> down
Feb 12 15:19:48 NetworkManager[2759]: <debug> [1549984788.1084]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:19:48 NetworkManager[2759]: <debug> [1549984788.1085]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:19:48 NetworkManager[2759]: <debug> [1549984788.1086]
device[0xaaab11a9f0b0] (wlan0): wifi-scan: reset interval to 23
seconds
Feb 12 15:19:48 NetworkManager[2759]: <debug> [1549984788.1090]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (0): 'recheck-
available'
Feb 12 15:19:58 NetworkManager[2759]: <warn>  [1549984798.0773]
device (wlan0): re-acquiring supplicant interface (#3).
Feb 12 15:19:58 NetworkManager[2759]: <debug> [1549984798.0775]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:19:58 NetworkManager[2759]: <debug> [1549984798.0777] sup-
iface[0xaaab119f6390,wlan0]: adding interface to supplicant
Feb 12 15:19:58 NetworkManager[2759]: <debug> [1549984798.0781]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:19:58 NetworkManager[2759]: <warn>  [1549984798.0773]
device (wlan0): re-acquiring supplicant interface (#3).
Feb 12 15:19:58 NetworkManager[2759]: <debug> [1549984798.0775]
supplicant: (wlan0): creating new supplicant interface
Feb 12 15:19:58 NetworkManager[2759]: <debug> [1549984798.0777] sup-
iface[0xaaab119f6390,wlan0]: adding interface to supplicant
Feb 12 15:19:58 NetworkManager[2759]: <debug> [1549984798.0781]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (1): 'waiting-for-
supplicant'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8679] sup-
iface[0xaaab119f6390,wlan0]: interface added to supplicant
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8679] sup-
iface[0xaaab119f6390,wlan0]: interface added to supplicant
Feb 12 15:20:16 NetworkManager[2759]: <info>  [1549984816.8792] sup-
iface[0xaaab119f6390,wlan0]: supports 5 scan SSIDs
Feb 12 15:20:16 NetworkManager[2759]: <info>  [1549984816.8792] sup-
iface[0xaaab119f6390,wlan0]: supports 5 scan SSIDs
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8838] sup-
iface[0xaaab119f6390,wlan0]: supplicant supports network credentials
requests
Feb 12 15:20:16 NetworkManager[2759]: <info>  [1549984816.8841]
device (wlan0): supplicant interface state: starting -> ready
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8842]
device[0xaaab11a9f0b0] (wlan0): supplicant ready
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8838] sup-
iface[0xaaab119f6390,wlan0]: supplicant supports network credentials
requests
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8843]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8844]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8846]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (2): 'queued-
state-change-disconnected'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8847]
device[0xaaab11a9f0b0] (wlan0): queue-state[disconnected,
reason:supplicant-available, id:151]: queue state change
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8848]
device[0xaaab11a9f0b0] (wlan0): is available, will transition to
disconnected
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8849]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (1): 'recheck-
available'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8851]
device[0xaaab11a9f0b0] (wlan0): queue-state[disconnected,
reason:supplicant-available, id:151]: change state
Feb 12 15:20:16 NetworkManager[2759]: <info>  [1549984816.8852]
device (wlan0): state change: unavailable -> disconnected (reason
'supplicant-available', sys-iface-state: 'managed')
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8854]
device[0xaaab11a9f0b0] (wlan0): will enable userland IPv6LL
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8855]
platform-linux: link: change 6: user-ipv6ll: set IPv6 address
generation mode to none
Feb 12 15:20:16 NetworkManager[2759]: <info>  [1549984816.8841]
device (wlan0): supplicant interface state: starting -> ready
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8867]
platform-linux: do-request-link: 6
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8872]
platform-linux: do-change-link[6]: success changing link: success
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8875]
platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/disable_ipv6' to '1' (current value is
'0')
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8877]
platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/disable_ipv6' to '0' (current value is
'1')
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8880]
platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/accept_ra_defrtr' to '0' (current
value is identical)
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8882]
platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/accept_ra_pinfo' to '0' (current value
is identical)
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8884]
platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/wlan0/accept_ra_rtr_pref': (2) No such file
or directory
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8885]
platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/use_tempaddr' to '0' (current value is
identical)
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8887]
platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/forwarding' to '0' (current value is
identical)
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8842]
device[0xaaab11a9f0b0] (wlan0): supplicant ready
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8918]
device[0xaaab11a9f0b0] (wlan0): wifi-scan: scanning requested
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8920]
device[0xaaab11a9f0b0] (wlan0): wifi-scan: no SSIDs to probe scan
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8925]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (2): 'wifi-scan'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8926]
device[0xaaab11a9f0b0] (wlan0): wifi-scan: scheduled in 3 seconds
(interval now 23 seconds)
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8927]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (1): 'queued-
state-change-disconnected'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8843]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (2): 'recheck-
available'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8844]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (1): 'waiting-
for-supplicant'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8846]
device[0xaaab11a9f0b0] (wlan0): add_pending_action (2): 'queued-
state-change-disconnected'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8847]
device[0xaaab11a9f0b0] (wlan0): queue-state[disconnected,
reason:supplicant-available, id:151]: queue state change
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8848]
device[0xaaab11a9f0b0] (wlan0): is available, will transition to
disconnected
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8849]
device[0xaaab11a9f0b0] (wlan0): remove_pending_action (1): 'recheck-
available'
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8851]
device[0xaaab11a9f0b0] (wlan0): queue-state[disconnected,
reason:supplicant-available, id:151]: change state
Feb 12 15:20:16 NetworkManager[2759]: <info>  [1549984816.8852]
device (wlan0): state change: unavailable -> disconnected (reason
'supplicant-available', sys-iface-state: 'managed')
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8854]
device[0xaaab11a9f0b0] (wlan0): will enable userland IPv6LL
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8855]
platform-linux: link: change 6: user-ipv6ll: set IPv6 address
generation mode to none
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8867]
platform-linux: do-request-link: 6
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.8872]
platform-linux: do-change-link[6]: success changing link: success
Feb 12 15:20:16 NetworkManager[2759]: <debug> [1549984816.9003]
device[0xaaab11a9f0b0] (wlan0): wifi-scan: scanning-state: scanning


After review these logs, I notice that NM is not able to communicate
with the wpa_supplicant until these messages are printed:
                Feb 12 15:20:16 wpa_supplicant[3102]: ENGINE: Loading
dynamic engine
Feb 12 15:20:16 wpa_supplicant[3102]: ENGINE: Loading dynamic engine

When NM fails the 5 retries are before these messages are printed,
however when NM works fine the retries are doing when the messages
are printed by wpa_supplicant.


Arturo.

From: networkmanager-list <networkmanager-list-bounces gnome org> On
Behalf Of Florin
Sent: Tuesday, February 12, 2019 15:55
Cc: networkmanager-list gnome org
Subject: Re: Timeout error adding wireless interface to supplicant
with NM 1.14.4

What does "journalctl --no-pager -u wpa_supplicant" say?

On Tue, Feb 12, 2019 at 3:10 PM Buzarra, Arturo <
Arturo Buzarra digi com<mailto:Arturo Buzarra digi com>> wrote:

Hi all,

I have an issue with the latest stable NetworkManager version 1.14.4
related with the wireless interface. In the initialization process,
NM turns up the wireless interface (wlan0) and starts the
wpa_supplicant but always fails adding the interface to the
supplicant manager with the same timeout error:

                <error> [1549972898.4209] sup-
iface[0xaaaaf15ab0d0,wlan0]: error adding interface: Timeout was
reached

After this error NM starts a retry system (5 times more) but never
connects with the supplicant to start using the wlan0 interface:

<debug> [1549972871.9456] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/disable_ipv6' to '1' (current value is
'0')
<debug> [1549972871.9458] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/disable_ipv6' to '0' (current value is
'1')
<debug> [1549972871.9459] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/accept_ra_defrtr' to '0' (current
value is '1')
<debug> [1549972872.2899] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/accept_ra_pinfo' to '0' (current value
is '1')
<debug> [1549972872.2901] platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/wlan0/accept_ra_rtr_pref': (2) No such file
or directory
<debug> [1549972872.2903] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/use_tempaddr' to '0' (current value is
identical)
<debug> [1549972872.2905] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/forwarding' to '0' (current value is
identical)
<debug> [1549972872.2907] device[0xaaaaf163c990] (wlan0): bringing up
device 6
<debug> [1549972872.2908] platform: link: setting up "wlan0" (6)
<debug> [1549972872.2909] platform-linux: link: change 6: flags: set
0x1/0x1 ([up] / [up])
<debug> [1549972872.2912] platform-linux: do-request-link: 6
<debug> [1549972872.2915] platform: signal: link changed: 6: wlan0
<UP;broadcast,multicast,up> mtu 1500 arp 1 wifi? init addrgenmode
none addr 00:04:8D:01:32:02 driver hif_pci rx:0,0 tx:0,0
<debug> [1549972872.2918] platform-linux: do-change-link[6]: success
changing link: success
<debug> [1549972872.2919] device[0xaaaaf163c990] (wlan0): preparing
device
<debug> [1549972872.2920] device[0xaaaaf163c990] (wlan0): clearing
queued IP4 config change
<debug> [1549972872.2921] device[0xaaaaf163c990] (wlan0): clearing
queued IP6 config change
<debug> [1549972872.2929] device[0xaaaaf163c990] (wlan0): ip4-config: 
update (commit=1, new-config=(nil))
<debug> [1549972872.2930] device[0xaaaaf163c990] (wlan0): ip4-config: 
clear IP Config instance
(/org/freedesktop/NetworkManager/IP4Config/1)
<debug> [1549972872.2948] device[0xaaaaf163c990] (wlan0): ip6-config: 
update (commit=1, new-config=(nil))
<debug> [1549972872.2949] device[0xaaaaf163c990] (wlan0): ip6-config: 
clear IP Config instance
(/org/freedesktop/NetworkManager/IP6Config/1)
        <debug> [1549972872.2982] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549972872.2988] device[0xaaaaf163c990] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<debug> [1549972872.2990] device[0xaaaaf163c990] (wlan0): device not
yet available for transition to DISCONNECTED
<debug> [1549972872.3020] device[0xaaaaf163c990] (wlan0):
connectivity state changed from UNKNOWN to NONE
<debug> [1549972872.3022] manager: connectivity checking indicates
NONE
<debug> [1549972872.3028] dispatcher: (2) dispatching action
'connectivity-change'
        […]
<debug> [1549972873.3918] firewall: firewall initialized (not
running)
<debug> [1549972873.3928] manager: (lo): assume: don't assume because
not managed
<debug> [1549972873.3931] manager: (can0): assume: don't assume
because not managed
<debug> [1549972873.3933] manager: (can1): assume: don't assume
because not managed
<debug> [1549972873.3934] manager: (eth0): assume: don't assume
because not managed
<debug> [1549972873.3935] manager: (eth1): assume: don't assume
because not managed
<debug> [1549972873.3937] manager: check_if_startup_complete returns
FALSE because of wlan0
<info>  [1549972873.3949] bluez: use BlueZ version 5
<info>  [1549972873.3977] supplicant: wpa_supplicant running
<debug> [1549972873.3980] supplicant: AP mode is supported
<debug> [1549972873.3981] supplicant: PMF is not supported
<debug> [1549972873.3982] supplicant: FILS is not supported
<debug> [1549972873.3984] supplicant: EAP-FAST is supported
<debug> [1549972873.3985] sup-iface[0xaaaaf15ab0d0,wlan0]: adding
interface to supplicant
<info>  [1549972873.3987] device (wlan0): supplicant interface state:
init -> starting
<info>  [1549972873.4041] bluez5: NAP: added interface
00:04:8D:01:32:03
ModemManager[2237]: <info>  ModemManager (version 1.8.2) starting in
system bus...

<info>  [1549972873.5724] modem-manager: ModemManager not available
<info>  [1549972873.6141] modem-manager: ModemManager now available
        <error> [1549972898.4209] sup-iface[0xaaaaf15ab0d0,wlan0]:
error adding interface: Timeout was reached
<info>  [1549972898.4212] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549972898.4214] device[0xaaaaf163c990] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549972898.4215] device[0xaaaaf163c990] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549972898.4216] device[0xaaaaf163c990] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549972898.4219] device[0xaaaaf163c990] (wlan0):
remove_pending_action (0): 'recheck-available'
<info>  [1549972898.4221] manager: startup complete
<warn>  [1549972908.4011] device (wlan0): re-acquiring supplicant
interface (#1).
<debug> [1549972908.4013] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549972908.4015] sup-iface[0xaaaaf15ab2e0,wlan0]: adding
interface to supplicant
<debug> [1549972908.4019] device[0xaaaaf163c990] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<error> [1549972933.4303] sup-iface[0xaaaaf15ab2e0,wlan0]: error
adding interface: Timeout was reached
<info>  [1549972933.4306] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549972933.4308] device[0xaaaaf163c990] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549972933.4309] device[0xaaaaf163c990] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549972933.4310] device[0xaaaaf163c990] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549972933.4313] device[0xaaaaf163c990] (wlan0):
remove_pending_action (0): 'recheck-available'
<warn>  [1549972943.4005] device (wlan0): re-acquiring supplicant
interface (#2).
<debug> [1549972943.4007] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549972943.4009] sup-iface[0xaaaaf15ab390,wlan0]: adding
interface to supplicant
<debug> [1549972943.4012] device[0xaaaaf163c990] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<error> [1549972968.4296] sup-iface[0xaaaaf15ab390,wlan0]: error
adding interface: Timeout was reached
<info>  [1549972968.4299] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549972968.4301] device[0xaaaaf163c990] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549972968.4302] device[0xaaaaf163c990] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549972968.4303] device[0xaaaaf163c990] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549972968.4307] device[0xaaaaf163c990] (wlan0):
remove_pending_action (0): 'recheck-available'
<warn>  [1549972978.4009] device (wlan0): re-acquiring supplicant
interface (#3).
<debug> [1549972978.4012] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549972978.4014] sup-iface[0xaaaaf15ab440,wlan0]: adding
interface to supplicant
<debug> [1549972978.4021] device[0xaaaaf163c990] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<error> [1549973003.4305] sup-iface[0xaaaaf15ab440,wlan0]: error
adding interface: Timeout was reached
<info>  [1549973003.4308] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549973003.4310] device[0xaaaaf163c990] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549973003.4311] device[0xaaaaf163c990] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549973003.4312] device[0xaaaaf163c990] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549973003.4315] device[0xaaaaf163c990] (wlan0):
remove_pending_action (0): 'recheck-available'
<warn>  [1549973013.3950] device (wlan0): re-acquiring supplicant
interface (#4).
<debug> [1549973013.3952] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549973013.3954] sup-iface[0xaaaaf15ab4f0,wlan0]: adding
interface to supplicant
<debug> [1549973013.3958] device[0xaaaaf163c990] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<error> [1549973038.4242] sup-iface[0xaaaaf15ab4f0,wlan0]: error
adding interface: Timeout was reached
<info>  [1549973038.4245] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549973038.4247] device[0xaaaaf163c990] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549973038.4248] device[0xaaaaf163c990] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549973038.4249] device[0xaaaaf163c990] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549973038.4252] device[0xaaaaf163c990] (wlan0):
remove_pending_action (0): 'recheck-available'
<warn>  [1549973048.4004] device (wlan0): re-acquiring supplicant
interface (#5).
<debug> [1549973048.4006] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549973048.4008] sup-iface[0xaaaaf15ab5a0,wlan0]: adding
interface to supplicant
<debug> [1549973048.4012] device[0xaaaaf163c990] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<error> [1549973073.4296] sup-iface[0xaaaaf15ab5a0,wlan0]: error
adding interface: Timeout was reached
<info>  [1549973073.4300] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549973073.4301] device[0xaaaaf163c990] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549973073.4302] device[0xaaaaf163c990] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549973073.4304] device[0xaaaaf163c990] (wlan0): wifi-scan:
reset interval to 23 seconds
<info>  [1549973073.4305] device (wlan0): supplicant interface keeps
failing, giving up
<debug> [1549973073.4308] device[0xaaaaf163c990] (wlan0):
remove_pending_action (0): 'recheck-available'

After NM starts there is a wpa_supplicant instance running:

# ps | grep wpa
2236 root      7280 S    /usr/sbin/wpa_supplicant -u -O
/var/run/wpa_supplicant
2243 root      3296 S    grep wpa
#

The wireless interface is working fine because I can perform a scan
with the iw tool:

# iw dev wlan0 scan


Notice that the wpa-supplicant version used is 2.6 and until now it
was working fine with the NetworkManager version 1.8.2
Finally, only a few times after several retries the NetworkManager is
able to add the wlan0 interface and then all start working fine, but
the rate is less than the 5%.
This is a trace when NM is able to add the wireless interface to the
supplicant:

<error> [1549914689.2504] sup-iface[0xaaaaef5df0d0,wlan0]: error
adding interface: Timeout was reached
<info>  [1549914689.2507] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549914689.2509] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549914689.2510] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549914689.2511] device[0xaaaaef673890] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549914689.2515] device[0xaaaaef673890] (wlan0):
remove_pending_action (0): 'recheck-available'
<info>  [1549914689.2517] manager: startup complete
<warn>  [1549914699.3738] device (wlan0): re-acquiring supplicant
interface (#1).
<debug> [1549914699.3741] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549914699.3743] sup-iface[0xaaaaef5df2e0,wlan0]: adding
interface to supplicant
<debug> [1549914699.3746] device[0xaaaaef673890] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<error> [1549964339.4772] sup-iface[0xaaaaef5df2e0,wlan0]: error
adding interface: Timeout was reached
<info>  [1549964339.4776] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549964339.4778] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549964339.4779] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549964339.4780] device[0xaaaaef673890] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549964339.4783] device[0xaaaaef673890] (wlan0):
remove_pending_action (0): 'recheck-available'
<warn>  [1549964349.4476] device (wlan0): re-acquiring supplicant
interface (#2).
<debug> [1549964349.4478] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549964349.4480] sup-iface[0xaaaaef5df390,wlan0]: adding
interface to supplicant
<debug> [1549964349.4484] device[0xaaaaef673890] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<error> [1549964374.4769] sup-iface[0xaaaaef5df390,wlan0]: error
adding interface: Timeout was reached
<info>  [1549964374.4772] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549964374.4774] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549964374.4775] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549964374.4776] device[0xaaaaef673890] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549964374.4780] device[0xaaaaef673890] (wlan0):
remove_pending_action (0): 'recheck-available'
<warn>  [1549964384.4482] device (wlan0): re-acquiring supplicant
interface (#3).
<debug> [1549964384.4485] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549964384.4486] sup-iface[0xaaaaef5df440,wlan0]: adding
interface to supplicant
<debug> [1549964384.4494] device[0xaaaaef673890] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<error> [1549964409.4779] sup-iface[0xaaaaef5df440,wlan0]: error
adding interface: Timeout was reached
<info>  [1549964409.4783] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549964409.4784] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549964409.4785] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549964409.4786] device[0xaaaaef673890] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549964409.4790] device[0xaaaaef673890] (wlan0):
remove_pending_action (0): 'recheck-available'
<warn>  [1549964419.4482] device (wlan0): re-acquiring supplicant
interface (#4).
<debug> [1549964419.4485] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549964419.4487] sup-iface[0xaaaaef5df4f0,wlan0]: adding
interface to supplicant
<debug> [1549964419.4491] device[0xaaaaef673890] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<error> [1549964444.4775] sup-iface[0xaaaaef5df4f0,wlan0]: error
adding interface: Timeout was reached
<info>  [1549964444.4779] device (wlan0): supplicant interface state:
starting -> down
<debug> [1549964444.4780] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549964444.4781] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549964444.4782] device[0xaaaaef673890] (wlan0): wifi-scan:
reset interval to 23 seconds
<debug> [1549964444.4786] device[0xaaaaef673890] (wlan0):
remove_pending_action (0): 'recheck-available'
<warn>  [1549964454.4478] device (wlan0): re-acquiring supplicant
interface (#5).
<debug> [1549964454.4480] supplicant: (wlan0): creating new
supplicant interface
<debug> [1549964454.4482] sup-iface[0xaaaaef5df5a0,wlan0]: adding
interface to supplicant
<debug> [1549964454.4486] device[0xaaaaef673890] (wlan0):
add_pending_action (1): 'waiting-for-supplicant'
<debug> [1549964474.4126] sup-iface[0xaaaaef5df5a0,wlan0]: interface
added to supplicant
<info>  [1549964474.4217] sup-iface[0xaaaaef5df5a0,wlan0]: supports 5
scan SSIDs
<debug> [1549964474.4248] sup-iface[0xaaaaef5df5a0,wlan0]: supplicant
supports network credentials requests
<info>  [1549964474.4251] device (wlan0): supplicant interface state:
starting -> ready
<debug> [1549964474.4252] device[0xaaaaef673890] (wlan0): supplicant
ready
<debug> [1549964474.4253] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'recheck-available'
<debug> [1549964474.4255] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'waiting-for-supplicant'
<debug> [1549964474.4257] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'queued-state-change-disconnected'
<debug> [1549964474.4258] device[0xaaaaef673890] (wlan0): queue-
state[disconnected, reason:supplicant-available, id:229]: queue state
change
<debug> [1549964474.4259] device[0xaaaaef673890] (wlan0): is
available, will transition to disconnected
<debug> [1549964474.4260] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'recheck-available'
<debug> [1549964474.4262] device[0xaaaaef673890] (wlan0): queue-
state[disconnected, reason:supplicant-available, id:229]: change
state
<info>  [1549964474.4263] device (wlan0): state change: unavailable
-> disconnected (reason 'supplicant-available', sys-iface-state:
'managed')
<debug> [1549964474.4265] device[0xaaaaef673890] (wlan0): will enable
userland IPv6LL
<debug> [1549964474.4266] platform-linux: link: change 6: user-
ipv6ll: set IPv6 address generation mode to none
<debug> [1549964474.4268] platform-linux: do-request-link: 6
<debug> [1549964474.4272] platform-linux: do-change-link[6]: success
changing link: success
<debug> [1549964474.4275] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/disable_ipv6' to '1' (current value is
'0')
<debug> [1549964474.4277] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/disable_ipv6' to '0' (current value is
'1')
<debug> [1549964474.4279] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/accept_ra_defrtr' to '0' (current
value is identical)
<debug> [1549964474.4281] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/accept_ra_pinfo' to '0' (current value
is identical)
<debug> [1549964474.4283] platform-linux: sysctl: failed to open
'/proc/sys/net/ipv6/conf/wlan0/accept_ra_rtr_pref': (2) No such file
or directory
<debug> [1549964474.4285] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/use_tempaddr' to '0' (current value is
identical)
<debug> [1549964474.4287] platform-linux: sysctl: setting
'/proc/sys/net/ipv6/conf/wlan0/forwarding' to '0' (current value is
identical)
<debug> [1549964474.4313] device[0xaaaaef673890] (wlan0): wifi-scan:
scanning requested
<debug> [1549964474.4315] device[0xaaaaef673890] (wlan0): wifi-scan:
no SSIDs to probe scan
<debug> [1549964474.4327] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'wifi-scan'
<debug> [1549964474.4329] device[0xaaaaef673890] (wlan0): wifi-scan:
scheduled in 3 seconds (interval now 23 seconds)
<debug> [1549964474.4330] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'queued-state-change-disconnected'
<debug> [1549964474.4398] device[0xaaaaef673890] (wlan0): wifi-scan:
scanning-state: scanning
<debug> [1549964477.9353] device[0xaaaaef673890] (wlan0): wifi-scan:
scanning-state: idle
<debug> [1549964477.9523] device[0xaaaaef673890] (wlan0): failed to
match hidden AP 6C:99:89:76:43:9F
<debug> [1549964477.9689] device[0xaaaaef673890] (wlan0): failed to
match hidden AP 6C:99:89:76:43:9E
<debug> [1549964477.9856] device[0xaaaaef673890] (wlan0): failed to
match hidden AP 6C:99:89:76:43:91
<debug> [1549964477.9884] device[0xaaaaef673890] (wlan0): failed to
match hidden AP 6C:99:89:76:43:90
<debug> [1549964477.9937] device[0xaaaaef673890] (wlan0): failed to
match hidden AP E0:0E:DA:38:C1:CF
<debug> [1549964478.0017] device[0xaaaaef673890] (wlan0): failed to
match hidden AP E0:0E:DA:38:C1:C0
<debug> [1549964478.0070] device[0xaaaaef673890] (wlan0): failed to
match hidden AP E0:0E:DA:38:C1:C1
<debug> [1549964478.0279] device[0xaaaaef673890] (wlan0): failed to
match hidden AP 6C:99:89:76:43:9C
<debug> [1549964478.0309] device[0xaaaaef673890] (wlan0): failed to
match hidden AP 6C:99:89:76:43:93
<debug> [1549964478.0339] device[0xaaaaef673890] (wlan0): failed to
match hidden AP E0:0E:DA:38:C1:CC
<debug> [1549964478.0368] device[0xaaaaef673890] (wlan0): failed to
match hidden AP E0:0E:DA:38:C1:C3
<debug> [1549964478.0640] device[0xaaaaef673890] (wlan0): wifi-scan:
scan-done callback: successful
<debug> [1549964478.0647] device[0xaaaaef673890] (wlan0): wifi-scan:
scheduled in 23 seconds (interval now 33 seconds)
<debug> [1549964478.0649] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'autoactivate'
<debug> [1549964478.0650] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'wifi-scan'
<debug> [1549964478.0654] device[0xaaaaef673890] (wlan0):
remove_pending_action (0): 'autoactivate'
<debug> [1549964501.4611] device[0xaaaaef673890] (wlan0): wifi-scan:
scanning requested
<debug> [1549964501.4615] device[0xaaaaef673890] (wlan0): wifi-scan:
no SSIDs to probe scan
<debug> [1549964501.4621] device[0xaaaaef673890] (wlan0):
add_pending_action (1): 'wifi-scan'
<debug> [1549964501.4623] device[0xaaaaef673890] (wlan0): wifi-scan:
scheduled in 33 seconds (interval now 43 seconds)
<debug> [1549964501.4703] device[0xaaaaef673890] (wlan0): wifi-scan:
scanning-state: scanning
<debug> [1549964504.9232] device[0xaaaaef673890] (wlan0): wifi-scan:
scanning-state: idle
<debug> [1549964504.9425] device[0xaaaaef673890] (wlan0): failed to
match hidden AP 4C:1B:86:00:6D:B3
<debug> [1549964504.9860] device[0xaaaaef673890] (wlan0): wifi-scan:
scan-done callback: successful
<debug> [1549964504.9866] device[0xaaaaef673890] (wlan0):
add_pending_action (2): 'autoactivate'
<debug> [1549964504.9868] device[0xaaaaef673890] (wlan0):
remove_pending_action (1): 'wifi-scan'
<debug> [1549964504.9873] device[0xaaaaef673890] (wlan0):
remove_pending_action (0): 'autoactivate'


Does anyone have any clue to find the problem here?

Thanks in advance.

Arturo.



_______________________________________________
networkmanager-list mailing list
networkmanager-list gnome org<mailto:networkmanager-list gnome org>
https://mail.gnome.org/mailman/listinfo/networkmanager-list
_______________________________________________
networkmanager-list mailing list
networkmanager-list gnome org
https://mail.gnome.org/mailman/listinfo/networkmanager-list

Follow-Ups:
- RE: Timeout error adding wireless interface to supplicant with NM 1.14.4
  - From: Buzarra, Arturo

References:
- Timeout error adding wireless interface to supplicant with NM 1.14.4
  - From: Buzarra, Arturo
- Re: Timeout error adding wireless interface to supplicant with NM 1.14.4
  - From: Florin
- RE: Timeout error adding wireless interface to supplicant with NM 1.14.4
  - From: Buzarra, Arturo

[Date Prev][Date Next] [Thread Prev][Thread Next] [Thread Index] [Date Index] [Author Index]