client drops

[conloos]

Hi,

everything works fine, except that after a few hours all clients are dropped and can't reconnect till i reboot the bpi r1.
This problem is well known and there a many tips like

• firmware,
• switch off the powermanagement or
• timing issues.
  Is there a working solution?

[jekader]

Hi, I can't confirm this behavior on my BPI-R1:

uptime

05:22:51 up 30 days, 18:22, 1 user, load average: 0.25, 0.10, 0.09

dmesg | grep wlan0

[ 30.354926] device wlan0 entered promiscuous mode
[ 31.032737] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 34.877602] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 34.905779] lanbr0: port 1(wlan0) entered forwarding state
[ 34.920947] lanbr0: port 1(wlan0) entered forwarding state
[ 49.924122] lanbr0: port 1(wlan0) entered forwarding state
[460610.174362] lanbr0: port 1(wlan0) entered disabled state
[460722.022666] lanbr0: port 1(wlan0) entered forwarding state
[460722.033079] lanbr0: port 1(wlan0) entered forwarding state
[460737.068332] lanbr0: port 1(wlan0) entered forwarding state
[460927.296437] lanbr0: port 1(wlan0) entered disabled state
[461463.394678] lanbr0: port 1(wlan0) entered forwarding state
[461463.405067] lanbr0: port 1(wlan0) entered forwarding state
[461478.443894] lanbr0: port 1(wlan0) entered forwarding state

As you see, there's just a couple interface flaps throughout the month, however my wireless clients are still able to connect.

What exactly happens in your case when wifi breaks? Do your clients still see the access point? Are you able to initiate a connection and enter a password?

I'd also try this once wifi is broken:

1. on bpi-r1 start tcpdump:

tcpdump -nn -i wlan0

2. try to associate a client
3. monitor tcpdump to see if any traffic appears, if a DHCP request is sent and if a reply is received (I've had problems with isc-dhcp-server on my box at least)

[conloos]

Hi,

sorry i needed the time to reproduce the failure.
With your package my connection is more stable.

Now i can say that my problem starts if i use more band width on my devices. E.g. downloading a update.

My devices (most android) see the accesspoint and try to reconnect to the bpi-r1.

This messages are from my /var/log/syslog
[...]
May 31 09:22:30 router kernel: [382606.393439] OnAction_p2p
May 31 09:22:30 router kernel: [382606.461620] OnAction_p2p
May 31 09:22:30 router kernel: [382606.735684] OnAction_p2p
May 31 09:22:31 router kernel: [382606.985707] OnAction_p2p
May 31 09:22:31 router kernel: [382607.067828] OnAction_p2p
May 31 09:22:31 router kernel: [382607.334355] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:22:31 router kernel: [382607.338549] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:22:31 router kernel: [382607.364233] issue_nulldata(wlan0) to 48:5a:3f:81:41:5a, ch:6, 1/1 in 20 ms
May 31 09:22:31 router kernel: [382607.368421] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:22:34 router kernel: [382610.477962] send_beacon success, issue:6, poll:51, 0 ms
May 31 09:22:43 router kernel: [382619.335316] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:22:43 router kernel: [382619.339517] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:22:43 router kernel: [382619.365112] issue_nulldata(wlan0) to 48:5a:3f:81:41:5a, ch:6, 1/1 in 20 ms
May 31 09:22:43 router kernel: [382619.369300] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:22:43 router kernel: [382619.386679] send_beacon success, issue:5, poll:41, 10 ms
May 31 09:22:51 router kernel: [382627.334098] asoc check, sta(48:5a:3f:81:41:5a) is alive
May 31 09:22:59 router kernel: [382635.336365] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:22:59 router kernel: [382635.340556] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:22:59 router kernel: [382635.366609] issue_nulldata(wlan0) to 48:5a:3f:81:41:5a, ch:6, 1/1 in 20 ms
May 31 09:22:59 router kernel: [382635.370799] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:23:07 router kernel: [382643.336984] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:23:07 router kernel: [382643.341174] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:23:07 router kernel: [382643.366983] issue_nulldata(wlan0) to 48:5a:3f:81:41:5a, ch:6, 1/1 in 20 ms
May 31 09:23:07 router kernel: [382643.371172] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:23:15 router kernel: [382651.337608] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:23:15 router kernel: [382651.341798] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:23:15 router kernel: [382651.367482] issue_nulldata(wlan0) to 48:5a:3f:81:41:5a, ch:6, 1/1 in 20 ms
May 31 09:23:15 router kernel: [382651.371670] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:23:33 router kernel: [382669.338866] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:23:33 router kernel: [382669.343057] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:23:33 router kernel: [382669.378857] issue_nulldata(wlan0) to 48:5a:3f:81:41:5a, ch:6, 1/1 in 30 ms
May 31 09:23:33 router kernel: [382669.383047] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:23:45 router kernel: [382681.339866] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:23:45 router kernel: [382681.344057] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:23:45 router hostapd: wlan0: STA 48:5a:3f:81:41:5a IEEE 802.11: disassociated
May 31 09:23:45 router hostapd: wlan0: STA 48:5a:3f:81:41:5a WPA: event 2 notification
May 31 09:23:45 router kernel: [382681.839601] OnDisassoc Reason code(8)
May 31 09:23:45 router kernel: [382681.842667] OnDisassoc, STA:48:5a:3f:81:41:5a
May 31 09:23:45 router kernel: [382681.845656] +rtw_indicate_sta_disassoc_event
May 31 09:23:45 router kernel: [382681.849512] report_del_sta_event: delete STA, mac_id=3
May 31 09:23:45 router kernel: [382681.853005] bss_cap_update_on_sta_leave, updated=0
May 31 09:23:45 router kernel: [382681.858031] issue_deauth to sta=48:5a:3f:81:41:5a for the reason(7)
May 31 09:23:45 router kernel: [382681.861091] issue_deauth to 48:5a:3f:81:41:5a
May 31 09:23:45 router kernel: [382681.864482] rtw_set_encryption
May 31 09:23:45 router kernel: [382681.870792] rtw_set_encryption(), sta has already been removed or never been added
May 31 09:23:45 router kernel: [382681.872649] rtw_set_encryption
May 31 09:23:46 router hostapd: wlan0: STA 48:5a:3f:81:41:5a IEEE 802.1X: unauthorizing port
May 31 09:23:46 router kernel: [382681.879912] rtw_set_encryption(), sta has already been removed or never been added
May 31 09:23:46 router kernel: [382681.882849] rtw_del_sta=48:5a:3f:81:41:5a
May 31 09:23:46 router kernel: [382681.888654] rtw_del_sta(), sta has already been removed or never been added
May 31 09:23:55 router kernel: [382691.340491] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:23:55 router kernel: [382691.344682] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:24:03 router kernel: [382699.341116] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:24:03 router kernel: [382699.345307] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:24:11 router kernel: [382707.341742] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:24:11 router kernel: [382707.346066] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:24:19 router kernel: [382715.342365] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:24:19 router kernel: [382715.346555] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:24:29 router kernel: [382725.343116] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:24:29 router kernel: [382725.347308] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:24:32 router dhclient: DHCPDISCOVER on eth0.101 to 255.255.255.255 port 67 interval 6
May 31 09:24:37 router kernel: [382733.343610] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 20 ms
May 31 09:24:37 router kernel: [382733.347801] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:24:38 router dhclient: DHCPDISCOVER on eth0.101 to 255.255.255.255 port 67 interval 17
May 31 09:24:55 router dhclient: DHCPDISCOVER on eth0.101 to 255.255.255.255 port 67 interval 16
May 31 09:25:05 router hostapd: wlan0: STA d8:50:e6:77:ac:1d IEEE 802.11: disassociated
May 31 09:25:05 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: event 2 notification
May 31 09:25:05 router kernel: [382761.663226] OnDisassoc Reason code(1)
May 31 09:25:05 router hostapd: wlan0: STA d8:50:e6:77:ac:1d IEEE 802.1X: unauthorizing port
May 31 09:25:05 router kernel: [382761.666291] OnDisassoc, STA:d8:50:e6:77:ac:1d
May 31 09:25:05 router kernel: [382761.669279] +rtw_indicate_sta_disassoc_event
May 31 09:25:05 router kernel: [382761.673144] report_del_sta_event: delete STA, mac_id=4
May 31 09:25:05 router kernel: [382761.676645] bss_cap_update_on_sta_leave, updated=0
May 31 09:25:05 router kernel: [382761.679670] rtw_set_encryption
May 31 09:25:05 router kernel: [382761.686042] rtw_set_encryption(), sta has already been removed or never been added
May 31 09:25:05 router kernel: [382761.687886] rtw_set_encryption
May 31 09:25:05 router kernel: [382761.694151] rtw_set_encryption(), sta has already been removed or never been added
May 31 09:25:05 router kernel: [382761.697574] rtw_del_sta=d8:50:e6:77:ac:1d
May 31 09:25:05 router kernel: [382761.703332] rtw_del_sta(), sta has already been removed or never been added

this block every time a device wants to connect again
[...]
May 31 09:25:09 router kernel: [382765.079276] +OnAuth
May 31 09:25:09 router kernel: [382765.081023] auth alg=0, seq=1
May 31 09:25:09 router kernel: [382765.085298] going to alloc stainfo for sa=d8:50:e6:77:ac:1d
May 31 09:25:09 router kernel: [382765.099692] OnAssocReq
May 31 09:25:09 router kernel: [382765.101865] allocate new AID = (2)
May 31 09:25:09 router kernel: [382765.106751] HT: STA d8:50:e6:77:ac:1d HT Capabilities Info: 0x012c
May 31 09:25:09 router kernel: [382765.114753] bss_cap_update_on_sta_join STA d8:50:e6:77:ac:1d - no greenfield, num of non-gf stations 2
May 31 09:25:09 router kernel: [382765.122264] bss_cap_update_on_sta_join STA d8:50:e6:77:ac:1d - 20 MHz HT, num of 20MHz HT STAs 2
May 31 09:25:09 router kernel: [382765.125688] bss_cap_update_on_sta_join, updated=0
May 31 09:25:09 router kernel: [382765.127019] issue_asocrsp
May 31 09:25:09 router kernel: [382765.131405] indicate_sta_join_event to upper layer - hostapd
May 31 09:25:09 router kernel: [382765.134159] +rtw_indicate_sta_assoc_event
May 31 09:25:09 router kernel: [382765.136895] report_add_sta_event: add STA
May 31 09:25:09 router kernel: [382765.142010] add_RATid=> mac_id:3 , raid:0 , bitmap=0xfffff, arg=0xa3
May 31 09:25:09 router kernel: [382765.146199] rtw_get_sta_wpaie, sta_addr: d8:50:e6:77:ac:1d
May 31 09:25:09 router hostapd: wlan0: STA d8:50:e6:77:ac:1d IEEE 802.11: associated
May 31 09:25:09 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: event 1 notification
May 31 09:25:09 router kernel: [382765.149343] rtw_set_encryption
May 31 09:25:09 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: start authentication
May 31 09:25:09 router kernel: [382765.153255] rtw_set_encryption, set pairwise key, none
May 31 09:25:09 router kernel: [382765.155426] rtw_set_encryption
May 31 09:25:09 router kernel: [382765.159315] rtw_set_encryption, set pairwise key, none
May 31 09:25:09 router hostapd: wlan0: STA d8:50:e6:77:ac:1d IEEE 802.1X: unauthorizing port
May 31 09:25:09 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: sending 1/4 msg of 4-Way Handshake
May 31 09:25:10 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: EAPOL-Key timeout
May 31 09:25:10 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: sending 1/4 msg of 4-Way Handshake
May 31 09:25:11 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: EAPOL-Key timeout
May 31 09:25:11 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: sending 1/4 msg of 4-Way Handshake
May 31 09:25:11 router dhclient: DHCPDISCOVER on eth0.101 to 255.255.255.255 port 67 interval 20
May 31 09:25:11 router kernel: [382767.366232] issue_nulldata(wlan0) to c0:ee:fb:21:53:32, ch:6, 1/1 in 40 ms
May 31 09:25:11 router kernel: [382767.370423] ack check for asoc expire, keep_alive_trycnt=1
May 31 09:25:12 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: EAPOL-Key timeout
May 31 09:25:12 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: sending 1/4 msg of 4-Way Handshake
May 31 09:25:13 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: EAPOL-Key timeout
May 31 09:25:13 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: PTKSTART: Retry limit 4 reached
May 31 09:25:13 router kernel: [382769.180997] rtw_set_encryption
May 31 09:25:13 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: event 3 notification
May 31 09:25:13 router kernel: [382769.184852] rtw_set_encryption, set pairwise key, none
May 31 09:25:13 router hostapd: wlan0: STA d8:50:e6:77:ac:1d IEEE 802.1X: unauthorizing port
May 31 09:25:13 router kernel: [382769.186730] rtw_set_encryption
May 31 09:25:13 router kernel: [382769.190620] rtw_set_encryption, set pairwise key, none
May 31 09:25:13 router kernel: [382769.194043] rtw_del_sta=d8:50:e6:77:ac:1d
May 31 09:25:13 router kernel: [382769.197120] issue_deauth to d8:50:e6:77:ac:1d
May 31 09:25:13 router kernel: [382769.200137] +rtw_indicate_sta_disassoc_event
May 31 09:25:13 router hostapd: wlan0: STA d8:50:e6:77:ac:1d MLME: MLME-DEAUTHENTICATE.indication(d8:50:e6:77:ac:1d, 2)
May 31 09:25:13 router hostapd: wlan0: STA d8:50:e6:77:ac:1d MLME: MLME-DELETEKEYS.request(d8:50:e6:77:ac:1d)
May 31 09:25:13 router kernel: [382769.204100] report_del_sta_event: delete STA, mac_id=3
May 31 09:25:13 router kernel: [382769.207632] bss_cap_update_on_sta_leave, updated=0
May 31 09:25:13 router kernel: [382769.210261] rtw_set_encryption
May 31 09:25:13 router hostapd: wlan0: STA d8:50:e6:77:ac:1d IEEE 802.11: disassociated
May 31 09:25:13 router hostapd: wlan0: STA d8:50:e6:77:ac:1d WPA: event 2 notification
May 31 09:25:13 router kernel: [382769.216639] rtw_set_encryption(), sta has already been removed or never been added
May 31 09:25:13 router kernel: [382769.218872] rtw_set_encryption
May 31 09:25:13 router kernel: [382769.225185] rtw_set_encryption(), sta has already been removed or never been added
May 31 09:25:13 router kernel: [382769.227122] rtw_set_encryption
May 31 09:25:13 router kernel: [382769.233423] rtw_set_encryption(), sta has already been removed or never been added
May 31 09:25:13 router hostapd: wlan0: STA d8:50:e6:77:ac:1d IEEE 802.1X: unauthorizing port
May 31 09:25:13 router kernel: [382769.236531] rtw_del_sta=d8:50:e6:77:ac:1d
May 31 09:25:13 router kernel: [382769.242240] rtw_del_sta(), sta has already been removed or never been added

many of this messages
[...]
May 31 09:25:45 router kernel: [382801.644477] _alloc_mgtxmitframe(wlan0) alloc xmitbuf fail
May 31 09:25:45 router kernel: [382801.647715] issue_beacon, alloc mgnt frame fail
[...]

[..] This type of messages i found after restarting the complete network on the console who is connected with a ttl to the bpi-r1.
+OnAuth
auth alg=0, seq=1
going to alloc stainfo for sa=d8:50:e6:77:ac:1d
OnAssocReq
allocate new AID = (1)
HT: STA d8:50:e6:77:ac:1d HT Capabilities Info: 0x012c
bss_cap_update_on_sta_join STA d8:50:e6:77:ac:1d - no greenfield, num of non-gf stations 1
bss_cap_update_on_sta_join STA d8:50:e6:77:ac:1d - 20 MHz HT, num of 20MHz HT STAs 1
bss_cap_update_on_sta_join, updated=0
issue_asocrsp
indicate_sta_join_event to upper layer - hostapd
+rtw_indicate_sta_assoc_event
report_add_sta_event: add STA
add_RATid=> mac_id:2 , raid:0 , bitmap=0xfffff, arg=0xa2
rtw_get_sta_wpaie, sta_addr: d8:50:e6:77:ac:1d
rtw_get_sta_wpaie, sta_addr: d8:50:e6:77:ac:1d
rtw_set_encryption
rtw_set_encryption, set pairwise key, none
rtw_set_encryption
rtw_set_encryption, set pairwise key, none
rtw_set_encryption
rtw_set_encryption, set pairwise key, none
rtw_set_encryption
rtw_set_encryption, set pairwise key, none
rtw_set_encryption
rtw_set_encryption, set pairwise key, none
rtw_set_encryption
rtw_set_encryption, set pairwise key, none
rtw_del_sta=d8:50:e6:77:ac:1d
issue_deauth to d8:50:e6:77:ac:1d
+rtw_indicate_sta_disassoc_event
report_del_sta_event: delete STA, mac_id=2
bss_cap_update_on_sta_leave, updated=0
rtw_set_encryption
rtw_set_encryption(), sta has already been removed or never been added
rtw_set_encryption
rtw_set_encryption(), sta has already been removed or never been added
rtw_set_encryption
rtw_set_encryption(), sta has already been removed or never been added
rtw_set_encryption
rtw_set_encryption(), sta has already been removed or never been added
rtw_set_encryption
rtw_set_encryption(), sta has already been removed or never been added
rtw_del_sta=d8:50:e6:77:ac:1d
rtw_del_sta(), sta has already been removed or never been added
rtw_del_sta=d8:50:e6:77:ac:1d
rtw_del_sta(), sta has already been removed or never been added
rtw_set_encryption
rtw_set_encryption(), sta has already been removed or never been added
rtw_set_encryption
rtw_set_encryption(), sta has already been removed or never been added
rtw_set_encryption
rtw_set_encryption(), sta has already been removed or never been added
rtw_del_sta=d8:50:e6:77:ac:1d
rtw_del_sta(), sta has already been removed or never been added

The tcpdump shows no messages.

My next step was to rmmod and insmod 8192cu and start the hostapd with -dd

There is many output, this is the block if a device trys to connect.

Wireless event: cmd=0x8c04 len=20
wlan0: Event DISASSOC (1) received
wlan0: STA d8:50:e6:77:ac:1d IEEE 802.11: disassociated
wlan0: AP-STA-DISCONNECTED d8:50:e6:77:ac:1d
wlan0: STA d8:50:e6:77:ac:1d WPA: event 2 notification
rtl871x_set_key_ops
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state DISCONNECTED
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state INITIALIZE
rtl871x_set_key_ops
wlan0: STA d8:50:e6:77:ac:1d IEEE 802.1X: unauthorizing port
+rtl871x_sta_remove_ops, d8:50:e6:77:ac:1d is sta address removed
hostapd_ht_operation_update current operation mode=0x0
hostapd_ht_operation_update new operation mode=0x0 changes=0
ap_free_sta: cancel ap_handle_timer for d8:50:e6:77:ac:1d
Wireless event: cmd=0x8c03 len=20
+rtl871x_get_sta_wpaie, d8:50:e6:77:ac:1d is sta's address
wlan0: Event ASSOC (0) received
wlan0: STA d8:50:e6:77:ac:1d IEEE 802.11: associated
STA included RSN IE in (Re)AssocReq
New STA
ap_sta_add: register ap_handle_timer timeout for d8:50:e6:77:ac:1d (300 seconds - ap_max_inactivity)
wlan0: STA d8:50:e6:77:ac:1d WPA: event 1 notification
rtl871x_set_key_ops
IEEE 802.1X: Ignore STA - 802.1X not enabled or forced for WPS
wlan0: STA d8:50:e6:77:ac:1d WPA: start authentication
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state INITIALIZE
rtl871x_set_key_ops
wlan0: STA d8:50:e6:77:ac:1d IEEE 802.1X: unauthorizing port
WPA: d8:50:e6:77:ac:1d WPA_PTK_GROUP entering state IDLE
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state AUTHENTICATION
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state AUTHENTICATION2
Get randomness: len=32 entropy=2
WPA: Assign ANonce - hexdump(len=32): 97 6d 6d 6d b0 ba 0b 4d c3 f9 6b 7e df 86 81 bf 68 5c 56 31 cd d5 a9 0c 83 d9 35 af ac 7a a2 21
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state INITPSK
Searching a PSK for d8:50:e6:77:ac:1d prev_psk=(nil)
Searching a PSK for d8:50:e6:77:ac:1d prev_psk=(nil)
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state PTKSTART
wlan0: STA d8:50:e6:77:ac:1d WPA: sending 1/4 msg of 4-Way Handshake
WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0)
WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
+rtl871x_send_eapol
TX EAPOL - hexdump(len=113): d8 50 e6 77 ac 1d ac a2 13 54 27 ef 88 8e 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 97 6d 6d 6d b0 ba 0b 4d c3 f9 6b 7e df 86 81 bf 68 5c 56 31 cd d5 a9 0c 83 d9 35 af ac 7a a2 21 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
WPA: Use EAPOL-Key timeout of 1000 ms (retry counter 1)
hostapd_new_assoc_sta: reschedule ap_handle_timer timeout for d8:50:e6:77:ac:1d (300 seconds - ap_max_inactivity)
l2_packet_receive: src=d8:50:e6:77:ac:1d len=135
wlan0: Event EAPOL_RX (24) received
IEEE 802.1X: 121 bytes from d8:50:e6:77:ac:1d
IEEE 802.1X: version=1 type=3 length=117
WPA: Received EAPOL-Key from d8:50:e6:77:ac:1d key_info=0x10a type=2 key_data_length=22
WPA: Received Key Nonce - hexdump(len=32): 39 ad e9 d4 0e 23 2d 83 7b e5 bd 90 05 84 09 8e f1 09 ad 08 a9 74 94 fc c5 cd fb 43 24 b5 d7 27
WPA: Received Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
wlan0: STA d8:50:e6:77:ac:1d WPA: received EAPOL-Key frame (2/4 Pairwise)
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state PTKCALCNEGOTIATING
Searching a PSK for d8:50:e6:77:ac:1d prev_psk=(nil)
WPA: PTK derivation - A1=ac:a2:13:54:27:ef A2=d8:50:e6:77:ac:1d
WPA: Nonce1 - hexdump(len=32): 97 6d 6d 6d b0 ba 0b 4d c3 f9 6b 7e df 86 81 bf 68 5c 56 31 cd d5 a9 0c 83 d9 35 af ac 7a a2 21
WPA: Nonce2 - hexdump(len=32): 39 ad e9 d4 0e 23 2d 83 7b e5 bd 90 05 84 09 8e f1 09 ad 08 a9 74 94 fc c5 cd fb 43 24 b5 d7 27
WPA: PMK - hexdump(len=32): [REMOVED]
WPA: PTK - hexdump(len=48): [REMOVED]
WPA: KCK - hexdump(len=16): [REMOVED]
WPA: KEK - hexdump(len=16): [REMOVED]
WPA: TK - hexdump(len=16): [REMOVED]
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state PTKCALCNEGOTIATING2
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state PTKINITNEGOTIATING
wlan0: STA d8:50:e6:77:ac:1d WPA: sending 3/4 msg of 4-Way Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=1 pairwise=1 kde_len=46 keyidx=1 encr=1)
WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 02
Plaintext EAPOL-Key Key Data - hexdump(len=56): [REMOVED]
+rtl871x_send_eapol
TX EAPOL - hexdump(len=169): d8 50 e6 77 ac 1d ac a2 13 54 27 ef 88 8e 02 03 00 97 02 13 ca 00 10 00 00 00 00 00 00 00 02 97 6d 6d 6d b0 ba 0b 4d c3 f9 6b 7e df 86 81 bf 68 5c 56 31 cd d5 a9 0c 83 d9 35 af ac 7a a2 21 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 4f 19 f5 57 72 7e 48 9a 1a f1 b6 08 2f 34 cc f4 00 38 db 30 5b 45 ba 40 86 f7 af 8d 17 a7 dc 68 aa 90 c2 60 50 88 73 1a 5a 89 f0 bb 5e fc 53 69 3b f9 57 d3 45 a6 b2 05 ac 16 a0 f8 ba a7 4c 99 97 05 50 44 ae 77 68 b0 9c be
WPA: Use EAPOL-Key timeout of 1000 ms (retry counter 1)
l2_packet_receive: src=d8:50:e6:77:ac:1d len=113
wlan0: Event EAPOL_RX (24) received
IEEE 802.1X: 99 bytes from d8:50:e6:77:ac:1d
IEEE 802.1X: version=1 type=3 length=95
WPA: Received EAPOL-Key from d8:50:e6:77:ac:1d key_info=0x30a type=2 key_data_length=0
WPA: Received Key Nonce - hexdump(len=32): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
WPA: Received Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 02
wlan0: STA d8:50:e6:77:ac:1d WPA: received EAPOL-Key frame (4/4 Pairwise)
WPA: d8:50:e6:77:ac:1d WPA_PTK entering state PTKINITDONE
rtl871x_set_key_ops
wlan0: AP-STA-CONNECTED d8:50:e6:77:ac:1d
wlan0: STA d8:50:e6:77:ac:1d IEEE 802.1X: authorizing port
wlan0: STA d8:50:e6:77:ac:1d RADIUS: starting accounting session 556AC0F9-00000003
wlan0: STA d8:50:e6:77:ac:1d WPA: pairwise key handshake completed (RSN)

Most times the device hangs on "Authentification" but somtimes i see "Getting IP Address".
I followed you hint and restarted dnsmasq, but no success.

Thanks Frank

[jekader]

Hi Frank, thanks for the great report. I sometimes see similar issues with clients unable to obtain an IP however this happens after hostapd finished it job and associated the client.

No idea what the root cause is, I've got a feeling that realtek's driver is to blame. I hope we'll once have the in-tree driver working properly and then using an unpatched hostapd will be possible.

Any ideas on fixing this are welcome. The sole wifi client on my BPI-R1 is a cellphone so I don't have enough data on my hands.

[conloos]

Hi,

thanks for your replay in lightspeed! :o)
Iam able to to load an unload the driver and hostapd and this solves not the error.
I have the feeling that an other player is in the game, too.
Next time i give my device a static ip and route to test if it is a dnsmasq problem.

Have you an other idea?

Thanks Frank

[jekader]

Well there's several parts where things could go wrong:

1. hardware issues
2. kernel driver
3. hostapd
4. network stack
5. DHCP/DNS/etc

Related to hardware - do you have enough power coming to the board? Do you have an HDD attached? For me strange things were happening with power until I bought a 5W power supply and applied this fix: http://bananapi.com/index.php/forum/general/391-why-the-sata-disk-doesnt-work-on-bpi-r1?start=12#1317

[fabiocannizzo]

Hi. I am having similar problems.

The BPI-R1 acts on my network as router, AP and DHCP server. In the network there is also a second AP and lot of nodes, some with static and some dynamic addresses, some wired and some wireless.

Everything works just fine for 2-3 days. Then the AP of the BPI-R1 stops working, everything else keeps working fine, including the dhcp, Internet and the DHCP server.

The stations can see the SSID, but when they try to connect the password is rejected.

To fix the problem, I have to:

1. systemctl stop hostapd
2. ifconfig wlan0
3. systemctl start hostapd
   Note that just restarting hostapd, without shutting down wlan0, is not sufficient to fix the issue.

Since restarting hostapd does not fix the problem, I suspect that is not the issue. Also DHCP seems ok.

When a station tries to connect, journalctl shows something like the below.

Do you have any suggestion? Thanks a lot!

Jun 11 21:56:30 bpir1 kernel: +OnAuth
Jun 11 21:56:30 bpir1 kernel: auth alg=0, seq=1
Jun 11 21:56:30 bpir1 kernel: going to alloc stainfo for sa=2c:44:fd:71:31:4c
Jun 11 21:56:30 bpir1 kernel: OnAssocReq
Jun 11 21:56:30 bpir1 kernel: allocate new AID = (1)
Jun 11 21:56:30 bpir1 kernel: update_bcn_fixed_ie
Jun 11 21:56:30 bpir1 kernel: HT: STA 2c:44:fd:71:31:4c HT Capabilities Info: 0x016c
Jun 11 21:56:30 bpir1 kernel: bss_cap_update_on_sta_join STA 2c:44:fd:71:31:4c - no greenfield, num of non-gf stations 1
Jun 11 21:56:30 bpir1 kernel: bss_cap_update_on_sta_join STA 2c:44:fd:71:31:4c - 20 MHz HT, num of 20MHz HT STAs 1
Jun 11 21:56:30 bpir1 kernel: bss_cap_update_on_sta_join, updated=1
Jun 11 21:56:30 bpir1 kernel: issue_asocrsp
Jun 11 21:56:30 bpir1 kernel: indicate_sta_join_event to upper layer - hostapd
Jun 11 21:56:30 bpir1 kernel: +rtw_indicate_sta_assoc_event
Jun 11 21:56:30 bpir1 kernel: report_add_sta_event: add STA
Jun 11 21:56:30 bpir1 hostapd[9257]: +rtl871x_get_sta_wpaie, 2c:44:fd:71:31:4c is sta's address
Jun 11 21:56:30 bpir1 kernel: rtw_get_sta_wpaie, sta_addr: 2c:44:fd:71:31:4c
Jun 11 21:56:30 bpir1 kernel: add_RATid=> mac_id:2 , raid:0 , bitmap=0xfffff, arg=0xa2
Jun 11 21:56:30 bpir1 kernel: rtw_set_encryption
Jun 11 21:56:30 bpir1 kernel: rtw_set_encryption, set pairwise key, none
Jun 11 21:56:30 bpir1 kernel: rtw_set_encryption
Jun 11 21:56:30 bpir1 kernel: rtw_set_encryption, set pairwise key, none
Jun 11 21:56:30 bpir1 hostapd[9257]: wlan0: STA 2c:44:fd:71:31:4c IEEE 802.11: associated
Jun 11 21:56:30 bpir1 hostapd[9257]: wlan0: STA 2c:44:fd:71:31:4c IEEE 802.11: associated
Jun 11 21:56:30 bpir1 hostapd[9257]: rtl871x_set_key_ops
Jun 11 21:56:30 bpir1 hostapd[9257]: rtl871x_set_key_ops
Jun 11 21:56:30 bpir1 hostapd[9257]: +rtl871x_send_eapol
Jun 11 21:56:31 bpir1 hostapd[9257]: +rtl871x_send_eapol
Jun 11 21:56:32 bpir1 hostapd[9257]: +rtl871x_send_eapol
Jun 11 21:56:33 bpir1 hostapd[9257]: +rtl871x_send_eapol
Jun 11 21:56:34 bpir1 hostapd[9257]: +rtl871x_sta_deauth_ops, 2c:44:fd:71:31:4c is deauth, reason=2
Jun 11 21:56:34 bpir1 hostapd[9257]: rtl871x_set_key_ops
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption, set pairwise key, none
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption, set pairwise key, none
Jun 11 21:56:34 bpir1 kernel: rtw_del_sta=2c:44:fd:71:31:4c
Jun 11 21:56:34 bpir1 kernel: issue_deauth to 2c:44:fd:71:31:4c
Jun 11 21:56:34 bpir1 hostapd[9257]: WPA: wpa_sm_step() called recursively
Jun 11 21:56:34 bpir1 hostapd[9257]: rtl871x_set_key_ops
Jun 11 21:56:34 bpir1 hostapd[9257]: +rtl871x_sta_remove_ops, 2c:44:fd:71:31:4c is sta address removed
Jun 11 21:56:34 bpir1 kernel: +rtw_indicate_sta_disassoc_event
Jun 11 21:56:34 bpir1 kernel: report_del_sta_event: delete STA, mac_id=2
Jun 11 21:56:34 bpir1 kernel: update_bcn_fixed_ie
Jun 11 21:56:34 bpir1 kernel: bss_cap_update_on_sta_leave, updated=1
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption(), sta has already been removed or never been added
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption(), sta has already been removed or never been added
Jun 11 21:56:34 bpir1 hostapd[9257]: wlan0: STA 2c:44:fd:71:31:4c IEEE 802.11: disassociated
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption
Jun 11 21:56:34 bpir1 kernel: rtw_set_encryption(), sta has already been removed or never been added
Jun 11 21:56:34 bpir1 kernel: rtw_del_sta=2c:44:fd:71:31:4c
Jun 11 21:56:34 bpir1 kernel: rtw_del_sta(), sta has already been removed or never been added
Jun 11 21:56:34 bpir1 hostapd[9257]: rtl871x_set_key_ops
Jun 11 21:56:34 bpir1 hostapd[9257]: wlan0: STA 2c:44:fd:71:31:4c IEEE 802.11: disassociated
Jun 11 21:56:34 bpir1 hostapd[9257]: rtl871x_set_key_ops
Jun 11 21:56:34 bpir1 hostapd[9257]: rtl871x_set_key_ops
Jun 11 21:56:34 bpir1 hostapd[9257]: +rtl871x_sta_remove_ops, 2c:44:fd:71:31:4c is sta address removed

[conloos]

Hi,

i found no solution. In my case the restart of hostapd didn't help. I have to reboot the whole system.

Greetings Frank

[schaubl]

Hi,
First thanks a lot @jekader for this repo which allowed me to make an AP with my BPi-R1 in less than 5 minutes.

Unfortunately I have the same issue as others in this thread.

My configuration is the following:

• HW: Banana Pi R1
• OS: bananian
• No HDD
• Power supply of 2000 mAh (only 1 A is used)
• dnsmasq

I can ensure that the issue is not related to the DHCP.
As @conloos, I realized that the issue happens when the amount of data transferred is high (ex 20 Mb/s for ~15 seconds).

To replicate the issue I'm using a speedtest application.

On android when the AP doesn't work correctly, it think that the password is wrong.
So it's probably related to the authentication phase.

I will be happy to run some tests or provides some logs if somebody has an idea of how to find/understand this issue.

[jekader]

@schaubl thanks for the steps - I was able to reproduce similar behavior using iperf. The first thing I noted was that the client stops receiving any replies from the AP when this is triggered. The AP seems to receive and send traffic however. Re-associating to the access point fixed the problem for me.

I'm not sure how a userspace app like hostapd might be causing this, I think the kernel module is causing this. To completely reload it I'd suggest running this:

/etc/init.d/hostapd stop && rmmod 8129cu && modprobe 8129cu && /etc/init.d/hostapd start

[fabiocannizzo]

In my case there is no need to remove/reload the driver. The following sequence works:

1. stop hostapd
2. ifconfig wlan0 down
3. start hostapd

It would be nice if I had a way to detect programmatically that the AP has become not responsive. I thought about starting a job which listen to the journal and grep for some specific messages which appears when the AP is not working, but not during normal operations. Unfortunately I could not identify any such message. All the messages in the log above, seems to appear also during normal operations.