ESP32-S3: Wifi STA status() returning 4 (WIFI_REASON_ASSOC_EXPIRE) upon initial connect attempt

[ned-pcs]

I am seeing the wifi STA status() method returning 4 upon connection attempts. This does not correspond with any known network.STAT_xxx values. Subsequent connection attempts return valid status codes. Has anyone seen this? What does it mean?

EDIT: I just saw a code of 39 too.

My code:

def _fatal_sta_status(status: int) -> bool:
    return status in [
        network.STAT_NO_AP_FOUND,
        network.STAT_WRONG_PASSWORD,
        network.STAT_BEACON_TIMEOUT,
        network.STAT_ASSOC_FAIL,
        network.STAT_HANDSHAKE_TIMEOUT,
    ]

Class WifiManager:
    def __init__(self):
        self.sta = network.WLAN(network.STA_IF)
        self.ap = network.WLAN(network.AP_IF)
        self.sta_ssid = None
        self.sta_password = None
        self.sta_ip = None
        self.mdns_client = None
        self.mdns_responder = None
        self.event_queue = Queue(2)

        # STA always active
        self.sta.active(True)
        self.sta.config(reconnects=0)  # Disable auto-reconnect
        self._sta_lock = _thread.allocate_lock()
        self._sta_lock.acquire()

        # AP only active in pairing state
        self._disable_ap()

        # Async scan (acquires self._sta_lock before running)
        self._scan_result = Message()
        self._scan_complete_evt = asyncio.Event()
        self._scan_complete_evt.set()
        self._scan_thread = _thread.start_new_thread(self._scan, ())
        self._scan_results = []

    async def _sta_connect(self, timeout_ms: int = _CONNECTION_TIMEOUT_MS) -> bool:
        log.info(f'Connecting to network "{self.sta_ssid}"...')
        self.sta.active(True)
        self.sta.connect(self.sta_ssid, self.sta_password)
        tick = time.ticks_ms()
        while not self.sta.isconnected():
            stat = self.sta.status()
            if _fatal_sta_status(stat) or (
                timeout_ms != 0 and time.ticks_diff(time.ticks_ms(), tick) > timeout_ms
            ):
                self._sta_disconnect()
                log.warning(f"Wifi STA connection timeout [status={self.sta.status()}]")
                return False
            await asyncio.sleep(0.1)
        # ip, subnet, gateway, dns
        ifconfig = self.sta.ifconfig()
        # wait until no members of ifconfig are "0.0.0.0":
        while any([x == "0.0.0.0" for x in ifconfig]):
            if timeout_ms != 0 and time.ticks_diff(time.ticks_ms(), tick) > timeout_ms:
                self._sta_disconnect()
                log.warning(
                    f"Wifi STA connection timeout [ifconfig={self.sta.ifconfig()}]"
                )
                return False
            ifconfig = self.sta.ifconfig()
            await asyncio.sleep(0.1)
        self.sta_ip = ifconfig[0]
        log.info(f"Connection successful to {self.sta_ssid}: {ifconfig}")
        return True

I am using the current Micropython development version:

MicroPython v1.23.0-preview.37.gc2887ad3a on 2024-01-11; Generic ESP32S3 module with Octal-SPIRAM with ESP32S3

[ned-pcs]

After a bit of research:
Reason 4 is WIFI_REASON_ASSOC_EXPIRE (see ports/esp32/network_wlan.c line 121 and esp-idf/components/esp_wifi/include/esp_wifi_types.h line 70).
I don't know what this means though, or how to fix it.
Reason 39 is WIFI_REASON_TIMEOUT.

Here is a UART debug log and the corresponding application log showing the disconnection and a later manual reconnection.

=========== UART debug (times in ms) ====================

ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0xc (RTC_SW_CPU_RST),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x42002c16
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3810,len:0xf8c
load:0x403c9700,len:0xb3c
load:0x403cc700,len:0x2dd4
entry 0x403c989c
I (4963) modsocket: Initializing
I (5453) pp: pp rom version: e7ae62f
I (5453) net80211: net80211 rom version: e7ae62f
I (5463) wifi:wifi driver task: 3fcf7c0c, prio:23, stack:6656, core=0
I (5463) system_api: Base MAC address is not set
I (5463) system_api: read default base MAC address from EFUSE
I (5473) wifi:wifi firmware version: e2d0ad8
I (5473) wifi:wifi certification version: v7.0
I (5483) wifi:config NVS flash: enabled
I (5483) wifi:config nano formating: disabled
I (5483) wifi:Init data frame dynamic rx buffer num: 32
I (5493) wifi:Init management frame dynamic rx buffer num: 32
I (5493) wifi:Init management short buffer num: 32
I (5503) wifi:Init static tx buffer num: 16
I (5503) wifi:Init tx cache buffer num: 32
I (5513) wifi:Init static tx FG buffer num: 2
I (5513) wifi:Init static rx buffer size: 1600
I (5513) wifi:Init static rx buffer num: 10
I (5523) wifi:Init dynamic rx buffer num: 32
I (5523) wifi_init: rx ba win: 6
I (5533) wifi_init: tcpip mbox: 32
I (5533) wifi_init: udp mbox: 6
I (5533) wifi_init: tcp mbox: 6
I (5543) wifi_init: tcp tx win: 5744
I (5543) wifi_init: tcp rx win: 5744
I (5553) wifi_init: tcp mss: 1440
I (5553) phy_init: phy_version 610,2bff4c8,Jul 27 2023,20:22:14
I (5593) wifi:mode : sta (34:85:18:73:5f:54)
I (5593) wifi:enable tsf
I (5593) wifi: STA_START
I (7883) wifi:flush txq
I (7883) wifi:stop sw txq
I (7883) wifi:lmac stop hw txq
I (7893) wifi:mode : sta (34:85:18:73:5f:54)
I (7893) wifi:enable tsf
I (7893) wifi: STA_START
I (8263) wifi:new:<4,0>, old:<1,0>, ap:<255,255>, sta:<4,0>, prof:1
I (8983) wifi:state: init -> auth (b0)
I (8983) wifi:state: auth -> assoc (0)
I (8983) wifi:state: assoc -> run (10)
I (9003) wifi:<ba-add>idx:0 (ifx:0, 1c:b7:2c:db:fa:c0), tid:0, ssn:0, winSize:64
I (9023) wifi:connected with PCS, aid = 5, channel 4, BW20, bssid = 1c:b7:2c:db:fa:c0
I (9023) wifi:security: WPA2-PSK, phy: bgn, rssi: -62
I (9023) wifi:pm start, type: 1

I (9023) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
I (9033) network: CONNECTED
I (9063) wifi:AP's beacon interval = 51200 us, DTIM period = 3
I (10193) wifi:state: run -> init (4c0)
I (10193) wifi:pm stop, total sleep time: 966817 us / 1164811 us

I (10193) wifi:<ba-del>idx
I (10193) wifi:new:<4,0>, old:<4,0>, ap:<255,255>, sta:<4,0>, prof:1
I (10193) wifi: STA_DISCONNECTED, reason:4:
I (10203) wifi: reconnect counter=0, max=1
I (37993) wifi:flush txq
I (37993) wifi:stop sw txq
I (37993) wifi:lmac stop hw txq
I (38143) wifi:mode : sta (34:85:18:73:5f:54)
I (38143) wifi:enable tsf
I (38143) wifi: STA_START
I (38163) wifi:new:<4,0>, old:<1,0>, ap:<255,255>, sta:<4,0>, prof:1
I (38163) wifi:state: init -> auth (b0)
I (38163) wifi:state: auth -> assoc (0)
I (38173) wifi:state: assoc -> run (10)
I (38173) wifi:<ba-add>idx:0 (ifx:0, 1c:b7:2c:db:fa:c0), tid:0, ssn:0, winSize:64
I (38193) wifi:connected with PCS, aid = 4, channel 4, BW20, bssid = 1c:b7:2c:db:fa:c0
I (38193) wifi:security: WPA2-PSK, phy: bgn, rssi: -63
I (38193) wifi:pm start, type: 1

I (38193) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
I (38203) wifi:AP's beacon interval = 51200 us, DTIM period = 3
I (38213) network: CONNECTED
I (40713) network: GOT_IP
I (40713) esp_netif_handlers: sta ip: 10.100.2.152, mask: 255.255.255.0, gw: 10.100.2.1
I (41833) wifi:state: run -> init (4c0)
I (41833) wifi:pm stop, total sleep time: 2359840 us / 3638681 us

I (41833) wifi:<ba-del>idx
I (41833) wifi:new:<4,0>, old:<4,0>, ap:<255,255>, sta:<4,0>, prof:1
I (41843) wifi: STA_DISCONNECTED, reason:4: ## WIFI_REASON_ASSOC_EXPIRE
I (41843) wifi: reconnect counter=0, max=1

### manually re-connecting after I realized that I didn't have a network connection any more

I (232843) wifi:flush txq
I (232843) wifi:stop sw txq
I (232843) wifi:lmac stop hw txq
I (232853) wifi:mode : sta (34:85:18:73:5f:54)
I (232853) wifi:enable tsf
I (232863) wifi: STA_START
I (232883) wifi:new:<4,0>, old:<1,0>, ap:<255,255>, sta:<4,0>, prof:1
I (232883) wifi:state: init -> auth (b0)
I (232883) wifi:state: auth -> assoc (0)
I (232883) wifi:state: assoc -> run (10)
I (232903) wifi:<ba-add>idx:0 (ifx:0, 1c:b7:2c:db:fa:c0), tid:0, ssn:0, winSize:64
I (232923) wifi:connected with PCS, aid = 5, channel 4, BW20, bssid = 1c:b7:2c:db:fa:c0
I (232923) wifi:security: WPA2-PSK, phy: bgn, rssi: -60
I (232923) wifi:pm start, type: 1

I (232923) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
I (232933) network: CONNECTED
I (232953) wifi:AP's beacon interval = 51200 us, DTIM period = 3
I (235433) network: GOT_IP
I (235433) esp_netif_handlers: sta ip: 10.100.2.152, mask: 255.255.255.0, gw: 10.100.2.1

========== LOG (times in seconds) ============

5.606 [wifi_manager] [INFO] Disabling AP
7.661 [socket_logger] [INFO] Awaiting client connection on port 8123
7.876 [wifi_manager] [INFO] Disconnecting STA from network "PCS"...
7.895 [wifi_manager] [INFO] Connecting to network "PCS"...
10.300 [wifi_manager] [INFO] Wifi STA status: 1001 -> 4
37.990 [wifi_manager] [WARNING] Wifi STA connection timeout [status=4]
37.994 [wifi_manager] [INFO] Disconnecting STA from network "PCS"...
38.005 [wifi_manager] [INFO] Wifi connection failed
38.009 [wifi_manager] [INFO] Wifi connection starting
38.136 [wifi_manager] [INFO] Disconnecting STA from network "PCS"...
38.140 [wifi_manager] [INFO] Connecting to network "PCS"...
40.758 [wifi_manager] [INFO] Connection successful to PCS: ('10.100.2.152', '255.255.255.0', '10.100.2.1', '192.168.2.6')
40.762 [wifi_manager] [INFO] Setting time from NTP
41.027 [wifi_manager] [INFO] Time now 758829107 seconds, 2024-01-17 17:51:47
41.030 [wifi_manager] [INFO] Time set ahead by 1 seconds
41.100 [wifi_manager] [INFO] Wifi connection complete

#### manually re-connecting after I realized that I didn't have a network connection any more

232.837 [wifi_manager] [INFO] Wifi re-connecting
232.840 [wifi_manager] [INFO] Disconnecting STA from network "PCS"...
232.855 [wifi_manager] [INFO] Connecting to network "PCS"...
235.508 [wifi_manager] [INFO] Connection successful to PCS: ('10.100.2.152', '255.255.255.0', '10.100.2.1', '192.168.2.6')
235.512 [wifi_manager] [INFO] Setting time from NTP
235.701 [wifi_manager] [INFO] Time now 758829302 seconds, 2024-01-17 17:55:02
235.704 [wifi_manager] [INFO] Time set ahead by 1 seconds