I have some new info, in case someone knowledgable in how a roam should look like in the logs wants to have a look:
I have written an ESP32 firmware now that connects to the WLAN, and once it succeeds, it pings a host on the same LAN (not WLAN) and also maintains a permanent connection to a TCP echo service (port 7) of that server where it sends and receives a byte every second. Finally the ESP monitors RSSI and reports if it changes by more than 5. All of this is written to the same remote syslog that the AP's use, to have a consolidated view of what happens during roaming on the APs (ax1, ax2) and the STA (Roamer).
This is the first start of the ESP near AP 1 after being off over night: immediate connection - fine!
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authentication OK (open system)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-AUTHENTICATE.indication(24:a1:60:54:37:d4, OPEN_SYSTEM)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authenticated
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: association OK (aid 8)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: associated (aid 8)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-ASSOCIATE.indication(24:a1:60:54:37:d4)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: binding station to interface 'wlan2'
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: event 1 notification
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: start authentication
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.1X: unauthorizing port
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: sending 1/4 msg of 4-Way Handshake
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: received EAPOL-Key frame (2/4 Pairwise)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: sending 3/4 msg of 4-Way Handshake
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: received EAPOL-Key frame (4/4 Pairwise)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.1X: authorizing port
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session 25DB6ABA0E4AA074
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4
2021-07-16T09:46:05+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:46:05+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:46:05.357187+02:00 Roamer-5437D4 Roamer Host Roamer-5437D4 1.7 started with IP 192.168.1.179
2021-07-16T09:46:05.357187+02:00 Roamer-5437D4 Roamer Connect at 2021-07-16 09:46:05
2021-07-16T09:46:05.365995+02:00 Roamer-5437D4 Roamer RSSI -> -64 at 2021-07-16 09:46:05
2021-07-16T09:46:06.046985+02:00 Roamer-5437D4 Roamer Echo disconnect at 1900-01-00 00:00:00
2021-07-16T09:46:06.055725+02:00 Roamer-5437D4 Roamer Echo ok at 2021-07-16 09:46:06
2021-07-16T09:46:07.071089+02:00 Roamer-5437D4 Roamer No ping at 1900-01-00 00:00:00
2021-07-16T09:46:07.078153+02:00 Roamer-5437D4 Roamer Ping ok at 2021-07-16 09:46:07
2021-07-16T09:46:16.877529+02:00 Roamer-5437D4 Roamer RSSI -> -59 at 2021-07-16 09:46:16
Now I move the ESP from AP 1 to near AP 2: the AP 2 and ESP start connection and try a DHCP handshake (DHCP is on AP 1) but never fully succeed (skiped the middle part - it just repeats) until for some reason a weak connection to AP 1 is tried and immediately succeeds:
2021-07-16T09:52:17.194696+02:00 Roamer-5437D4 Roamer RSSI -> -72 at 2021-07-16 09:52:17
2021-07-16T09:52:17.305858+02:00 Roamer-5437D4 Roamer RSSI -> -77 at 2021-07-16 09:52:17
2021-07-16T09:52:17.719723+02:00 Roamer-5437D4 Roamer RSSI -> -84 at 2021-07-16 09:52:17
2021-07-16T09:52:17.909847+02:00 Roamer-5437D4 Roamer RSSI -> -78 at 2021-07-16 09:52:17
2021-07-16T09:52:18.903096+02:00 Roamer-5437D4 Roamer RSSI -> -89 at 2021-07-16 09:52:18
2021-07-16T09:52:18.930983+02:00 Roamer-5437D4 Roamer RSSI -> -83 at 2021-07-16 09:52:18
2021-07-16T09:52:19.465451+02:00 Roamer-5437D4 Roamer RSSI -> -90 at 2021-07-16 09:52:19
2021-07-16T09:52:25+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disconnected due to excessive missing ACKs
2021-07-16T09:52:25+02:00 ax1 hostapd: wlan2: AP-STA-DISCONNECTED 24:a1:60:54:37:d4
2021-07-16T09:52:25+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DISASSOCIATE.indication(24:a1:60:54:37:d4, 34)
2021-07-16T09:52:25+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DISASSOCIATE.indication(24:a1:60:54:37:d4, 4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DISASSOCIATE.indication(24:a1:60:54:37:d4, 4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DISASSOCIATE.indication(24:a1:60:54:37:d4, 4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DISASSOCIATE.indication(24:a1:60:54:37:d4, 4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DISASSOCIATE.indication(24:a1:60:54:37:d4, 4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DISASSOCIATE.indication(24:a1:60:54:37:d4, 4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DISASSOCIATE.indication(24:a1:60:54:37:d4, 4)
2021-07-16T09:52:29+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:52:31+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authenticated
2021-07-16T09:52:31+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: associated (aid 3)
2021-07-16T09:52:31+02:00 ax2 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T09:52:31+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session BF50C3FB2EE7A4ED
2021-07-16T09:52:31+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T09:52:31+02:00 ax2 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4
2021-07-16T09:52:31+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:31+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:52:31+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:31+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:52:32+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:32+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:52:32+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:32+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:52:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:52:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:52:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:35+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:52:35+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:35+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:52:35+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:36+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:52:36+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:36+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:52:36+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:38+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:52:38+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:38+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:52:38+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:52:39+02:00 ax2 hostapd: wlan2: AP-STA-DISCONNECTED 24:a1:60:54:37:d4
... repeating retries for ~40s, until...
2021-07-16T09:53:19+02:00 ax2 hostapd: wlan2: AP-STA-DISCONNECTED 24:a1:60:54:37:d4
2021-07-16T09:53:19+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T09:53:20+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authentication OK (open system)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-AUTHENTICATE.indication(24:a1:60:54:37:d4, OPEN_SYSTEM)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authenticated
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: association OK (aid 8)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: associated (aid 8)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-ASSOCIATE.indication(24:a1:60:54:37:d4)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: binding station to interface 'wlan2'
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: event 1 notification
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: start authentication
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.1X: unauthorizing port
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: sending 1/4 msg of 4-Way Handshake
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: received EAPOL-Key frame (2/4 Pairwise)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: sending 3/4 msg of 4-Way Handshake
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: received EAPOL-Key frame (4/4 Pairwise)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.1X: authorizing port
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session D687E1781612588F
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T09:53:21+02:00 ax1 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4
2021-07-16T09:53:21+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:53:21+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:56:08.502404+02:00 Roamer-5437D4 Roamer RSSI -> -87 at 2021-07-16 09:56:07
2021-07-16T09:56:08.585764+02:00 Roamer-5437D4 Roamer Echo disconnect at 2021-07-16 09:52:22
2021-07-16T09:56:08.603748+02:00 Roamer-5437D4 Roamer Echo ok at 2021-07-16 09:56:08
2021-07-16T09:56:09.551902+02:00 Roamer-5437D4 Roamer No ping at 2021-07-16 09:52:28
2021-07-16T09:56:09.558300+02:00 Roamer-5437D4 Roamer Ping ok at 2021-07-16 09:56:09
2021-07-16T09:56:12.213865+02:00 Roamer-5437D4 Roamer RSSI -> -92 at 2021-07-16 09:56:12
Due to the connection to AP 1 is very weak, it is dropped (as expected/wished), but connect to AP 2 again does not work:
2021-07-16T09:56:19.990328+02:00 Roamer-5437D4 Roamer RSSI -> -92 at 2021-07-16 09:56:19
2021-07-16T09:56:20.716446+02:00 Roamer-5437D4 Roamer RSSI -> -86 at 2021-07-16 09:56:20
2021-07-16T09:56:28+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disconnected due to excessive missing ACKs
2021-07-16T09:56:28+02:00 ax1 hostapd: wlan2: AP-STA-DISCONNECTED 24:a1:60:54:37:d4
2021-07-16T09:56:28+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DISASSOCIATE.indication(24:a1:60:54:37:d4, 34)
2021-07-16T09:56:28+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 MLME: MLME-DELETEKEYS.request(24:a1:60:54:37:d4)
2021-07-16T09:56:31+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authenticated
2021-07-16T09:56:31+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: associated (aid 6)
2021-07-16T09:56:31+02:00 ax2 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T09:56:31+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session 90BE97C4500ADD0F
2021-07-16T09:56:31+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T09:56:31+02:00 ax2 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4
2021-07-16T09:56:31+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:31+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:56:31+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:31+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:56:32+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:32+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:56:32+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:32+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:56:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:34+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:36+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:36+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:36+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:36+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:38+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:38+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:38+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:38+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:39+02:00 ax2 hostapd: wlan2: AP-STA-DISCONNECTED 24:a1:60:54:37:d4
2021-07-16T09:56:39+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T09:56:40+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
2021-07-16T09:56:41+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authenticated
2021-07-16T09:56:41+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: associated (aid 6)
2021-07-16T09:56:41+02:00 ax2 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T09:56:41+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session 928DA38871ADC3F0
2021-07-16T09:56:41+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T09:56:41+02:00 ax2 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4
2021-07-16T09:56:41+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:41+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:56:41+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:41+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:56:42+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:42+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:56:42+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:42+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T09:56:44+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:44+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:44+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:44+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:45+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:45+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:45+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:45+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:46+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:46+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:46+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:46+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:48+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:48+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:48+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T09:56:48+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T09:56:49+02:00 ax2 hostapd: wlan2: AP-STA-DISCONNECTED 24:a1:60:54:37:d4
....
- Another walk to AP 1 -> immediate connection.
- Another walk to AP 2 -> back in the reconnect loop until finally, after 3.5 min magic happens: AP 2 connects:
2021-07-16T10:24:49+02:00 ax2 hostapd: wlan2: AP-STA-DISCONNECTED 24:a1:60:54:37:d4
2021-07-16T10:24:49+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T10:24:50+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
2021-07-16T10:24:51+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authenticated
2021-07-16T10:24:51+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: associated (aid 2)
2021-07-16T10:24:51+02:00 ax2 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T10:24:51+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session 9FED695DDFD9516F
2021-07-16T10:24:51+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T10:24:51+02:00 ax2 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4
2021-07-16T10:24:51+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:51+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T10:24:51+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:51+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T10:24:52+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:52+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T10:24:52+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:52+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T10:24:54+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T10:24:54+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:54+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T10:24:54+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:54+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T10:24:54+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:54+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T10:24:54+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:55+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T10:24:55+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:55+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T10:24:55+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:57+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T10:24:57+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:57+02:00 ax1 dnsmasq-dhcp[3348]: DHCPDISCOVER(br-lan) 24:a1:60:54:37:d4
2021-07-16T10:24:57+02:00 ax1 dnsmasq-dhcp[3348]: DHCPOFFER(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:24:59+02:00 ax2 hostapd: wlan2: AP-STA-DISCONNECTED 24:a1:60:54:37:d4
2021-07-16T10:24:59+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disassociated
2021-07-16T10:25:00+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
2021-07-16T10:25:01+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authenticated
2021-07-16T10:25:01+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: associated (aid 2)
2021-07-16T10:25:01+02:00 ax2 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T10:25:01+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session D39FB07693605E49
2021-07-16T10:25:01+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T10:25:01+02:00 ax2 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4
2021-07-16T10:25:01+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:25:01+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T10:25:01+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T10:25:01+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T10:25:01.894453+02:00 Roamer-5437D4 Roamer Disconnect at 2021-07-16 10:21:30
2021-07-16T10:25:01.899916+02:00 Roamer-5437D4 Roamer Connect at 2021-07-16 10:25:01
2021-07-16T10:25:01.911294+02:00 Roamer-5437D4 Roamer RSSI -> -42 at 2021-07-16 10:25:01
2021-07-16T10:25:02.068027+02:00 Roamer-5437D4 Roamer Echo disconnect at 2021-07-16 10:17:19
2021-07-16T10:25:02.080761+02:00 Roamer-5437D4 Roamer Echo ok at 2021-07-16 10:25:02
2021-07-16T10:25:03.480361+02:00 Roamer-5437D4 Roamer No ping at 2021-07-16 10:21:25
2021-07-16T10:25:03.487365+02:00 Roamer-5437D4 Roamer Ping ok at 2021-07-16 10:25:03
2021-07-16T10:53:20.813430+02:00 Roamer-5437D4 Roamer RSSI -> -55 at 2021-07-16 10:53:20
but it is not stable. I see sporadic reconnects:
2021-07-16T11:11:51.545730+02:00 Roamer-5437D4 Roamer RSSI -> -40 at 2021-07-16 11:11:51
2021-07-16T11:30:02+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: disconnected due to excessive missing ACKs
2021-07-16T11:30:02+02:00 ax2 hostapd: wlan2: AP-STA-DISCONNECTED 24:a1:60:54:37:d4
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: authenticated
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.11: associated (aid 2)
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session D39FB07693605E49
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4
2021-07-16T11:30:04+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T11:30:04+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T11:30:04+02:00 ax1 dnsmasq-dhcp[3348]: DHCPREQUEST(br-lan) 192.168.1.179 24:a1:60:54:37:d4
2021-07-16T11:30:04+02:00 ax1 dnsmasq-dhcp[3348]: DHCPACK(br-lan) 192.168.1.179 24:a1:60:54:37:d4 Roamer-5437D4
2021-07-16T11:30:06.466075+02:00 Roamer-5437D4 Roamer RSSI -> 0 at 2021-07-16 11:30:02
2021-07-16T11:30:06.486225+02:00 Roamer-5437D4 Roamer RSSI -> -40 at 2021-07-16 11:30:06
I do not see any reason for the disconnects, not for the connect loops and not why connect to AP 2 finally succeeds. Any way to crank up log level?
The only difference I see between connects to AP 1 vs AP 2 is right before the respective EAPOL-4WAY-HS-COMPLETED messages. Could that be a hint?:
AP 1:
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 IEEE 802.1X: authorizing port
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session 25DB6ABA0E4AA074
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T09:46:05+02:00 ax1 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4
AP 2: (missing: IEEE 802.1X: authorizing port)
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: AP-STA-CONNECTED 24:a1:60:54:37:d4
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 RADIUS: starting accounting session D39FB07693605E49
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: STA 24:a1:60:54:37:d4 WPA: pairwise key handshake completed (RSN)
2021-07-16T11:30:04+02:00 ax2 hostapd: wlan2: EAPOL-4WAY-HS-COMPLETED 24:a1:60:54:37:d4