Connected users to chilli hotspot disconnects

[domasgim]

Summary

A user is connected to a hotspot network but gets disconnected at random times (after 1-10 minutes when user stops using internet). I have done extensive testing using an iPhone as the client.

Using the internet regularly such as watching YouTube videos there is no such problem but whenever the user stops, they can get disconnected from the chilli hotspot. I have noticed (not always though) that whenever I turn off the phone's screen the user gets disconnected and when the screen is turned on the user is immediately connected back again. I would guess that this is a problem with the phone itself but I have managed to reproduce the same behavior using a laptop as the client (running Ubuntu 20.04). When using the laptop, a connected user would disconnect when they would stop using the internet after some time.

Version

CoovaChilli-v1.4 / coova-chilli 0.2b

Wireshark

I have tried to inspect the TCP packets using Wireshark of the iPhone user but have not found anything insightful other than that there are regular RST packets sent to and from the connected client. The attached picture shows the exact time the first LOGOUT appears as seen on the later logs from hostapd:

OpenWRT logs

Here are some additional logs from the router itself, here it can be seen that hostapd keeps disconnecting and connecting the client

LOGIN
Wed Jul 20 08:52:57 2022 [1658296377.945] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: authenticated
Wed Jul 20 08:52:57 2022 [1658296377.948] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: associated (aid 1)
Wed Jul 20 08:52:57 2022 [1658296377.971] daemon.notice hostapd: wlan1: AP-STA-CONNECTED 44:35:83:6e:97:18
Wed Jul 20 08:52:57 2022 [1658296377.974] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 RADIUS: starting accounting session 2357F446630DA3DD
Wed Jul 20 08:52:57 2022 [1658296377.974] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 WPA: pairwise key handshake completed (RSN)

LOGOUT (Wireshark logs time)
Wed Jul 20 08:58:38 2022 [1658296718.329] daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 44:35:83:6e:97:18
Wed Jul 20 08:58:38 2022 [1658296718.335] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: disassociated
Wed Jul 20 08:58:39 2022 [1658296719.338] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

LOGIN
Wed Jul 20 08:59:10 2022 [1658296750.619] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: authenticated
Wed Jul 20 08:59:10 2022 [1658296750.623] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: associated (aid 1)
Wed Jul 20 08:59:10 2022 [1658296750.631] daemon.notice hostapd: wlan1: AP-STA-CONNECTED 44:35:83:6e:97:18
Wed Jul 20 08:59:10 2022 [1658296750.633] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 RADIUS: starting accounting session CD3D5F55FDF76F21
Wed Jul 20 08:59:10 2022 [1658296750.634] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 WPA: pairwise key handshake completed (RSN)

LOGOUT
Wed Jul 20 09:03:31 2022 [1658297011.258] daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 44:35:83:6e:97:18
Wed Jul 20 09:03:31 2022 [1658297011.259] daemon.debug chilli[5974]: hostapd_event_handle(415): found 192.168.2.11 62d7983a00000001
Wed Jul 20 09:03:31 2022 [1658297011.261] daemon.err chilli[5974]: chilli[5974]: hostapd_event_handle(415): found 192.168.2.11 62d7983a00000001
Wed Jul 20 09:03:31 2022 [1658297011.265] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: disassociated
Wed Jul 20 09:03:31 2022 [1658297011.268] daemon.debug chilli[5974]: hostapd_event_handle(415): found 192.168.2.11 62d79ab300000001
Wed Jul 20 09:03:31 2022 [1658297011.268] daemon.err chilli[5974]: chilli[5974]: hostapd_event_handle(415): found 192.168.2.11 62d79ab300000001
Wed Jul 20 09:03:32 2022 [1658297012.273] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

LOGIN
Wed Jul 20 09:03:54 2022 [1658297034.243] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: authenticated
Wed Jul 20 09:03:54 2022 [1658297034.248] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: associated (aid 1)
Wed Jul 20 09:03:54 2022 [1658297034.255] daemon.notice hostapd: wlan1: AP-STA-CONNECTED 44:35:83:6e:97:18
Wed Jul 20 09:03:54 2022 [1658297034.258] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 RADIUS: starting accounting session FD8587857F4A1E6E
Wed Jul 20 09:03:54 2022 [1658297034.258] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 WPA: pairwise key handshake completed (RSN)

LOGOUT
Wed Jul 20 09:04:05 2022 [1658297045.599] daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 44:35:83:6e:97:18
Wed Jul 20 09:04:05 2022 [1658297045.604] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: disassociated
Wed Jul 20 09:04:06 2022 [1658297046.607] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

LOGIN
Wed Jul 20 09:04:16 2022 [1658297056.307] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: authenticated
Wed Jul 20 09:04:16 2022 [1658297056.311] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: associated (aid 1)
Wed Jul 20 09:04:16 2022 [1658297056.319] daemon.notice hostapd: wlan1: AP-STA-CONNECTED 44:35:83:6e:97:18
Wed Jul 20 09:04:16 2022 [1658297056.322] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 RADIUS: starting accounting session EFAB5E7AF2156E05
Wed Jul 20 09:04:16 2022 [1658297056.323] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 WPA: pairwise key handshake completed (RSN)

LOGOUT
Wed Jul 20 09:04:16 2022 [1658297056.627] daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 44:35:83:6e:97:18
Wed Jul 20 09:04:16 2022 [1658297056.632] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: disassociated
Wed Jul 20 09:04:17 2022 [1658297057.635] daemon.info hostapd: wlan1: STA 44:35:83:6e:97:18 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

Other notes

I have looked around the chilli code while debugging and noticed when the disconnect happens, the logs sometimes say Freeing RADIUS packet. It gets called by this macro:

coova-chilli/src/radius.c

Line 423 in 7dee2ff

RADIUS_QUEUE_PKTFREE(this->queue[idx].p);

Unfortunately, this does not always appear when the user gets disconnected.

I have searched for simmilar issues with no success and tried to change settings regarding different timeout settings with no success either.

[xewonder]

Check this
https://www.oreilly.com/library/view/radius/0596003226/re24.html

[alfredamb]

Check this
--lease=INT Lease time to allocate to clients (default=`600')