initialization of wpa_supplicant is very long

Dan Williams dcbw at redhat.com
Tue Jun 4 08:03:03 PDT 2019


On Mon, 2019-06-03 at 10:19 +0200, Arthur LAMBERT wrote:
> Hi,
> 
> I have an issue with wpa_supplicant. Just after booting my device, I
> run
> wpa_supplicant, it took between 30 seconds and 90 seconds to
> initialize. It is normal ? Is there an issue in my
> setup/configuration ?
> I am using wpa_supplicant 2.7 version on embedded device handle with
> buildroot.

"random: nonblocking pool is initialized"

Looks like on bootup your system does not have enough randomness
entropy which then blocks the supplicant (and anything else needing
entropy). You can add programs like rng-tools that grab more entropy
and feed it to the kernel.

See https://wiki.archlinux.org/index.php/Rng-tools for some examples.

Dan

> I can call wpa_cli -i wlan0 terminate to kill wpa_supplicant. Then if
> I tried to initialize wpa_supplicant again, its only 2 or 3 seconds
> to initialize. In fact the initializatiion process is not long the
> first
> time, its seems that the process is very long only just after boot.
> If I boot my device, then I wait 60 seconds, then I can run
> wpa_supplicant
> and the work is done very quickly !
> 
> My wpa configuration file :
> 
> # cat /data/conf/wpa_supplicant.conf
> ctrl_interface=/var/run/wpa_supplicant
> update_config=1
> 
> logs :
> 
> # time wpa_supplicant  -B -c /data/conf/wpa_supplicant.conf -dd -i
> wlan0 -t
> 1559548613.929934: wpa_supplicant v2.7
> 1559548613.933464: random: Trying to read entropy from /dev/random
> 1559548613.933819: Successfully initialized wpa_supplicant
> 1559548613.934203: Initializing interface 'wlan0' conf
> '/data/conf/wpa_supplicant.conf' driver 'default' ctrl_interface
> 'N/A' bridge 'N/A'
> 1559548613.934691: Configuration file
> '/data/conf/wpa_supplicant.conf' -> '/data/conf/wpa_supplicant.conf'
> 1559548613.934924: Reading configuration file
> '/data/conf/wpa_supplicant.conf'
> 1559548613.936368: ctrl_interface='/var/run/wpa_supplicant'
> 1559548613.936706: update_config=1
> 1559548613.937093: Line: 4 - start of a new network block
> 1559548613.937441: ssid - hexdump_ascii(len=13):
>      44 52 45 45 4d 2d 42 41 43 4b 2d 55 50            XXXXXXX
> 1559548613.938472: PSK (ASCII passphrase) - hexdump_ascii(len=9):
> [REMOVED]
> 1559548614.040959: PSK (from passphrase) - hexdump(len=32): [REMOVED]
> 1559548614.041154: Line: 9 - start of a new network block
> 1559548614.041254: ssid - hexdump_ascii(len=10):
>      44 72 65 65 6d 5f 54 65 61 6d                     XXXXXXX
> 1559548614.041630: PSK (ASCII passphrase) - hexdump_ascii(len=17):
> [REMOVED]
> 1559548614.114452: PSK (from passphrase) - hexdump(len=32): [REMOVED]
> 1559548614.114641: Priority group 0
> 1559548614.114716:    id=0 ssid='XXXXX'
> 1559548614.114796:    id=1 ssid='XXXXX'
> 1559548614.128129: nl80211: Using driver-based roaming
> 1559548614.128267: nl80211: Supported cipher 00-0f-ac:1
> 1559548614.128430: nl80211: Supported cipher 00-0f-ac:5
> 1559548614.128542: nl80211: Supported cipher 00-0f-ac:2
> 1559548614.128651: nl80211: Supported cipher 00-0f-ac:4
> 1559548614.129181: nl80211: Using driver-based off-channel TX
> 1559548614.129327: nl80211: Supported vendor command:
> vendor_id=0x1018 subcmd=1
> 1559548614.129488: nl80211: Use separate P2P group interface (driver
> advertised support)
> 1559548614.129557: nl80211: use P2P_DEVICE support
> 1559548614.129613: nl80211: interface wlan0 in phy phy0
> 1559548614.131540: nl80211: Set mode ifindex 4 iftype 2 (STATION)
> 1559548614.132108: nl80211: Subscribe to mgmt frames with non-AP
> handle 0x832020
> 1559548614.132253: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=0104
> 1559548614.132538: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=040a
> 1559548614.132789: nl80211: RegistIPv6: ADDRCONF(NETDEV_UP): wlan0:
> link is not ready
> er frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x832020
> match=040b
> 1559548614.133026: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=040c
> 1559548614.133248: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=040d
> 1559548614.133464: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=090a
> 1559548614.133684: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=090b
> 1559548614.133904: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=090c
> 1559548614.134180: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=090d
> 1559548614.134416: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=0409506f9a09
> 1559548614.134647: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=7f506f9a09
> 1559548614.134861: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=06
> 1559548614.135077: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=0a07
> 1559548614.135291: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=0a11
> 1559548614.135509: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=0a1a
> 1559548614.135727: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=1101
> 1559548614.135942: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=1102
> 1559548614.136159: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=0505
> 1559548614.136378: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x832020 match=0500
> 1559548614.137522: rfkill: Cannot open RFKILL control device
> 1559548614.137626: nl80211: RFKILL status not available
> 1559548614.230560: netlink: Operstate: ifindex=4 linkmode=1
> (userspace-control), operstate=5 (IF_OPER_DORMANT)
> 1559548614.232515: Add interface wlan0 to a new radio phy0
> 1559548614.234236: nl80211: Regulatory information - country=00
> 1559548614.234357: nl80211: 2402-2472 @ 40 MHz 20 mBm
> 1559548614.234503: nl80211: 2457-2482 @ 20 MHz 20 mBm (no IR)
> 1559548614.234640: nl80211: 2474-2494 @ 20 MHz 20 mBm (no OFDM) (no
> IR)
> 1559548614.234783: nl80211: 5170-5250 @ 80 MHz 20 mBm (no IR)
> 1559548614.234920: nl80211: 5250-5330 @ 80 MHz 20 mBm (DFS) (no IR)
> 1559548614.235064: nl80211: 5490-5730 @ 160 MHz 20 mBm (DFS) (no IR)
> 1559548614.235207: nl80211: 5735-5835 @ 80 MHz 20 mBm (no IR)
> 1559548614.235343: nl80211: 57240-63720 @ 2160 MHz 0 mBm
> 1559548614.235588: nl80211: Added 802.11b mode based on 802.11g
> information
> 1559548614.257134: wlan0: Own MAC address: 8c:45:00:5c:09:d3
> 1559548614.257434: wpa_driver_nl80211_set_key: ifindex=4 (wlan0)
> alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0
> 1559548614.257961: wpa_driver_nl80211_set_key: ifindex=4 (wlan0)
> alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0 key_len=0
> 1559548614.258406: wpa_driver_nl80211_set_key: ifindex=4 (wlan0)
> alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0 key_len=0
> 1559548614.258762: wpa_driver_nl80211_set_key: ifindex=4 (wlan0)
> alg=0 addr=(nil) key_idx=3 set_tx=0 seq_len=0 key_len=0
> 1559548614.259067: wlan0: RSN: flushing PMKID list in the driver
> 1559548614.259149: nl80211: Flush PMKIDs
> 1559548614.263694: wlan0: WPS: UUID based on MAC address: 0e36585e-
> 44e7-545d-866f-4a351076558f
> 
> (...)
> Very long delay here
> (...)
> 
> random: nonblocking pool is initialized
> 1559548683.469670: EAPOL: SUPP_PAE entering state DISCONNECTED
> 1559548683.469949: EAPOL: Supplicant port status: Unauthorized
> 1559548683.470122: nl80211: Skip set_supp_port(unauthorized) while
> not associated
> 1559548683.470260: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
> 1559548683.470396: EAPOL: SUPP_BE entering state INITIALIZE
> 1559548683.470535: EAP: EAP entering state DISABLED
> 1559548683.471473: wlan0: Added interface wlan0
> 1559548683.471813: wlan0: State: DISCONNECTED -> DISCONNECTED
> 1559548683.472005: nl80211: Set wlan0 operstate 0->0 (DORMANT)
> 1559548683.472295: netlink: Operstate: ifindex=4 linkmode=-1 (no
> change), operstate=5 (IF_OPER_DORMANT)
> 1559548683.472887: nl80211: Create interface iftype 10 (P2P_DEVICE)
> 1559548683.487103: nl80211: New P2P Device interface p2p-dev-wlan0
> (0x2) created
> 1559548683.487496: Initializing interface 'p2p-dev-wlan0' conf
> '/data/conf/wpa_supplicant.conf' driver 'nl80211' ctrl_interface
> '/var/run/wpa_supplicant' bridge 'N/A'
> 1559548683.487857: Configuration file
> '/data/conf/wpa_supplicant.conf' -> '/data/conf/wpa_supplicant.conf'
> 1559548683.488089: Reading configuration file
> '/data/conf/wpa_supplicant.conf'
> 1559548683.488520: ctrl_interface='/var/run/wpa_supplicant'
> 1559548683.488786: update_config=1
> 1559548683.488977: Line: 4 - start of a new network block
> 1559548683.489178: ssid - hexdump_ascii(len=13):
>      44 52 45 45 4d 2d 42 41 43 4b 2d 55 50            DREEM-BACK-
> UP   
> 1559548683.490242: PSK (ASCII passphrase) - hexdump_ascii(len=9):
> [REMOVED]
> 1559548683.573446: PSK (from passphrase) - hexdump(len=32): [REMOVED]
> 1559548683.573601: Line: 9 - start of a new network block
> 1559548683.573698: ssid - hexdump_ascii(len=10):
>      44 72 65 65 6d 5f 54 65 61
> 6d                     Dreem_Team      
> 1559548683.574068: PSK (ASCII passphrase) - hexdump_ascii(len=17):
> [REMOVED]
> 1559548683.647239: PSK (from passphrase) - hexdump(len=32): [REMOVED]
> 1559548683.647414: Priority group 0
> 1559548683.647485:    id=0 ssid='DREEM-BACK-UP'
> 1559548683.647568:    id=1 ssid='Dreem_Team'
> 1559548683.720112: nl80211: Using driver-based roaming
> 1559548683.720283: nl80211: Supported cipher 00-0f-ac:1
> 1559548683.720405: nl80211: Supported cipher 00-0f-ac:5
> 1559548683.720518: nl80211: Supported cipher 00-0f-ac:2
> 1559548683.720625: nl80211: Supported cipher 00-0f-ac:4
> 1559548683.721162: nl80211: Using driver-based off-channel TX
> 1559548683.721300: nl80211: Supported vendor command:
> vendor_id=0x1018 subcmd=1
> 1559548683.721460: nl80211: Use separate P2P group interface (driver
> advertised support)
> 1559548683.721532: nl80211: use P2P_DEVICE support
> 1559548683.721586: nl80211: interface p2p-dev-wlan0 in phy phy0
> 1559548683.723166: nl80211: Set mode ifindex 0 iftype 10 (P2P_DEVICE)
> 1559548683.723467: nl80211: Failed to set interface 0 to mode 10: -22
> (Invalid argument)
> 1559548683.724396: nl80211: Subscribe to mgmt frames with non-AP
> handle 0x84d258
> 1559548683.724525: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=0104
> 1559548683.724796: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=040a
> 1559548683.725041: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=040b
> 1559548683.725270: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=040c
> 1559548683.725491: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=040d
> 1559548683.725713: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=090a
> 1559548683.725928: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=090b
> 1559548683.726144: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=090c
> 1559548683.726357: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=090d
> 1559548683.726627: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=0409506f9a09
> 1559548683.727060: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=7f506f9a09
> 1559548683.727315: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=06
> 1559548683.727546: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=0a07
> 1559548683.727769: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=0a11
> 1559548683.727993: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=0a1a
> 1559548683.728210: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=1101
> 1559548683.728425: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=1102
> 1559548683.728645: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=0505
> 1559548683.728870: nl80211: Register frame type=0xd0
> (WLAN_FC_STYPE_ACTION) nl_handle=0x84d258 match=0500
> 1559548683.729978: rfkill: Cannot get wiphy information
> 1559548683.730072: nl80211: RFKILL status not available
> 1559548683.732725: nl80211: Start P2P Device p2p-dev-wlan0 (0x2):
> Success
> 1559548683.734386: Add interface p2p-dev-wlan0 to existing radio phy0
> 1559548683.736012: nl80211: Regulatory information - country=00
> 1559548683.736126: nl80211: 2402-2472 @ 40 MHz 20 mBm
> 1559548683.736272: nl80211: 2457-2482 @ 20 MHz 20 mBm (no IR)
> 1559548683.736413: nl80211: 2474-2494 @ 20 MHz 20 mBm (no OFDM) (no
> IR)
> 1559548683.736554: nl80211: 5170-5250 @ 80 MHz 20 mBm (no IR)
> 1559548683.736691: nl80211: 5250-5330 @ 80 MHz 20 mBm (DFS) (no IR)
> 1559548683.737129: nl80211: 5490-5730 @ 160 MHz 20 mBm (DFS) (no IR)
> 1559548683.737292: nl80211: 5735-5835 @ 80 MHz 20 mBm (no IR)
> 1559548683.737432: nl80211: 57240-63720 @ 2160 MHz 0 mBm
> 1559548683.737740: nl80211: Added 802.11b mode based on 802.11g
> information
> 1559548683.737874: p2p-dev-wlan0: Own MAC address: xx:xx:xx:xx:xx:xx
> 1559548683.737963: p2p-dev-wlan0: RSN: flushing PMKID list in the
> driver
> 1559548683.738033: nl80211: Flush PMKIDs
> 1559548683.738245: p2p-dev-wlan0: State: DISCONNECTED -> INACTIVE
> 1559548683.738421: p2p-dev-wlan0: WPS: UUID from the first interface:
> 0e36585e-44e7-545d-866f-4a351076558f
> 1559548683.741240: EAPOL: SUPP_PAE entering state DISCONNECTED
> 1559548683.741346: EAPOL: Supplicant port status: Unauthorized
> 1559548683.741417: nl80211: Skip set_supp_port(unauthorized) while
> not associated
> 1559548684.073928: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
> 1559548684.074115: EAPOL: SUPP_BE entering state INITIALIZE
> 1559548684.074272: EAP: EAP entering state DISABLED
> 1559548684.074653: Using existing control interface directory.
> 1559548684.075236: P2P: Add operating class 81
> 1559548684.075460: P2P: Channels - hexdump(len=13): 01 02 03 04 05 06
> 07 08 09 0a 0b 0c 0d
> 1559548684.076333: P2P: Add operating class 115
> 1559548684.076501: P2P: Channels - hexdump(len=4): 24 28 2c 30
> 1559548684.077099: P2P: Add operating class 116
> 1559548684.077273: P2P: Channels - hexdump(len=2): 24 2c
> 1559548684.077554: P2P: Add operating class 117
> 1559548684.077719: P2P: Channels - hexdump(len=2): 28 30
> 1559548684.077998: P2P: Add operating class 124
> 1559548684.078170: P2P: Channels - hexdump(len=4): 95 99 9d a1
> 1559548684.078525: P2P: Add operating class 125
> 1559548684.078699: P2P: Channels - hexdump(len=5): 95 99 9d a1 a5
> 1559548684.079095: P2P: Add operating class 126
> 1559548684.079262: P2P: Channels - hexdump(len=2): 95 9d
> 1559548684.079593: P2P: Add operating class 127
> 1559548684.079761: P2P: Channels - hexdump(len=2): 99 a1
> 1559548684.080120: P2P: Add operating class 130
> 1559548684.080332: P2P: Channels - hexdump(len=20): 24 28 2c 30 34 38
> 3c 40 64 68 6c 70 74 78 7c 80 84 88 8c 90
> 1559548684.086137: P2P: Own listen channel: 81:6
> 1559548684.086574: P2P: Random operating channel: 81:1
> 1559548684.087581: P2P: initialized
> 1559548684.088802: P2P: channels: 81:1,2,3,4,5,6,7,8,9,10,11,12,13
> 115:36,40,44,48 116:36,44 117:40,48 124:149,153,157,161
> 125:149,153,157,161,165 126:149,157 127:153,161
> 130:36,40,44,48,52,56,60,64,100,10
> 4,108,112,116,120,124,128,132,136,140,144
> 1559548684.089060: P2P: cli_channels:
> 1559548684.089308: p2p-dev-wlan0: Added interface p2p-dev-wlan0
> 1559548684.089624: p2p-dev-wlan0: State: INACTIVE -> DISCONNECTED
> 1559548684.089832: nl80211: Set p2p-dev-wlan0 operstate 0->0
> (DORMANT)
> 1559548684.090128: netlink: Operstate: ifindex=0 linkmode=-1 (no
> change), operstate=5 (IF_OPER_DORMANT)
> 1559548684.090645: p2p-dev-wlan0: Determining shared radio
> frequencies (max len 1)
> 1559548684.090929: p2p-dev-wlan0: Shared frequencies (len=0):
> completed iteration
> 1559548684.091131: P2P: Add operating class 81
> 1559548684.091315: P2P: Channels - hexdump(len=13): 01 02 03 04 05 06
> 07 08 09 0a 0b 0c 0d
> 1559548684.092172: P2P: Add operating class 115
> 1559548684.092384: P2P: Channels - hexdump(len=4): 24 28 2c 30
> 1559548684.092747: P2P: Add operating class 116
> 1559548684.092912: P2P: Channels - hexdump(len=2): 24 2c
> 1559548684.093189: P2P: Add operating class 117
> 1559548684.093354: P2P: Channels - hexdump(len=2): 28 30
> 1559548684.093634: P2P: Add operating class 124
> 1559548684.093803: P2P: Channels - hexdump(len=4): 95 99 9d a1
> 1559548684.094157: P2P: Add operating class 125
> 1559548684.094327: P2P: Channels - hexdump(len=5): 95 99 9d a1 a5
> 1559548684.094725: P2P: Add operating class 126
> 1559548684.094890: P2P: Channels - hexdump(len=2): 95 9d
> 1559548684.095217: P2P: Add operating class 127
> 1559548684.095384: P2P: Channels - hexdump(len=2): 99 a1
> 1559548684.095744: P2P: Add operating class 130
> 1559548684.095956: P2P: Channels - hexdump(len=20): 24 28 2c 30 34 38
> 3c 40 64 68 6c 70 74 78 7c 80 84 88 8c 90
> 1559548684.097451: P2P: Update channel list
> 1559548684.098088: P2P: channels: 81:1,2,3,4,5,6,7,8,9,10,11,12,13
> 115:36,40,44,48 116:36,44 117:40,48 124:149,153,157,161
> 125:149,153,157,161,165 126:149,157 127:153,161
> 130:36,40,44,48,52,56,60,64,100,10
> 4,108,112,116,120,124,128,132,136,140,144
> 1559548684.098230: P2P: cli_channels:
> 1559548684.098330: Daemonize..
> real    1m 10.29s
> user    0m 0.38s
> sys     0m 0.10s
> 
> Thanks,
> Arthur.
> 
> _______________________________________________
> Hostap mailing list
> Hostap at lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/hostap




More information about the Hostap mailing list