[Solved] Unable to create AP with hostapd due to lack of entropy

jlight2011 · 2012-10-24 11:30:31

Hi Arch Users
I have an old PC that had Arch on it, is main purpose was for a FTP server and later also shared my internet connection using hostapd.

I had changed my HDD and set up a fresh install of Arch. However, I am unable to get the wireless AP up. I am using the Arch's hostapd's wiki This is my config file for hostapd.

interface=wlan0
driver=nl80211
logger_syslog=-1
logger_syslog_level=2
logger_stdout=-1
logger_stdout_level=2
ssid=test
hw_mode=g
channel=6
auth_algs=3
max_num_sta=255
wpa=2
wpa_passphrase=abcd1234
wpa_key_mgmt=WPA-PSK
wpa_pairwise=TKIP CCMP
rsn_pairwise=CCMP

My output when I run hostapd:

hostapd -dd /etc/hostapd/hostapd.conf
random: Trying to read entropy from /dev/random
Configuration file: /etc/hostapd/hostapd.conf
nl80211: interface wlan0 in phy phy0
rfkill: initial event: idx=0 type=1 op=0 soft=0 hard=0
nl80211: Using driver-based off-channel TX
nl80211: Add own interface ifindex 3
nl80211: Set mode ifindex 3 iftype 3 (AP)
nl80211: Create interface iftype 6 (MONITOR)
nl80211: New interface mon.wlan0 created: ifindex=10
nl80211: Add own interface ifindex 10
BSS count 1, BSSID mask 00:00:00:00:00:00 (0 bits)
nl80211: Regulatory information - country=00
nl80211: 2402-2472 @ 40 MHz
nl80211: 2457-2482 @ 20 MHz
nl80211: 2474-2494 @ 20 MHz
nl80211: 5170-5250 @ 40 MHz
nl80211: 5735-5835 @ 40 MHz
nl80211: 57240-63720 @ 2160 MHz
nl80211: Added 802.11b mode based on 802.11g information
Allowed channel: mode=1 chan=1 freq=2412 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=2 freq=2417 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=3 freq=2422 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=4 freq=2427 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=5 freq=2432 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=6 freq=2437 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=7 freq=2442 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=8 freq=2447 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=9 freq=2452 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=10 freq=2457 MHz max_tx_power=20 dBm
Allowed channel: mode=1 chan=11 freq=2462 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=1 freq=2412 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=2 freq=2417 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=3 freq=2422 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=4 freq=2427 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=5 freq=2432 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=6 freq=2437 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=7 freq=2442 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=8 freq=2447 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=9 freq=2452 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=10 freq=2457 MHz max_tx_power=20 dBm
Allowed channel: mode=0 chan=11 freq=2462 MHz max_tx_power=20 dBm
Completing interface initialization
Mode: IEEE 802.11g  Channel: 6  Frequency: 2437 MHz
nl80211: Set freq 2437 (ht_enabled=0 sec_channel_offset=0)
RATE[0] rate=10 flags=0x1
RATE[1] rate=20 flags=0x1
RATE[2] rate=55 flags=0x1
RATE[3] rate=110 flags=0x1
RATE[4] rate=60 flags=0x0
RATE[5] rate=90 flags=0x0
RATE[6] rate=120 flags=0x0
RATE[7] rate=180 flags=0x0
RATE[8] rate=240 flags=0x0
RATE[9] rate=360 flags=0x0
RATE[10] rate=480 flags=0x0
RATE[11] rate=540 flags=0x0
Flushing old station entries
Deauthenticate all stations
wpa_driver_nl80211_set_key: ifindex=3 alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_nl80211_set_key: ifindex=3 alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0 key_len=0
wpa_driver_nl80211_set_key: ifindex=3 alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0 key_len=0
wpa_driver_nl80211_set_key: ifindex=3 alg=0 addr=(nil) key_idx=3 set_tx=0 seq_len=0 key_len=0
Using interface wlan0 with hwaddr b0:48:7a:de:87:33 and ssid 'BatmanVsRobin'
Deriving WPA PSK based on passphrase
SSID - hexdump_ascii(len=13):
     42 61 74 6d 61 6e 56 73 52 6f 62 69 6e            BatmanVsRobin   
PSK (ASCII passphrase) - hexdump_ascii(len=8): [REMOVED]
PSK (from passphrase) - hexdump(len=32): [REMOVED]
random: Got 20/20 bytes from /dev/random
Get randomness: len=32 entropy=0
GMK - hexdump(len=32): [REMOVED]
Get randomness: len=32 entropy=0
Key Counter - hexdump(len=32): [REMOVED]
WPA: Delay group state machine start until Beacon frames have been configured
nl80211: Set beacon (beacon_set=0)
WPA: Start group state machine to set initial keys
WPA: group state machine entering state GTK_INIT (VLAN-ID 0)
Get randomness: len=16 entropy=0
GTK - hexdump(len=16): [REMOVED]
WPA: group state machine entering state SETKEYSDONE (VLAN-ID 0)
wpa_driver_nl80211_set_key: ifindex=3 alg=3 addr=0x80aef3a key_idx=1 set_tx=1 seq_len=0 key_len=16
   broadcast key
wpa_driver_nl80211_set_operstate: operstate 0->1 (UP)
netlink: Operstate: linkmode=-1, operstate=6
wlan0: Setup of interface done.
RTM_NEWLINK: operstate=1 ifi_flags=0x1002 ()
nl80211: Ignore interface down event since interface mon.wlan0 is up
RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'mon.wlan0' added
Unknown event 5
RTM_NEWLINK: operstate=1 ifi_flags=0x1003 ([UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
nl80211: if_removed already cleared - ignore event
RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
nl80211: if_removed already cleared - ignore event
Add randomness: count=1 entropy=0
Add randomness: count=2 entropy=1
Add randomness: count=3 entropy=2
Add randomness: count=4 entropy=3
Add randomness: count=5 entropy=4
Add randomness: count=6 entropy=5
Add randomness: count=7 entropy=6
Add randomness: count=8 entropy=7
Add randomness: count=9 entropy=8
Add randomness: count=10 entropy=9
Add randomness: count=11 entropy=10
Add randomness: count=12 entropy=11
Add randomness: count=13 entropy=12
Add randomness: count=14 entropy=13
Add randomness: count=15 entropy=14
Add randomness: count=16 entropy=15
Add randomness: count=17 entropy=16
Add randomness: count=18 entropy=17
Add randomness: count=19 entropy=18
Add randomness: count=20 entropy=19
Add randomness: count=21 entropy=20
...

The Add randomness keep going on and on. When I first saw this I thought that the entropy level was low, when I ran

cat /proc/sys/kernel/random/entropy_avail

It gave a value less than <<1000. So I installed the package Haveged. Now the value is >2000.

However there is no change. Have looked in the forums and on the web but unable to get a solution on this.

Cheers!

Nish

Last edited by jlight2011 (2012-11-16 03:31:54)

ewaller · 2012-10-24 15:36:13

My general suggestion would be to, while running hostpad, change over to a different console, log in, and do something disk intensive. Something silly like find / -print should do nicely

Edit: Then, of course, flip back to the original console and see if it gets off top dead center on the entropy thing.

Last edited by ewaller (2012-10-24 15:37:05)

hunterthomson · 2012-10-25 08:29:35

can you configure it to use /dev/urandom ?

/dev/random only returns real random numbers. However, /dev/urandom will first use all the real random numbers then switch to pseudorandom. Correct me if I'm worng about the details.

("real random numbers" as in number originating from the traditional Linux sources, keyboard, mouse,....)

Last edited by hunterthomson (2012-10-25 08:33:03)

jlight2011 · 2012-10-25 11:19:11

ewaller wrote:

My general suggestion would ...Something silly like find / -print should do nicely ...

Tried this, the operation lasts only for a few seconds (my total disk usage is <800M). Since my root is btrfs I also tried running a scrub (reports to last for 16s). (This may be out my total lack of knowledge on how hostapd works but...) When the disk is engaged I actually find that my AP is up, visible and can be connected to, for the briefest moment. A few second after the disk operation is done the AP is down again!

Is this an issue with hostapd or the kernel?

Cheers!

Last edited by jlight2011 (2012-10-25 11:30:16)

jlight2011 · 2012-10-25 11:29:11

hunterthomson wrote:

can you configure it to use /dev/urandom ?

Requesting for help from hostapd gives:

$ hostapd -h
hostapd v1.0
User space daemon for IEEE 802.11 AP management,
IEEE 802.1X/WPA/WPA2/EAP/RADIUS Authenticator
Copyright (c) 2002-2012, Jouni Malinen <j@w1.fi> and contributors

usage: hostapd [-hdBKtv] [-P <PID file>] [-e <entropy file>] <configuration file(s)>

options:
   -h   show this usage
   -d   show more debug messages (-dd for even more)
   -B   run daemon in the background
   -e   entropy file
   -P   PID file
   -K   include key data in debug messages
   -t   include timestamps in some debug messages
   -v   show hostapd version

Seeing the -e option makes me believe I can try using (some) entropy file. However /dev/urandom does not work. Here is what I tried

$ hostapd -dd -e /dev/urandom /etc/hostapd/hostapd.conf
random: Invalid entropy file /dev/urandom
random: Trying to read entropy from /dev/random
Get randomness: len=20 entropy=0
random: Updated entropy file /dev/urandom (own_pool_ready=0)
Configuration file: /etc/hostapd/hostapd.conf
nl80211: interface wlan0 in phy phy0
rfkill: initial event: idx=0 type=1 op=0 soft=0 hard=0
...

My guess is that my assumption (about -e) is not correct. Any ideas?

Cheers!

Last edited by jlight2011 (2012-10-25 11:31:18)

axs · 2012-10-25 13:25:38

jlight2011 wrote:

The Add randomness keep going on and on. When I first saw this I thought that the entropy level was low, when I ran

Same thing with my hostapd, it keeps printing Add randomness and yet it works well.
I had hostapd failing due to lack of randomness (I had no /dev/random), it looks differently:
"WPA: Not enough entropy in random pool for secure operations - update keys later when the first station connects"
So I don't think it's related to the lack of randomness.

In fact, as far as I can tell your hostapd thinks it's all ok and ready to accept clients.
Here's what mine outputs:

(...)
RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
RTM_NEWLINK, IFLA_IFNAME: Interface 'br0' added
Unknown event 5
mgmt::deauth cb
Add randomness: count=1 entropy=0
Add randomness: count=2 entropy=1
Add randomness: count=3 entropy=2
Add randomness: count=4 entropy=3
Add randomness: count=5 entropy=4
Add randomness: count=6 entropy=5
Add randomness: count=7 entropy=6
Add randomness: count=8 entropy=7
Add randomness: count=9 entropy=8
Add randomness: count=10 entropy=9
Add randomness: count=11 entropy=10
Add randomness: count=12 entropy=11
Add randomness: count=13 entropy=12
Add randomness: count=14 entropy=13
mgmt::auth
authentication: STA=(...) auth_alg=0 auth_transaction=1 status_code=0 wep=0

Looking at the code, mgmt::auth means it's got authentication request, from my laptop in this case.

jlight2011 · 2012-10-25 14:25:12

axs wrote:

I had hostapd failing due to lack of randomness (I had no /dev/random), it looks differently:
Looking at the code, mgmt::auth means it's got authentication request, from my laptop in this case.

By trial and error there are my observations based on the suggestion mentioned here

1. When I run hostapd (on CompA) , as you noted it's all ok and ready to accept clients, however it not actually broadcasting.
2. I start a disk intensive operation (like btrfs scrub, here on refered as just scrub, that lasts about 20s)
3. I immediately see the Wireless Network on my Laptop (CompB)
4. I connect to it (if connections fails I start another scrub on CompA) then immediately I can see that authentication is a success in CompB /var/log/message.log
5. I then try browse the internet, things are ok for 10-30s. If the page does not load I start another scrub on CompA, bang! the page loads.

Here are some pings from CompB (192.168.100.1 is our proxy server) (comments embedded into the output and start with <-- )

From 192.168.100.113 icmp_seq=1210 Destination Host Unreachable
64 bytes from 192.168.100.1: icmp_req=1211 ttl=128 time=750 ms
64 bytes from 192.168.100.1: icmp_req=1212 ttl=128 time=1.20 ms
64 bytes from 192.168.100.1: icmp_req=1213 ttl=128 time=1.15 ms
64 bytes from 192.168.100.1: icmp_req=1214 ttl=128 time=0.962 ms
64 bytes from 192.168.100.1: icmp_req=1215 ttl=128 time=1.24 ms
64 bytes from 192.168.100.1: icmp_req=1216 ttl=128 time=25.2 ms
64 bytes from 192.168.100.1: icmp_req=1217 ttl=128 time=13.4 ms
64 bytes from 192.168.100.1: icmp_req=1218 ttl=128 time=4.85 ms
64 bytes from 192.168.100.1: icmp_req=1219 ttl=128 time=2.03 ms
64 bytes from 192.168.100.1: icmp_req=1220 ttl=128 time=2.81 ms
64 bytes from 192.168.100.1: icmp_req=1221 ttl=128 time=6.53 ms
64 bytes from 192.168.100.1: icmp_req=1222 ttl=128 time=6.32 ms
64 bytes from 192.168.100.1: icmp_req=1223 ttl=128 time=2.53 ms
64 bytes from 192.168.100.1: icmp_req=1224 ttl=128 time=1.41 ms
64 bytes from 192.168.100.1: icmp_req=1225 ttl=128 time=9.68 ms
64 bytes from 192.168.100.1: icmp_req=1226 ttl=128 time=10.4 ms
64 bytes from 192.168.100.1: icmp_req=1227 ttl=128 time=5.38 ms
64 bytes from 192.168.100.1: icmp_req=1228 ttl=128 time=11.9 ms
64 bytes from 192.168.100.1: icmp_req=1229 ttl=128 time=5.12 ms           <--Got stuck here waited for 5s then started a scrub on CompA
64 bytes from 192.168.100.1: icmp_req=1230 ttl=128 time=9160 ms     
64 bytes from 192.168.100.1: icmp_req=1231 ttl=128 time=8161 ms
64 bytes from 192.168.100.1: icmp_req=1232 ttl=128 time=7161 ms
64 bytes from 192.168.100.1: icmp_req=1233 ttl=128 time=6161 ms
64 bytes from 192.168.100.1: icmp_req=1234 ttl=128 time=5162 ms
64 bytes from 192.168.100.1: icmp_req=1235 ttl=128 time=4162 ms
64 bytes from 192.168.100.1: icmp_req=1236 ttl=128 time=3162 ms
64 bytes from 192.168.100.1: icmp_req=1237 ttl=128 time=2163 ms
64 bytes from 192.168.100.1: icmp_req=1238 ttl=128 time=1163 ms
64 bytes from 192.168.100.1: icmp_req=1239 ttl=128 time=163 ms           <--Back to normal
64 bytes from 192.168.100.1: icmp_req=1240 ttl=128 time=1.98 ms
64 bytes from 192.168.100.1: icmp_req=1241 ttl=128 time=21.4 ms
64 bytes from 192.168.100.1: icmp_req=1242 ttl=128 time=0.679 ms
64 bytes from 192.168.100.1: icmp_req=1243 ttl=128 time=0.936 ms
64 bytes from 192.168.100.1: icmp_req=1244 ttl=128 time=1.16 ms
64 bytes from 192.168.100.1: icmp_req=1245 ttl=128 time=42.9 ms
64 bytes from 192.168.100.1: icmp_req=1246 ttl=128 time=5.72 ms
64 bytes from 192.168.100.1: icmp_req=1247 ttl=128 time=4.05 ms
64 bytes from 192.168.100.1: icmp_req=1248 ttl=128 time=0.794 ms
64 bytes from 192.168.100.1: icmp_req=1249 ttl=128 time=17.1 ms
64 bytes from 192.168.100.1: icmp_req=1250 ttl=128 time=2.97 ms
64 bytes from 192.168.100.1: icmp_req=1251 ttl=128 time=7.51 ms
64 bytes from 192.168.100.1: icmp_req=1252 ttl=128 time=6.31 ms
64 bytes from 192.168.100.1: icmp_req=1253 ttl=128 time=2.62 ms
64 bytes from 192.168.100.1: icmp_req=1254 ttl=128 time=5.95 ms
64 bytes from 192.168.100.1: icmp_req=1255 ttl=128 time=2.71 ms
64 bytes from 192.168.100.1: icmp_req=1256 ttl=128 time=1.78 ms
64 bytes from 192.168.100.1: icmp_req=1257 ttl=128 time=2.81 ms      <--Got stuck again waited for a few seconds and hit another scrub
64 bytes from 192.168.100.1: icmp_req=1258 ttl=128 time=4240 ms     
64 bytes from 192.168.100.1: icmp_req=1259 ttl=128 time=3246 ms
64 bytes from 192.168.100.1: icmp_req=1260 ttl=128 time=2249 ms
64 bytes from 192.168.100.1: icmp_req=1261 ttl=128 time=1254 ms
64 bytes from 192.168.100.1: icmp_req=1262 ttl=128 time=256 ms
64 bytes from 192.168.100.1: icmp_req=1263 ttl=128 time=3.22 ms
64 bytes from 192.168.100.1: icmp_req=1264 ttl=128 time=2.35 ms
64 bytes from 192.168.100.1: icmp_req=1265 ttl=128 time=0.869 ms
64 bytes from 192.168.100.1: icmp_req=1266 ttl=128 time=0.985 ms
64 bytes from 192.168.100.1: icmp_req=1267 ttl=128 time=3.98 ms
64 bytes from 192.168.100.1: icmp_req=1268 ttl=128 time=1.25 ms

My understanding from this, rathur crude experiment, the disk operation increases the entropy and hostapd is happy to act normal. When there is no disk operation, entropy is low hostapd temporally pauses broadcasting until the necessary entropy is reached.

EDIT:
I also need to mention that when the ping seem to get stuck the netowrk is not boradcasting as I cannot see it in my mobile (for example) even after multiple refreshes . When I start a scrub the ping improves and when I immediately refresh networks on my mobile I can see the Wireless Network.

Last edited by jlight2011 (2012-10-25 14:31:58)

axs · 2012-10-25 15:26:12

Still doesn't look like a randomness problem to me.
Long ping times are more indicative of retransmission or retraining issues.
I can't simulate it properly, but from what I can tell failing hostapd should result in immediate "network unreachable" messages, not long delays.

Also, I tried disabling (renaming) /dev/random, here's what hostapd writes:

random: Cannot read from /dev/random: Resource temporarily unavailable
random: Only 19/20 bytes of strong random data available from /dev/random
random: Allow operation to proceed based on internal entropy

And it doesn't drop the connection. It kept running for several minutes without any apparent issues.

No idea why or how it could be linked to disk activity.
I'd try to check link quality (watch -n1 iw wlan0 station dump / iwconfig wlan0) when the pings stop, preferably on both hosts.
With iw, maybe also iw wlan0 info.

Last edited by axs (2012-10-25 15:44:20)

Leonid.I · 2012-10-25 16:46:38

For those who has this problem, the solution is to install haveged from [community]. It will always maintain a pool of entropy taking it from CPU timer. This problem of low entropy is very common in canned routers -- /proc/sys/kernel/random/entropy_avail is ~50. Meanwhile it should be ~3000.

Even if you don't have an immediate problem with randomness, running havege is still a good idea because you never know when you need entropy.. At some point suse even considered including it in default installs...

Finally, for a strong encryption, do not use /dev/urandom. The difference from /dev/random is that urandom is nonblocking, so you may end up getting a bad pseudorandom number and a weak encryption. On the contrary, /dev/random will block until enough entropy has been collected.

Last edited by Leonid.I (2012-10-25 16:47:11)

jlight2011 · 2012-10-26 02:52:23

axs wrote:

Still doesn't look like a randomness problem to me.
Long ping times are more indicative of retransmission or retraining issues.
I can't simulate it properly, but from what I can tell failing hostapd should result in immediate "network unreachable" messages, not long delays.
Also, I tried disabling (renaming) /dev/random, here's what hostapd writes:

I renamed /dev/random, on doing so I am unable to connect. The Laptop Reports (message.log)

Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) starting connection 'Auto Cobra'
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0/wireless): access point 'Auto Cobra' has security, but secrets are required.
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0/wireless): connection 'Auto Cobra' has security, and secrets exist.  No new secrets needed.
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Config: added 'ssid' value 'Cobra'
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Config: added 'scan_ssid' value '1'
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Config: added 'psk' value '<omitted>'
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> Config: set interface ap_scan to 1
Oct 26 13:36:35 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: inactive -> scanning
Oct 26 13:36:36 jlightDell kernel: [56648.140066] wlan0: authenticate with b0:48:7a:de:87:33
Oct 26 13:36:36 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Oct 26 13:36:36 jlightDell kernel: [56648.149467] wlan0: send auth to b0:48:7a:de:87:33 (try 1/3)
Oct 26 13:36:36 jlightDell kernel: [56648.152582] wlan0: authenticated
Oct 26 13:36:36 jlightDell kernel: [56648.152690] iwlwifi 0000:03:00.0: wlan0: disabling HT as WMM/QoS is not supported
Oct 26 13:36:36 jlightDell kernel: [56648.154066] wlan0: associate with b0:48:7a:de:87:33 (try 1/3)
Oct 26 13:36:36 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: authenticating -> associating
Oct 26 13:36:36 jlightDell kernel: [56648.160420] wlan0: RX AssocResp from b0:48:7a:de:87:33 (capab=0x411 status=0 aid=1)
Oct 26 13:36:36 jlightDell kernel: [56648.165177] wlan0: associated
Oct 26 13:36:36 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: associating -> associated
Oct 26 13:36:36 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Oct 26 13:36:36 jlightDell kernel: [56648.177890] wlan0: deauthenticated from b0:48:7a:de:87:33 (Reason: 2)
Oct 26 13:36:36 jlightDell kernel: [56648.181887] cfg80211: Calling CRDA to update world regulatory domain
Oct 26 13:36:36 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: 4-way handshake -> disconnected
Oct 26 13:36:36 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Oct 26 13:36:37 jlightDell kernel: [56648.910824] wlan0: authenticate with b0:48:7a:de:87:33
Oct 26 13:36:37 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Oct 26 13:36:37 jlightDell kernel: [56648.919967] wlan0: send auth to b0:48:7a:de:87:33 (try 1/3)
Oct 26 13:36:37 jlightDell kernel: [56648.929539] wlan0: authenticated
Oct 26 13:36:37 jlightDell kernel: [56648.929647] iwlwifi 0000:03:00.0: wlan0: disabling HT as WMM/QoS is not supported
Oct 26 13:36:37 jlightDell kernel: [56648.929864] wlan0: associate with b0:48:7a:de:87:33 (try 1/3)
Oct 26 13:36:37 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: authenticating -> associating
Oct 26 13:36:37 jlightDell kernel: [56648.938292] wlan0: RX AssocResp from b0:48:7a:de:87:33 (capab=0x411 status=0 aid=1)
Oct 26 13:36:37 jlightDell kernel: [56648.940983] wlan0: associated
Oct 26 13:36:37 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: associating -> associated
Oct 26 13:36:37 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Oct 26 13:36:37 jlightDell kernel: [56648.956533] wlan0: deauthenticated from b0:48:7a:de:87:33 (Reason: 2)
Oct 26 13:36:37 jlightDell kernel: [56648.957878] cfg80211: Calling CRDA to update world regulatory domain
Oct 26 13:36:37 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: 4-way handshake -> disconnected
Oct 26 13:36:37 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Oct 26 13:36:38 jlightDell kernel: [56649.685791] wlan0: authenticate with b0:48:7a:de:87:33
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Oct 26 13:36:38 jlightDell kernel: [56649.696944] wlan0: send auth to b0:48:7a:de:87:33 (try 1/3)
Oct 26 13:36:38 jlightDell kernel: [56649.701914] wlan0: authenticated
Oct 26 13:36:38 jlightDell kernel: [56649.702038] iwlwifi 0000:03:00.0: wlan0: disabling HT as WMM/QoS is not supported
Oct 26 13:36:38 jlightDell kernel: [56649.702373] wlan0: associate with b0:48:7a:de:87:33 (try 1/3)
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: authenticating -> associating
Oct 26 13:36:38 jlightDell kernel: [56649.710200] wlan0: RX AssocResp from b0:48:7a:de:87:33 (capab=0x411 status=0 aid=1)
Oct 26 13:36:38 jlightDell kernel: [56649.713190] wlan0: associated
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: associating -> associated
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Oct 26 13:36:38 jlightDell kernel: [56649.738911] wlan0: deauthenticated from b0:48:7a:de:87:33 (Reason: 2)
Oct 26 13:36:38 jlightDell kernel: [56649.740221] cfg80211: Calling CRDA to update world regulatory domain
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: 4-way handshake -> disconnected
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Oct 26 13:36:38 jlightDell kernel: [56650.493289] wlan0: authenticate with b0:48:7a:de:87:33
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Oct 26 13:36:38 jlightDell kernel: [56650.502460] wlan0: send auth to b0:48:7a:de:87:33 (try 1/3)
Oct 26 13:36:38 jlightDell kernel: [56650.508299] wlan0: authenticated
Oct 26 13:36:38 jlightDell kernel: [56650.508434] iwlwifi 0000:03:00.0: wlan0: disabling HT as WMM/QoS is not supported
Oct 26 13:36:38 jlightDell kernel: [56650.511460] wlan0: associate with b0:48:7a:de:87:33 (try 1/3)
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: authenticating -> associating
Oct 26 13:36:38 jlightDell kernel: [56650.523191] wlan0: RX AssocResp from b0:48:7a:de:87:33 (capab=0x411 status=0 aid=1)
Oct 26 13:36:38 jlightDell kernel: [56650.526222] wlan0: associated
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: associating -> associated
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: associated -> 4-way handshake
Oct 26 13:36:38 jlightDell kernel: [56650.538202] wlan0: deauthenticated from b0:48:7a:de:87:33 (Reason: 2)
Oct 26 13:36:38 jlightDell kernel: [56650.541914] cfg80211: Calling CRDA to update world regulatory domain
Oct 26 13:36:38 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: 4-way handshake -> disconnected
Oct 26 13:36:39 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Oct 26 13:36:39 jlightDell kernel: [56651.195067] wlan0: authenticate with b0:48:7a:de:87:33
Oct 26 13:36:39 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Oct 26 13:36:39 jlightDell kernel: [56651.197546] wlan0: send auth to b0:48:7a:de:87:33 (try 1/3)
Oct 26 13:36:39 jlightDell kernel: [56651.400506] wlan0: send auth to b0:48:7a:de:87:33 (try 2/3)
Oct 26 13:36:39 jlightDell kernel: [56651.603593] wlan0: send auth to b0:48:7a:de:87:33 (try 3/3)
Oct 26 13:36:40 jlightDell kernel: [56651.806701] wlan0: authentication with b0:48:7a:de:87:33 timed out
Oct 26 13:36:40 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: authenticating -> disconnected
Oct 26 13:36:40 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: disconnected -> scanning
Oct 26 13:37:00 jlightDell NetworkManager[481]: <warn> Activation (wlan0/wireless): association took too long.
Oct 26 13:37:00 jlightDell NetworkManager[481]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
Oct 26 13:37:00 jlightDell NetworkManager[481]: <warn> Activation (wlan0/wireless): asking for new secrets
Oct 26 13:37:00 jlightDell NetworkManager[481]: <info> (wlan0): supplicant interface state: scanning -> disconnected
Oct 26 13:37:00 jlightDell NetworkManager[481]: <warn> Couldn't disconnect supplicant interface: This interface is not connected.
Oct 26 13:37:03 jlightDell NetworkManager[481]: <warn> No agents were available for this request.
Oct 26 13:37:03 jlightDell NetworkManager[481]: <info> (wlan0): device state change: need-auth -> failed (reason 'no-secrets') [60 120 7]
Oct 26 13:37:03 jlightDell NetworkManager[481]: <info> Marking connection 'Auto Cobra' invalid.
Oct 26 13:37:03 jlightDell NetworkManager[481]: <warn> Activation (wlan0) failed for connection 'Auto Cobra'
Oct 26 13:37:03 jlightDell NetworkManager[481]: <info> (wlan0): device state change: failed -> disconnected (reason 'none') [120 30 0]
Oct 26 13:37:03 jlightDell NetworkManager[481]: <info> (wlan0): deactivating device (reason 'none') [0]

No idea why or how it could be linked to disk activity.

The disk activity was a suggestion by ewaller to increase entropy, which seem to do so quite well, unfortunately I do not know how to keep this activity up indefinitely (for testing). Obviously I would not want that to be the norm.

I'd try to check link quality (watch -n1 iw wlan0 station dump / iwconfig wlan0) when the pings stop, preferably on both hosts.
With iw, maybe also iw wlan0 info.

I dont believe it is a link quality issue. The reason I believe this is so, when the disk active (=entropy generated: I think), the network experience is great. iwlist scan reports 70/70 link strength. Ont the machine where hoastapd is running. Once the disk activity is done I see this from hostapd output:

wlan0: STA ac:72:89:88:cb:47 IEEE 802.11: deauthenticated due to local deauth request
Add randomness: count=121 entropy=1
Add randomness: count=122 entropy=2
...

Once on the Laptop the ping (at the very moment) seem to be stuck. Now when I start another scrub everything goes back to normal.

Cheers!

jlight2011 · 2012-10-26 02:59:42

Leonid.I wrote:

For those who has this problem, the solution is to install haveged from [community]. It will always maintain a pool of entropy taking it from CPU timer. This problem of low entropy is very common in canned routers -- /proc/sys/kernel/random/entropy_avail is ~50. Meanwhile it should be ~3000.

Installing haveged was one of the first thing I did. I remember when I had updated pacman a while back on this machine it I had issues creating the key-management (it think that is what its called) while connected to this through ssh. Installing haveged solved that particular problem then, does not seem to do so here.

I have ensured that haveged is started during boot and have verified its status. Infact /proc/sys/kernel/random/entropy_avail reports a value 3000+ (before scrub and after scrub). Unfortunately, my AP seem to work only when I start some disk intensive activity .

Cheers!

Last edited by jlight2011 (2012-10-26 03:02:55)

Leonid.I · 2012-10-26 15:47:30

Ah... I wrote too fast. So, it's not an entropy problem.

Anyway, just out of curiosity, does your AP appear with "auth_algs=1" instead of 3? And try reducing max number of stations to ~10...

If it helps, here is my hostapd.conf (modified from the upstream default), which is working right now:

$ grep -v -e ^$ -e ^# hostapd.conf
interface=wap
bridge=br0
driver=nl80211
logger_syslog=-1
logger_syslog_level=0
logger_stdout=-1
logger_stdout_level=2
dump_file=/tmp/hostapd.dump
ctrl_interface=/var/run/hostapd
ctrl_interface_group=0
ssid=xxxxxx
hw_mode=g
channel=6
beacon_int=100
dtim_period=2
max_num_sta=20
rts_threshold=2347
fragm_threshold=2346
preamble=1
macaddr_acl=0
auth_algs=1
ignore_broadcast_ssid=0
wmm_enabled=1
wmm_ac_bk_cwmin=4
wmm_ac_bk_cwmax=10
wmm_ac_bk_aifs=7
wmm_ac_bk_txop_limit=0
wmm_ac_bk_acm=0
wmm_ac_be_aifs=3
wmm_ac_be_cwmin=4
wmm_ac_be_cwmax=10
wmm_ac_be_txop_limit=0
wmm_ac_be_acm=0
wmm_ac_vi_aifs=2
wmm_ac_vi_cwmin=3
wmm_ac_vi_cwmax=4
wmm_ac_vi_txop_limit=94
wmm_ac_vi_acm=0
wmm_ac_vo_aifs=2
wmm_ac_vo_cwmin=2
wmm_ac_vo_cwmax=3
wmm_ac_vo_txop_limit=47
wmm_ac_vo_acm=0
ieee80211n=1
ht_capab=[HT40+][SHORT-GI-40][DSSS_CCK-40][TX-STBC][RX-STBC1]
eapol_key_index_workaround=0
eap_server=0
own_ip_addr=127.0.0.1
wpa=2
wpa_passphrase=xxxxxxxxxxxx
wpa_key_mgmt=WPA-PSK
wpa_pairwise=CCMP
rsn_pairwise=CCMP

Last edited by Leonid.I (2012-10-26 15:49:40)

axs · 2012-10-26 20:37:12

jlight2011 wrote:

I renamed /dev/random, on doing so I am unable to connect. The Laptop Reports (...)

Does hostapd report anything?
My experience is that when hostapd has troubles with entropy it states so clearly and loudly.

kernel: [56648.177890] wlan0: deauthenticated from b0:48:7a:de:87:33 (Reason: 2)

According to http://www.aboutcher.co.uk/2012/07/linu … son-codes/ reason 2 is "Previous authentication no longer valid".
Not sure here, but some of the possible causes are radio interference and another AP with the same SSID in range.

The disk activity was a suggestion by ewaller to increase entropy, which seem to do so quite well, unfortunately I do not know how to keep this activity up indefinitely (for testing).

Does increasing entropy by other means help?
If no, it's not entropy, it's something else. Maybe hdd activity itself.

unfortunately I do not know how to keep this activity up indefinitely (for testing).

Something like while true; do disk-intensive-task; done, no?
Alternatively, I used this little script to keep the disc running (for other reasons, it parked its heads otherwise):

#!/bin/bash

unit=516096
count=155061
while true; do
	sector=$[($RANDOM+$RANDOM)%$count]
	dd if=/dev/hdb of=/dev/zero bs=$unit skip=$sector count=1 2>/dev/null
	sleep 1
done

iwlist scan reports 70/70 link strength

That's signal strength, it says nothing about noise.
I'd be more interested in tx retries / tx failed counters and tx bitrate changes.

Btw, does changing channel to 1 or 11 help? 6 tends to be very popular (=noisy) channel.

jlight2011 · 2012-11-16 03:38:09

Hi All
Sorry about the delay for the reply, I was away and was not able to look at this.

The issue turned out to be, as all most everyone here indicated, to be not related to entropy.

I noticed, when I booted to a live Ubuntu USB stick, that I was not able to connect to the WiFi hotspot from my phone (while trying to install the hostapd package). This indicated to me that the issue was more with my card then anything else.

I remember I had moved my case and it seem to have caused some movement in my card. Opening the case and re fitting the card enabled me to connect to the WiFi hostspot. Then booting into Arch I found that the problem was fixed!

How the random writes to disk helped the situation continues to baffle me.

Thank you all for helping me out!

Cheers!

NJ

frepa · 2013-02-19 19:22:46

I found this thread when I was puzzled by the "Add randomness: count=1 entropy=0" message from hostapd. I ran hostapd -dd, and got the message roughly once a second. Otherwise, the access point worked normally. I also thought that this message is about /dev/random running low, but it turned out to be a harmless debugging message, visible only when running hostapd with the -dd flag.

I looked at the source of hostapd 1.0, and found the following. Hostapd keeps an internal pool of entropy, which it uses for encryption in addition to values it reads from /dev/random. At several points in the code, unpredictable values are mixed into this pool. For example the signal strength measured for each received packet. Every time something is added to the pool, the message "Add randomness" is printed. So this message is really harmless, and just shows that the internal entropy pool is functioning. Just run hostapd with less debugging (say -d) and concentrate on the other, more important, messages. As for why disk accesses make the "Add randomness" message stop, I can only guess that loading the system with the disk accesses just gives hostapd less chances to run.

Another note: The message seems to appear only for newer versions of hostapd, I have seen it with version 1.0. On ubuntu 12.04, I have version 0.7.3, and see no "Add radomness" messages. My reason for digging into this was setting up a Raspberry Pi as a WiFi router. It worked out well, I wrote about it here.

Thanks for the pointer to haveged anyway! I once saw hostapd complain in this way:
random: Got 18/20 bytes from /dev/random
This message really indicates that /dev/random is depleted. Since I installed haveged, I have not seen this.

Cheers!
Frepa

Arch Linux

#1 2012-10-24 11:30:31

[Solved] Unable to create AP with hostapd due to lack of entropy

#2 2012-10-24 15:36:13

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#3 2012-10-25 08:29:35

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#4 2012-10-25 11:19:11

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#5 2012-10-25 11:29:11

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#6 2012-10-25 13:25:38

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#7 2012-10-25 14:25:12

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#8 2012-10-25 15:26:12

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#9 2012-10-25 16:46:38

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#10 2012-10-26 02:52:23

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#11 2012-10-26 02:59:42

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#12 2012-10-26 15:47:30

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#13 2012-10-26 20:37:12

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#14 2012-11-16 03:38:09

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

#15 2013-02-19 19:22:46

Re: [Solved] Unable to create AP with hostapd due to lack of entropy

Board footer