adafruit_requests.get() results in OSError:0 from SocketPool.getaddrinfo()

[askpatrickw]

In a simple adafruit_requests.get() I am consistently getting a failure OSError:0.
It seems to be failing in SocketPool not requests so I'm opening this in CP.

I have reduced the case to just attempting to call SocketPool.getaddrinfo.
I confirmed I have the fix for #3576 was in common-hal/wifi/init.c on my machine.

code.py

import wifi
import socketpool

try:
    from secrets import secrets
except ImportError:
    print("WiFi secrets are kept in secrets.py, please add them there!")
    raise

for network in wifi.radio.start_scanning_networks():
    print(network, network.ssid, network.rssi, network.channel)
    if network.ssid == secrets['ssid']:
        wifi.radio.connect(secrets['ssid'], secrets['wifi_password'])
wifi.radio.stop_scanning_networks()

print("ip", wifi.radio.ipv4_address)

pool = socketpool.SocketPool(wifi.radio)
print(f"get_addrinfo: {pool.getaddrinfo('wifitest.adafruit.com', 80)}")

Result

code.py output:
<Network> deepplaya_IoT -33 6
<Network> deepplaya_IoT -50 6
<Network> hoodinternet_old -57 6
<Network> Wi-Fi_Name -76 6
<Network> AccioWifi -80 6
<Network> Sea2019 -86 6
ip 192.168.1.35
Traceback (most recent call last):
  File "code.py", line 19, in <module>
OSError: 0

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x3 (DOWNLOAD(USB/UART0/1/SPI))
waiting for download
ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x3ffe6100,len:0x8
load:0x3ffe6108,len:0x1898
load:0x4004c000,len:0x930
load:0x40050000,len:0x2cc8
entry 0x4004c1b4

Debug Result

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
... snip ....
I (48) boot: ESP-IDF v4.3-dev-1197-g8bc19ba89 2nd stage bootloader
... snip ....
I (2052) wifi:wifi driver task: 3ffff0e8, prio:23, stack:3584, core=0
I (2052) system_api: Base MAC address is not set
I (2052) system_api: read default base MAC address from EFUSE
I (2052) wifi:wifi firmware version: d3be909
I (2062) wifi:wifi certification version: v7.0
I (2062) wifi:config NVS flash: disabled
I (2062) wifi:config nano formating: disabled
I (2072) wifi:Init data frame dynamic rx buffer num: 32
I (2072) wifi:Init management frame dynamic rx buffer num: 32
I (2082) wifi:Init management short buffer num: 32
I (2082) wifi:Init dynamic tx buffer num: 32
I (2092) wifi:Init tx cache buffer num: 32
I (2092) wifi:Init static rx buffer size: 1600
I (2102) wifi:Init static rx buffer num: 10
I (2102) wifi:Init dynamic rx buffer num: 32
I (2102) wifi_init: rx ba win: 6
I (2112) wifi_init: tcpip mbox: 32
I (2112) wifi_init: udp mbox: 6
I (2112) wifi_init: tcp mbox: 6
I (2122) wifi_init: tcp tx win: 5744
I (2122) wifi_init: tcp rx win: 5744
I (2132) wifi_init: tcp mss: 1440
I (2132) wifi_init: WiFi IRAM OP enabled
I (2142) wifi_init: WiFi RX IRAM OP enabled
I (2302) phy: phy_version: 603, 72dfd77, Jul  7 2020, 19:57:05, 0, 2
I (2302) wifi:enable tsf
I (2302) wifi:mode : softAP (7c:df:a1:02:64:1f)
I (2302) wifi:Total power save buffer number: 16
I (2312) wifi:Init max length of beacon: 752/752
I (2312) wifi:Init max length of beacon: 752/752
I (2392) wifi:mode : sta (7c:df:a1:02:64:1e)
I (3252) wifi:new:<6,0>, old:<1,1>, ap:<255,255>, sta:<6,0>, prof:1
I (3722) wifi:state: init -> auth (b0)
I (3732) wifi:state: auth -> assoc (0)
I (3742) wifi:state: assoc -> run (10)
I (3752) wifi:connected with deepplaya_IoT, aid = 1, channel 6, BW20, bssid = 74:ac:b9:a5:83:b9
I (3752) wifi:security: WPA2-PSK, phy: bgn, rssi: -32
I (3752) wifi:pm start, type: 1

W (3762) wifi: connected
I (3812) wifi:AP's beacon interval = 102400 us, DTIM period = 3
I (6042) esp_netif_handlers: sta ip: 192.168.1.35, mask: 255.255.255.0, gw: 192.168.1.1
W (6042) wifi: got ip
I (6112) wifi:state: run -> init (0)
I (6112) wifi:pm stop, total sleep time: 1623928 us / 2350443 us

I (6112) wifi:new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1
W (6112) wifi:hmac tx: stop, discard
W (6122) wifi: disconnected
W (6122) wifi: reason 8 0x08
I (6162) wifi:flush txq
I (6162) wifi:stop sw txq
I (6162) wifi:lmac stop hw txq
I (6162) wifi:Deinit lldesc rx mblock:10

abort() was called at PC 0x400b3425 on core 0

Backtrace:0x4002f586:0x3ffdbda0 0x4002fabd:0x3ffdbdc0 0x400374da:0x3ffdbde0 0x400b3425:0x3ffdbe50 0x4009e6d3:0x3ffdbe70 0x4009e2f8:0x3ffdbe90 0x4009e39c:0x3ffdbeb0 0x4009e618:0x3ffdbf00 0x4009e80f:0x3ffdbf20 0x4002facc:0x3ffdbf40


ELF file SHA256: 3e8a8e1ca43639e0

CPU halted.

Backtrace Decoded

python tools/decode_backtrace.py espressif_kaluga_1
espressif_kaluga_1
? Backtrace:0x4002f586:0x3ffdbda0 0x4002fabd:0x3ffdbdc0 0x400374da:0x3ffdbde0 0x400b3425:0x3ffdbe50 0x4009e6d3:0x3ffdbe70 0x4009e2f8:0x3ffdbe90 0x4009e39c:0x3ffdbeb0 0x4009e618:0x3ffdbf00 0x4009e80f:0x3ffdbf20 0x4002facc:0x3ffdbf40
got ['0x4002f586', '0x4002fabd', '0x400374da', '0x400b3425', '0x4009e6d3', '0x4009e2f8', '0x4009e39c', '0x4009e618', '0x4009e80f', '0x4002facc']
.../circuitpython/ports/esp32s2/build-espressif_kaluga_1/esp-idf/../../esp-idf/components/esp_system/panic.c:360
.../circuitpython/ports/esp32s2/build-espressif_kaluga_1/esp-idf/../../esp-idf/components/esp_system/system_api.c:104
.../circuitpython/ports/esp32s2/build-espressif_kaluga_1/esp-idf/../../esp-idf/components/newlib/abort.c:46
.../circuitpython/ports/esp32s2/common-hal/wifi/__init__.c:147 (discriminator 1)
.../circuitpython/ports/esp32s2/supervisor/port.c:123
.../circuitpython/ports/esp32s2/../../main.c:237
.../circuitpython/ports/esp32s2/../../main.c:296
.../circuitpython/ports/esp32s2/../../main.c:515
.../circuitpython/ports/esp32s2/supervisor/port.c:213
.../circuitpython/ports/esp32s2/build-espressif_kaluga_1/esp-idf/../../esp-idf/components/freertos/xtensa/port.c:535

[askpatrickw]

I am re-opening this because I have a consistent repo of a simple case

[anecdata]

Works for me on Saola-R. If I read the debug log above correctly, the station is disconnecting (8==disassoc) prior to the abort, but I see no reason why it should.

Addendum: Adafruit CircuitPython 6.0.0-rc.0 on 2020-10-16; Saola 1 w/Wrover with ESP32S2

[askpatrickw]

I'll try one more time with builds off the S3 bucket.

[askpatrickw]

@anecdata are you seeing #3580 ?

Kaluga worked better with adafruit-circuitpython-espressif_kaluga_1-en_US-20201023-c676385.bin
I only saw 3 failures out of 20 attempts, and only after a Reset, not a CTRL-D. I wasn't pounding away I waited 5-10 seconds before any reload\reset.

UMFeatherS2_PreRelease adafruit-circuitpython-unexpectedmaker_feathers2_prerelease-en_US-20201023-c676385.bin
Initially, It failed more frequently >50% of the time and not any noticeable improvement between a reload and a reset. But after a few minutes it improve and worked as well as the Kaluga did.
Also, I had previously tried the build just before ^^ that one (2581d09) and it failed all the time as before.

Verified in my git log that I'm at the same commit level (?) as main c676385 so unclear why local build would behave differently.

Check IDF ... there were updates and there's a wifi related update in updated IDF submodules. ⬅️ 🤦‍♂️
Built and flashed FeatherS2. Failed on initial reset after flash, on soft reboot (I didn't do that one) and on reload 2 times.
Reset. It worked. Reload it worked. 10 Reloads in a row worked.
Reset. It worked.

OK.. I still thing there is something here, but It is also WAY improved. I think there are other open issues tracking "weird things", so I'm calling this my bad build environment and closing.

[anecdata]

@askpatrickw I haven't spent much time testing #3580. I'm mostly still using rc.0, seeing some "weird things" on certain boards, but need to run them down more.