pyportal @Paul Cutler | adafruit | Page 1

fresh terrace May 20, 2024, 11:50 PM

#

starting thread

analog palm May 20, 2024, 11:54 PM

#

I have 1.7.7 firmware, and absolute latest CircuitPython as of Sunday and I used circup to update my libraries, which should be up to date. With the exclusion of adafruit_minimqtt, which has the custom code I just pasted that is allowing it to run

willow briar May 20, 2024, 11:56 PM

#

Maybe grab the newest MinMQTT, run it as is and paste the whole serial log here?

#

Also, I want to verify that there isn't a esp32spi folder in the root

analog palm May 21, 2024, 12:00 AM

#

nope, no esp32spi folder in the root

#

I apologize, I didn't realize we weren't done troubleshooting - i need to put a few lines of code back in, like the logger as i started to clean it up since it was working. I need a few minutes and I'll paste it

#

if the PyPortal reboots too many times in a short period of time, I get this error. Letting it sit for 5 minutes and then restarting it seems to work. So waiting...

Traceback (most recent call last):
  File "main.py", line 97, in <module>
  File "adafruit_requests.py", line 591, in get
  File "adafruit_requests.py", line 525, in request
  File "adafruit_connection_manager.py", line 322, in get_socket
  File "adafruit_connection_manager.py", line 234, in _get_connected_socket
  File "adafruit_connection_manager.py", line 61, in connect
  File "adafruit_esp32spi/adafruit_esp32spi_socketpool.py", line 117, in connect
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 836, in socket_connect
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 732, in socket_open
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 341, in _send_command_get_response
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 297, in _wait_response_cmd
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 206, in _wait_for_ready
TimeoutError: ESP32 not responding

willow briar May 21, 2024, 12:05 AM

#

So something strange is going on. I doubt you want to manually update MiniMQTT with each release...

analog palm May 21, 2024, 12:05 AM

#

I'd rather not. 🙂

willow briar May 21, 2024, 12:06 AM

#

That happens to me sometimes too. I usually unplug it

#

Also to confirm, you downloaded the most recent minimqtt from GitHub?

analog palm May 21, 2024, 12:12 AM

#

nope, thanks for confirming, I just used circup thinking that it was up to date. It finally rebooted, too.

willow briar May 21, 2024, 12:13 AM

#

Yeah, circup updates nightly

analog palm May 21, 2024, 12:13 AM

#

I need to stop using the sd card too, it's too slow for testing

#

ok, all set up, thank you for your patience. Booting it up now

#

I spoke too soon, ESP32 timeout again. Will paste the error as soon as it comes up

willow briar May 21, 2024, 12:19 AM

#

@fresh terrace is there a command to get the esp to fully reset?

fresh terrace May 21, 2024, 12:21 AM

#

There is the adafruit_airlift library. Are you already using that to set it up? It has a reset() method. https://docs.circuitpython.org/projects/airlift/en/latest/

analog palm May 21, 2024, 12:24 AM

#

ok! here it is:

240.908: DEBUG - Attempting to connect to MQTT broker (attempt #0)
240.910: DEBUG - Attempting to establish MQTT connection...
240.983: DEBUG - Sending CONNECT to broker...
240.985: DEBUG - Fixed Header: bytearray(b'\x10?')
240.988: DEBUG - Variable Header: bytearray(b'\x00\x04MQTT\x04\xc2\x00<')
241.142: DEBUG - Receiving CONNACK packet from broker
241.215: DEBUG - Got message type: 0x20 pkt: 0x20
Subscribing to prcutler/feeds/albumart
241.221: DEBUG - Sending SUBSCRIBE to broker...
241.224: DEBUG - Fixed Header: bytearray(b'\x82\x1c')
241.246: DEBUG - Variable Header: b'\x00\x01'
241.268: DEBUG - SUBSCRIBING to topic prcutler/feeds/albumart with QoS 0
241.271: DEBUG - payload: b'\x00\x17prcutler/feeds/albumart\x00'
241.359: DEBUG - Got message type: 0x90 pkt: 0x90
241.372: DEBUG - Resetting reconnect backoff
241.375: DEBUG - waiting for messages for 5 seconds
Traceback (most recent call last):
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 1001, in _wait_for_msg
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 1091, in _sock_exact_recv
  File "adafruit_esp32spi/adafruit_esp32spi_socketpool.py", line 183, in recv_into
timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "main.py", line 266, in <module>
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 976, in loop
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 1006, in _wait_for_msg
TypeError: function takes 3 positional arguments but 2 were given

Code done running.

#

This is the code and the displayio stuff is not commented out, this is the whole thing

📎 main.py

#

And the prcutler/feeds/albumart Adafruit IO feed is still public

fresh terrace May 21, 2024, 12:28 AM

#

and did you say that removing the displayio functionality makes it not fail?

willow briar May 21, 2024, 12:29 AM

#

Can you, after you define pool do:

ht = hasattr(pool, "timeout")
print(f"has timeout: {ht}")

#

@fresh terrace you can see, it's totally going into the non timeout block (or I'm crazy)

analog palm May 21, 2024, 12:30 AM

#

fresh terrace and did you say that removing the displayio functionality makes it not fail?

I honestly don't remember now, we've done so much - I think once we upped the heap in boot.py that fixed part of it

analog palm May 21, 2024, 12:30 AM

#

willow briar Can you, after you define `pool` do: ```py ht = hasattr(pool, "timeout") print(f...

yes, running now

willow briar May 21, 2024, 12:30 AM

#

Yeah, the heap and this timeout fix got everything running

analog palm May 21, 2024, 12:31 AM

#

latest with the ht:

679.524: DEBUG - Attempting to connect to MQTT broker (attempt #0)
679.526: DEBUG - Attempting to establish MQTT connection...
679.598: DEBUG - Sending CONNECT to broker...
679.601: DEBUG - Fixed Header: bytearray(b'\x10@')
679.604: DEBUG - Variable Header: bytearray(b'\x00\x04MQTT\x04\xc2\x00<')
679.756: DEBUG - Receiving CONNACK packet from broker
679.862: DEBUG - Got message type: 0x20 pkt: 0x20
Subscribing to prcutler/feeds/albumart
679.869: DEBUG - Sending SUBSCRIBE to broker...
679.871: DEBUG - Fixed Header: bytearray(b'\x82\x1c')
679.893: DEBUG - Variable Header: b'\x00\x01'
679.916: DEBUG - SUBSCRIBING to topic prcutler/feeds/albumart with QoS 0
679.918: DEBUG - payload: b'\x00\x17prcutler/feeds/albumart\x00'
680.007: DEBUG - Got message type: 0x90 pkt: 0x90
680.020: DEBUG - Resetting reconnect backoff
680.022: DEBUG - waiting for messages for 5 seconds
Traceback (most recent call last):
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 1001, in _wait_for_msg
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 1091, in _sock_exact_recv
  File "adafruit_esp32spi/adafruit_esp32spi_socketpool.py", line 183, in recv_into
timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "main.py", line 269, in <module>
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 976, in loop
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 1006, in _wait_for_msg
TypeError: function takes 3 positional arguments but 2 were given

Code done running.

willow briar May 21, 2024, 12:32 AM

#

What did it print for ht?

#

It's higher in the stack

analog palm May 21, 2024, 12:33 AM

#

found it, sorry: has timeout: False

willow briar May 21, 2024, 12:34 AM

#

Are you on 9.1.0 beta 2?

analog palm May 21, 2024, 12:35 AM

#

yes - Adafruit CircuitPython 9.1.0-beta.2-6-ge0f745c14c on 2024-05-18; Adafruit PyPortal Titano with samd51j20

willow briar May 21, 2024, 12:35 AM

#

Okay

#

@fresh terrace got it

#

Is the new socketpool frozen in 9.1.0 beta 2?

#

It's defined outside of it now

fresh terrace May 21, 2024, 12:36 AM

#

could you also print pool, repr(pool), and pool.class?

willow briar May 21, 2024, 12:36 AM

#

That's a special case I never thought of

analog palm May 21, 2024, 12:36 AM

#

yup, one sec

fresh terrace May 21, 2024, 12:37 AM

#

FROZEN_MPY_DIRS += $(TOP)/frozen/Adafruit_CircuitPython_ConnectionManager
FROZEN_MPY_DIRS += $(TOP)/frozen/Adafruit_CircuitPython_PortalBase
FROZEN_MPY_DIRS += $(TOP)/frozen/Adafruit_CircuitPython_Requests
FROZEN_MPY_DIRS += $(TOP)/frozen/Adafruit_CircuitPython_ESP32SPI
FROZEN_MPY_DIRS += $(TOP)/frozen/Adafruit_CircuitPython_NeoPixel
FROZEN_MPY_DIRS += $(TOP)/frozen/Adafruit_CircuitPython_Display_Text
FROZEN_MPY_DIRS += $(TOP)/frozen/Adafruit_CircuitPython_FakeRequests

#

put the latest ESP32SPI library dir in CIRCUITPY top-level, not in lib, that will override what is frozen

willow briar May 21, 2024, 12:39 AM

#

Yeah, the socketpool version is frozen on main

#

That's the issue

analog palm May 21, 2024, 12:40 AM

#

what's the right way to print pool.class? I get a SyntaxError with print("class: " + pool.class)

willow briar May 21, 2024, 12:40 AM

#

pool.__class__

analog palm May 21, 2024, 12:40 AM

#

ah, dunder, thank you

fresh terrace May 21, 2024, 12:40 AM

#

sorry

willow briar May 21, 2024, 12:40 AM

#

This is why it worked for me. I'm on 9.0.4

analog palm May 21, 2024, 12:41 AM

#

print("Pool: " + pool, "repr: " + repr(pool)) gives me: TypeError: unsupported types for __add__: 'str', 'SocketPool'

willow briar May 21, 2024, 12:41 AM

#

@analog palm don't worry about it.

#

I've pinpointed the bug

#

@fresh terrace questions on how to fix. Chat here or GitHub?

fresh terrace May 21, 2024, 12:43 AM

#

here is fine

#

so what is the problem? skew between ESP32SPI and MQTT library?

willow briar May 21, 2024, 12:43 AM

#

Do we need the esp32spi to raise the old timeout error?

#

Skew in esp32spi

#

aka I broke it

fresh terrace May 21, 2024, 12:45 AM

#

is it fixed now or you need to make a fix? Is it broken in 9.0.4 builds that frozen ESP32SPI? That has much older versions of the libs (from a few months ago)

#

I looked at the guides and all the libraries and only mqtt library knows about the class timeout exception

#

are you asking could we update it to TimeoutError?

willow briar May 21, 2024, 12:47 AM

#

So it's broken in 9.1.0 beta 9 when frozen, or someone using the latest (like with a feather)

#

What does CP socket raise?

fresh terrace May 21, 2024, 12:50 AM

#

if you just fix it, we'll make a new release and i'll update the frozen libraries before the next beta release. If needed I could do a quick beta release. The only reason the libs are frozen are to save heap RAM. I don't know if using an override in CIRCUITPY would cause a RAM issue.

#

I always update frozen libs just before a beta or final release

#

there are plenty of bugs in the beta's, that's why they are betas. This is just another one

willow briar May 21, 2024, 12:53 AM

#

So I would (if there's not a reason not to) is update the error in esp32spi to match what you would get with native wifi

#

Because the code runs fine without knowing about timeout...

fresh terrace May 21, 2024, 12:56 AM

#

if the minimqtt library is going to be happy with that

willow briar May 21, 2024, 12:57 AM

#

I'll do some testing tonight

fresh terrace May 21, 2024, 12:57 AM

#

so you can make a PR, and if you want testing in advance, give Paul a patched version of the library to load in his CIRCUITPY (not lib)

willow briar May 21, 2024, 12:58 AM

#

Will do. What exactly does native raise? What's the base exception class?

fresh terrace May 21, 2024, 1:01 AM

#

espressif raises OSError(ETIMEDOUT)

#

and it looks like pico-w does the same

#

i am going to sign off to decompress. Thanks for the debugging!

analog palm May 21, 2024, 1:06 AM

#

thanks for all the help dan and justin, much appreciated

willow briar May 21, 2024, 1:10 AM

#

Will have a PR tonight!

willow briar May 21, 2024, 5:42 AM

#

@analog palm for tomorrow, tagged you on a PR in esp32spi

willow briar May 21, 2024, 12:33 PM

#

@analog palm, saw your comment on git hub. Create a folder on the root named adafruit_esp32spi and place all the files in there

analog palm May 21, 2024, 12:33 PM

#

I did, that's the last error.

#

main.py output:
Traceback (most recent call last):
  File "main.py", line 64, in <module>
AttributeError: 'module' object has no attribute 'ESP_SPIcontrol'

willow briar May 21, 2024, 12:35 PM

#

And all 6 py files are in there?

analog palm May 21, 2024, 12:35 PM

#

yup, looking at 'em now

willow briar May 21, 2024, 12:37 PM

#

Okay, let's try this a different way.

Install esp32spi vis circup, and then move the folder from lib to the root
Delete the adafruit_esp32spi_socketpool.mpy
Place the adafruit_esp32spi_socketpool.py that was downloaded in there

analog palm May 21, 2024, 12:37 PM

#

ok, one minute

#

Delete the mpy I assume?

fresh terrace May 21, 2024, 12:40 PM

#

make sure you delete all the solo files you copied over, so that only the folder remains

analog palm May 21, 2024, 12:42 PM

#

I deleted the ESP32spi folder in both the root and the /lib, used Circup to install it again, and moved the whole folder to the root. I then copied over the socketpool.py, deleted the mpy and get the same error:

Traceback (most recent call last):
  File "main.py", line 64, in <module>
AttributeError: 'module' object has no attribute 'ESP_SPIcontrol'

willow briar May 21, 2024, 12:46 PM

#

Yes, just the one

#

Can you screenshot the CP drive?

analog palm May 21, 2024, 12:52 PM

#

fresh terrace May 21, 2024, 12:53 PM

#

from adafruit_esp32spi import adafruit_esp32spi . Try changing this to import adafruit_esp32spi

#

around line 52 in main.py

analog palm May 21, 2024, 12:53 PM

#

oh yeah, I did that too, should have mentioned it:

#

if is_microcontroller:
    import board
    import busio
    from digitalio import DigitalInOut
    # from adafruit_esp32spi import adafruit_esp32spi
    import adafruit_esp32spi

fresh terrace May 21, 2024, 12:55 PM

#

i think we should just try some import and dir() calls from the REPL. I will try to set this up on a PyPortal

analog palm May 21, 2024, 12:55 PM

#

ok

#

sorry for all of this. :/

fresh terrace May 21, 2024, 12:56 PM

#

maybe there is some weird pathological import problem, but I think it should be OK.

#

where did you get adafruit_esp32spi/ from again? From the bundle, or the repo?

#

I just want to exactly dupe what you are doing

analog palm May 21, 2024, 1:02 PM

#

I used the bundle via Circup and then copied adafruit_esp32spi_socketpool.py from Justin's branch to the directory

#

and deleted the mpy

willow briar May 21, 2024, 1:08 PM

#

@analog palm it doesn't work with the import either way?

fresh terrace May 21, 2024, 1:08 PM

#

OK, put back the from adafruit_esp32spi import adafruit_esp32spi

#

the structure of this library is a bit of a nightmare

analog palm May 21, 2024, 1:09 PM

#

done, no error, it's connecting

fresh terrace May 21, 2024, 1:09 PM

#

>>> from adafruit_esp32spi import adafruit_esp32spi
>>> dir(adafruit_esp32spi)
['__class__', '__name__', 'const', 'Direction', 'SPIDevice', '__dict__', '__file__', '__version__', 'struct', 'time', '__repo__', 'ESP_SPIcontrol', 'SOCKET_CLOSED', 'SOCKET_LISTEN', 'SOCKET_FIN_WAIT_1', 'SOCKET_FIN_WAIT_2', 'SOCKET_TIME_WAIT', 'SOCKET_SYN_SENT', 'SOCKET_SYN_RCVD', 'SOCKET_CLOSE_WAIT', 'SOCKET_ESTABLISHED', 'SOCKET_CLOSING', 'SOCKET_LAST_ACK', 'WL_NO_SHIELD', 'WL_NO_MODULE', 'WL_IDLE_STATUS', 'WL_NO_SSID_AVAIL', 'WL_SCAN_COMPLETED', 'WL_CONNECTED', 'WL_CONNECT_FAILED', 'WL_CONNECTION_LOST', 'WL_DISCONNECTED', 'WL_AP_LISTENING', 'WL_AP_CONNECTED', 'WL_AP_FAILED', 'ADC_ATTEN_DB_0', 'ADC_ATTEN_DB_2_5', 'ADC_ATTEN_DB_6', 'ADC_ATTEN_DB_11']
>>> adafruit_esp32spi.ESP_SPIcontrol()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>

analog palm May 21, 2024, 1:09 PM

#

lol, 'TimeoutError: ESP32 not responding. of course! power cycling

fresh terrace May 21, 2024, 1:10 PM

#

having library components that are library.library is always confusing

analog palm May 21, 2024, 1:10 PM

#

ok, it's up and running

#

and now my website is crashing for some reason making it a bit hard to send messages, let me see if I can do it manually

#

if it's not one thing, it's another. 🙂

#

hey my site came back up! I wonder if the API I call went down. But as soon as I sent a message I got (not sure if this is related):

New message on topic prcutler/feeds/albumart: New album picked!
Traceback (most recent call last):
  File "main.py", line 267, in <module>
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 976, in loop
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 1047, in _wait_for_msg
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 382, in _handle_on_message
  File "main.py", line 181, in message
  File "adafruit_requests.py", line 591, in get
  File "adafruit_requests.py", line 525, in request
  File "adafruit_connection_manager.py", line 322, in get_socket
  File "adafruit_connection_manager.py", line 234, in _get_connected_socket
  File "adafruit_connection_manager.py", line 61, in connect
  File "adafruit_esp32spi/adafruit_esp32spi_socketpool.py", line 114, in connect
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 836, in socket_connect
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 732, in socket_open
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 341, in _send_command_get_response
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 297, in _wait_response_cmd
  File "adafruit_esp32spi/adafruit_esp32spi.py", line 206, in _wait_for_ready
TimeoutError: ESP32 not responding

#

rebooted, still not responding, going to let the dog out and give it a few

#

After a couple of timeouts, it's up and running. I've sent a few messgaes successfully

willow briar May 21, 2024, 1:33 PM

#

🚀

#

Can you make a comment on the PR, just so we have it?

analog palm May 21, 2024, 1:35 PM

#

absolutely, will do in a few

willow briar May 21, 2024, 1:38 PM

#

@fresh terrace I marked it ready for review. I do think getting this on another beta release would be helpful (it's this fix and the add for sendto, so ntp works)

fresh terrace May 21, 2024, 1:39 PM

#

thanks - will take a look within an hour or so

willow briar May 21, 2024, 1:39 PM

#

Awesome. Thank you both for helping me get this solved

willow briar May 21, 2024, 2:40 PM

#

@analog palm when you have a chance, could you send a message? I'm trying the same fix for the wiznet5k (Ethernet featherwing)

analog palm May 21, 2024, 2:42 PM

#

willow briar <@273162248615100417> when you have a chance, could you send a message? I'm tryi...

message sent

willow briar May 21, 2024, 2:43 PM

#

Perfect. Thanks!

analog palm May 21, 2024, 2:44 PM

#

no problem. I'll be in a meeting in 15 minutes, so if you need anything I might not respond right away. Thanks again for all your work on this.

willow briar May 21, 2024, 2:48 PM

#

I think I'm good. Watch for the next CP beta and you should be good. Tomorrow you can re-install esp32spi so you have the mpy (just make sure to move it back to the root)

fresh terrace May 21, 2024, 3:20 PM

#

https://www.githubstatus.com/ trouble with Actions. I restarted a build for the wiznet PR

willow briar May 21, 2024, 3:54 PM

#

Yeah, I saw

willow briar May 22, 2024, 8:04 PM

#

🚀

#

beta3 is on the way

#

@analog palm when you have a chance, can you:

install beta 3: https://adafruit-circuit-python.s3.amazonaws.com/bin/pyportal_titano/en_US/adafruit-circuitpython-pyportal_titano-en_US-9.1.0-beta.3.uf2
remove (or rename) the adafruit_esp32spi folder on the root
run circup update

See if it all works????

willow briar May 22, 2024, 8:59 PM

#

it's working on my pyportal!

analog palm May 22, 2024, 9:18 PM

#

yes! will install beta 3 in just a bit - thanks for letting me know the build is available

willow briar May 22, 2024, 9:18 PM

#

Quite welcome. Mine is looping nicely

analog palm May 22, 2024, 11:11 PM

#

I had two crashes within the first 15 minutes each time:

Traceback (most recent call last):
  File "main.py", line 267, in <module>
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 969, in loop
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 628, in ping
MMQTTException: ('PINGRESP not returned from broker within 10 seconds.', None)

Code done running.

I went to dinner, came back, and my PyPortal erased itself. So I'll do some more testing.

fresh terrace May 22, 2024, 11:21 PM

#

analog palm I had two crashes within the first 15 minutes each time: ```py Traceback (most r...

Update the bootloader, if you have not already done so: https://learn.adafruit.com/adafruit-pyportal/update-the-uf2-bootloader.

analog palm May 22, 2024, 11:32 PM

#

will do, thanks

analog palm May 23, 2024, 2:18 PM

#

Well, I hate to be the bearer of bad news, but I"m still having an issue on message send. When I send a message, it's crashing. It's not every time, but maybe 2 out of 3. And since it's an ESP32 Not Responding error, I usually have to wait 5-10 minutes before plugging it back in so it does respond. Here's the whole error:

#

[09:15:30.342] Topic: prcutler/feeds/albumart
[09:15:30.342] Msg: bytearray(b'New album picked!')

[09:15:30.345] New message on topic prcutler/feeds/albumart: New album picked!
[09:15:43.375] Traceback (most recent call last):
[09:15:43.375]   File "main.py", line 267, in <module>
[09:15:43.376]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 976, in loop
[09:15:43.376]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 1047, in _wait_for_msg
[09:15:43.376]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 382, in _handle_on_message
[09:15:43.379]   File "main.py", line 181, in message
[09:15:43.379]   File "adafruit_requests.py", line 683, in get
[09:15:43.380]   File "adafruit_requests.py", line 615, in request
[09:15:43.380]   File "adafruit_connection_manager.py", line 332, in get_socket
[09:15:43.380]   File "adafruit_connection_manager.py", line 244, in _get_connected_socket
[09:15:43.380]   File "adafruit_connection_manager.py", line 61, in connect
[09:15:43.380]   File "adafruit_esp32spi/adafruit_esp32spi_socketpool.py", line 114, in connect
[09:15:43.380]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 836, in socket_connect
[09:15:43.381]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 732, in socket_open
[09:15:43.382]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 341, in _send_command_get_response
[09:15:43.382]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 297, in _wait_response_cmd
[09:15:43.383]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 206, in _wait_for_ready
[09:15:43.383] TimeoutError: ESP32 not responding
[09:15:43.384]
[09:15:43.384] Code done running.

[09:15:43.388] Press any key to enter the REPL. Use CTRL-D to reload.

fresh terrace May 23, 2024, 2:29 PM

#

i've lost the context for this. Which issue is this written up in? Is it your own mqtt server?

analog palm May 23, 2024, 2:29 PM

#

No problem - I'm using AdafruitIO

fresh terrace May 23, 2024, 2:29 PM

#

I would like to try to reproduce. I am doing some SSL testing with Espressif that is working ok right now, but haven't started testing with ESP32SPI yet.

analog palm May 23, 2024, 2:30 PM

#

No rush at all, I appreciate all the help. I can try using MQTT non-SSL with Adafruit IO too

fresh terrace May 23, 2024, 2:30 PM

#

is your test program in an issue?

analog palm May 23, 2024, 2:31 PM

#

It was, but I closed it, should I re-open it?

fresh terrace May 23, 2024, 2:31 PM

#

which one is it?

analog palm May 23, 2024, 2:31 PM

#

looking now

fresh terrace May 23, 2024, 2:31 PM

#

yes, you can reopen it

analog palm May 23, 2024, 2:31 PM

#

will do, I'll include the latest code

willow briar May 23, 2024, 2:50 PM

#

Responded there

analog palm May 23, 2024, 3:21 PM

#

Sorry, went for a walk. I'll try updating it now

willow briar May 23, 2024, 5:03 PM

#

@analog palm can I have you try some things here? Just easier to respond

analog palm May 23, 2024, 5:03 PM

#

Absolutely

willow briar May 23, 2024, 5:05 PM

#

can you change this:

esp = adafruit_esp32spi.ESP_SPIcontrol(spi, esp32_cs, esp32_ready, esp32_reset)

to:

esp = adafruit_esp32spi.ESP_SPIcontrol(spi, esp32_cs, esp32_ready, esp32_reset, debug=True)

#

you'll get a lot more logging, but I'm hoping to see something.

analog palm May 23, 2024, 5:06 PM

#

Running now

#

Here we go:

[12:08:17.254] New message on topic prcutler/feeds/albumart: New album picked!
[12:08:17.255] *** Get host by name
[12:08:17.547] *** Get socket
[12:08:17.548] Allocated socket #1
[12:08:17.549] *** Socket connect mode 2
[12:08:17.549] *** Open socket to silversaucer.com 443 2
[12:08:17.550] *** Closing socket #1
[12:08:17.552] Traceback (most recent call last):
[12:08:17.552]   File "main.py", line 265, in <module>
[12:08:17.552]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 969, in loop
[12:08:17.553]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 623, in ping
[12:08:17.553]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 1047, in _wait_for_msg
[12:08:17.554]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 382, in _handle_on_message
[12:08:17.555]   File "main.py", line 180, in message
[12:08:17.555]   File "adafruit_requests.py", line 683, in get
[12:08:17.555]   File "adafruit_requests.py", line 615, in request
[12:08:17.556]   File "adafruit_connection_manager.py", line 332, in get_socket
[12:08:17.557]   File "adafruit_connection_manager.py", line 244, in _get_connected_socket
[12:08:17.557]   File "adafruit_connection_manager.py", line 61, in connect
[12:08:17.559]   File "adafruit_esp32spi/adafruit_esp32spi_socketpool.py", line 114, in connect
[12:08:17.559]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 836, in socket_connect
[12:08:17.559]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 721, in socket_open
[12:08:17.560] OSError: 23
[12:08:17.560]
[12:08:17.560] Code done running.

#

let me know if you want anything before that, it's a lot. 🙂

willow briar May 23, 2024, 5:10 PM

#

how about the first time you get data from silversaucer.com (before you connect to mqtt)

analog palm May 23, 2024, 5:10 PM

#

oops, my scroll back doesn't go back far enough, lol. Restarting

#

[12:10:52.777] Reset ESP32
[12:10:54.439] Firmware version
[12:10:54.441] bytearray(b'1.7.7\x00')
[12:10:54.971] Connecting to AP...
[12:10:54.972] Connection status: 0
[12:10:54.974] Connect to AP: ssid=Dispatch, password=                    '**********'
[12:10:55.442] Connection status: 1
[12:10:55.908] Connection status: 1
[12:10:56.376] Connection status: 1
[12:10:56.847] Connection status: 1
[12:10:57.311] Connection status: 1
[12:10:57.778] Connection status: 1
[12:10:58.246] Connection status: 1
[12:10:58.714] Connection status: 1
[12:10:59.182] Connection status: 1
[12:10:59.651] Connection status: 1
[12:11:00.118] Connection status: 1
[12:11:00.587] Connection status: 1
[12:11:01.055] Connection status: 1
[12:11:01.525] Connection status: 3
[12:11:01.525] Connection status: 3
[12:11:01.529] Connected to Dispatch     RSSI: -61
[12:11:01.529] sleeping for 10 seconds to make sure wifi is good...
[12:11:11.359] *** Get host by name
[12:11:11.820] *** Get socket
[12:11:11.822] Allocated socket #0
[12:11:11.823] *** Socket connect mode 2
[12:11:11.823] *** Open socket to silversaucer.com 443 2
[12:11:19.830] Writing: b'GET'
[12:11:20.294] Writing: b' /'
[12:11:20.757] Writing: b'album/data'
[12:11:20.768] Writing: b' HTTP/1.1\r\n'
[12:11:21.231] Writing: b'Host'
[12:11:21.242] Writing: b': '
[12:11:21.706] Writing: b'silversaucer.com'
[12:11:21.719] Writing: b'\r\n'
[12:11:22.180] Writing: b'User-Agent'
[12:11:22.192] Writing: b': '
[12:11:22.655] Writing: b'Adafruit CircuitPython'
[12:11:22.667] Writing: b'\r\n'
[12:11:23.128] Writing: b'\r\n'
[12:11:23.141] ESPSocket: 0 bytes available
[12:11:23.143] ESPSocket: 0 bytes available
[12:11:23.597] ESPSocket: 0 bytes available
[12:11:23.599] ESPSocket: 423 bytes available

#

And then I have hundreds of ESPSocket: 0 bytes available

willow briar May 23, 2024, 5:17 PM

#

okay. I know what's happening, but not sure why it's coded this way

analog palm May 23, 2024, 5:17 PM

#

progress. 🙂

willow briar May 23, 2024, 5:20 PM

#

so hear's the break down:

the not responding error, I often get when too much memory is being used (this is why I had you comment out the display code originally)
to fix this, I had you close responses that were left open
they don't fully close (until they need to), but the code tracks a _tls_socket and if set it doesn't allow you to make another tls (ssl, secure, whatever) call

#

this will be a strange test, after each with requests. add esp._tls_socket = None like this:

with requests.get(data_source) as resp:
    data = resp.json()
    print(data)
 esp._tls_socket = None

analog palm May 23, 2024, 5:23 PM

#

ok

#

ESP32 not responding, will be a bit, sorry

willow briar May 23, 2024, 5:25 PM

#

No worries

analog palm May 23, 2024, 5:41 PM

#

Ok, now I'm getting repeated connect failures, this has happened twice in a row before I get to sending a message:

[12:35:48.580] Reading 38 bytes from ESP socket with status 4
[12:35:48.582] {'artist': 'Frank Turner', 'album': 'Positive Songs For Negative People', 'image_url': 'https://i.discogs.com/n7nNjf2KYO9sSgzIXL5vmbp-tUGsEkdnrlpcp1fVIo8/rs:fit/g:sm/q:90/h:599/w:600/czM6Ly9kaXNjb2dz/LWRhdGFiYXNlLWlt/YWdlcy9SLTc1MjY2/MTEtMTYzMDk4Mjg3/OC0zNjUwLmpwZWc.jpeg'}
[12:35:56.368] 47.177: DEBUG - Attempting to connect to MQTT broker (attempt #0)
[12:35:56.369] 47.179: DEBUG - Attempting to establish MQTT connection...
[12:35:56.370] *** Get host by name
[12:35:56.387] *** Get socket
[12:35:56.388] Allocated socket #1
[12:35:56.389] *** Socket connect mode 2
[12:35:56.389] *** Open socket to io.adafruit.com 8883 2
[12:35:56.640] *** Closing socket #1
[12:35:56.642] *** Closing socket #0
[12:35:56.649] *** Get socket
[12:35:56.650] Allocated socket #0
[12:35:56.651] *** Socket connect mode 2
[12:35:56.651] *** Open socket to io.adafruit.com 8883 2
[12:35:56.890] *** Closing socket #0

#

[12:35:56.896] 47.711: WARNING - Socket error when connecting: Expected 01 but got 00
[12:35:56.896] 47.713: DEBUG - Resetting reconnect backoff
[12:35:56.898] 47.715: DEBUG - Attempting to connect to MQTT broker (attempt #0)
[12:35:56.900] 47.717: DEBUG - Attempting to establish MQTT connection...
[12:35:56.900] *** Get host by name
[12:35:56.903] *** Get socket
[12:35:56.905] Allocated socket #0
[12:35:56.906] *** Socket connect mode 2
[12:35:56.906] *** Open socket to io.adafruit.com 8883 2
[12:35:56.960] *** Closing socket #0
[12:35:56.964] 47.782: WARNING - Socket error when connecting: Expected 01 but got 00
[12:35:56.972] 47.784: DEBUG - Resetting reconnect backoff
[12:35:56.972] 47.787: DEBUG - Attempting to connect to MQTT broker (attempt #0)
[12:35:56.972] 47.789: DEBUG - Attempting to establish MQTT connection...
[12:35:56.972] *** Get host by name
[12:35:56.982] *** Get socket
[12:35:56.984] Allocated socket #0
[12:35:56.985] *** Socket connect mode 2
[12:35:56.985] *** Open socket to io.adafruit.com 8883 2
[12:35:57.039] *** Closing socket #0
[12:35:57.044] 47.863: WARNING - Socket error when connecting: Expected 01 but got 00
[12:35:57.046] 47.865: DEBUG - Resetting reconnect backoff

#

[12:35:57.048] 47.868: DEBUG - Attempting to connect to MQTT broker (attempt #0)
[12:35:57.050] 47.870: DEBUG - Attempting to establish MQTT connection...
[12:35:57.050] *** Get host by name
[12:35:57.054] *** Get socket
[12:35:57.055] Allocated socket #0
[12:35:57.056] *** Socket connect mode 2
[12:35:57.056] *** Open socket to io.adafruit.com 8883 2
[12:35:57.109] *** Closing socket #0
[12:35:57.113] 47.934: WARNING - Socket error when connecting: Expected 01 but got 00
[12:35:57.115] 47.936: DEBUG - Resetting reconnect backoff
[12:35:57.118] 47.938: DEBUG - Attempting to connect to MQTT broker (attempt #0)
[12:35:57.120] 47.941: DEBUG - Attempting to establish MQTT connection...
[12:35:57.133] *** Get host by name
[12:35:57.133] *** Get socket
[12:35:57.136] Allocated socket #0
[12:35:57.136] *** Socket connect mode 2
[12:35:57.136] *** Open socket to io.adafruit.com 8883 2
[12:35:57.190] *** Closing socket #0
[12:35:57.193] 48.015: WARNING - Socket error when connecting: Expected 01 but got 00
[12:35:57.194] Traceback (most recent call last):
[12:35:57.194]   File "main.py", line 262, in <module>
[12:35:57.194]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 459, in connect
[12:35:57.195] MMQTTException: ('Repeated connect failures', None)
[12:35:57.196]
[12:35:57.196] Code done running.

#

I have to go to a meeting, I'll be back in an hourish. No hurry looking at this, thank you for everything so far

fresh terrace May 23, 2024, 5:55 PM

#

analog palm ESP32 not responding, will be a bit, sorry

you mentioned you have to let it sit. That's very odd. You should be able to just power cycle. Or you might need to let the servers you are talking to timeout. That's usually a 2 minute timeout, I think.

willow briar May 23, 2024, 7:17 PM

#

@analog palm when you have a chance, can you upload your current code? I want to give you something else to try

#

and @fresh terrace do you know why the ESP32SPI library limits to 1 open tls connection?

fresh terrace May 23, 2024, 7:19 PM

#

it may be inherent in the firmware; i don't know; i'm just starting to test on it

#

I'm hoping CM is taking care of that now: it would close the first stocket when the second connect fails

analog palm May 23, 2024, 7:22 PM

#

Here you go:

📎 main.py

willow briar May 23, 2024, 7:25 PM

#

Since it's all just 1 host, it never tries a second time.

#

Try this. I'm forcing the sockets to close

📎 main.py

analog palm May 23, 2024, 7:29 PM

#

Running now

#

Of course, ESP32 not responding. Power cycling

#

up and running, sent a message and:

[14:32:08.288] 72.067: DEBUG - Receiving PUBLISH
[14:32:08.288] Topic: prcutler/feeds/albumart
[14:32:08.288] Msg: bytearray(b'New album picked!')

[14:32:08.289] New message on topic prcutler/feeds/albumart: New album picked!
[14:32:08.291] *** Get host by name
[14:32:08.294] *** Get socket
[14:32:08.295] Allocated socket #1
[14:32:08.296] *** Socket connect mode 2
[14:32:08.296] *** Open socket to silversaucer.com 443 2
[14:32:08.297] *** Closing socket #1
[14:32:08.299] Traceback (most recent call last):
[14:32:08.299]   File "main.py", line 271, in <module>
[14:32:08.300]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 976, in loop
[14:32:08.300]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 1047, in _wait_for_msg
[14:32:08.301]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 382, in _handle_on_message
[14:32:08.301]   File "main.py", line 182, in message
[14:32:08.302]   File "adafruit_requests.py", line 683, in get
[14:32:08.302]   File "adafruit_requests.py", line 615, in request
[14:32:08.303]   File "adafruit_connection_manager.py", line 332, in get_socket
[14:32:08.303]   File "adafruit_connection_manager.py", line 244, in _get_connected_socket
[14:32:08.304]   File "adafruit_connection_manager.py", line 61, in connect
[14:32:08.304]   File "adafruit_esp32spi/adafruit_esp32spi_socketpool.py", line 114, in connect
[14:32:08.305]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 836, in socket_connect
[14:32:08.305]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 721, in socket_open
[14:32:08.306] OSError: 23
[14:32:08.306]
[14:32:08.307] Code done running.

willow briar May 23, 2024, 7:50 PM

#

@analog palm are you able to automate sending a message?

analog palm May 23, 2024, 7:55 PM

#

willow briar <@273162248615100417> are you able to automate sending a message?

I'm not sure - from my current program? or I could write a Python program to do it

#

Or I could use another MCU and do it

willow briar May 23, 2024, 7:55 PM

#

So I'm setting up my pyportal to see if I can repro

analog palm May 23, 2024, 7:56 PM

#

Gotcha

willow briar May 23, 2024, 7:56 PM

#

Just trying to find a way not to ask you to keep sending

analog palm May 23, 2024, 7:56 PM

#

Since the feed is public, can you send a message?

willow briar May 23, 2024, 7:56 PM

#

oh, maybe

analog palm May 23, 2024, 7:57 PM

#

The page is public: https://io.adafruit.com/prcutler/feeds/albumart

#

But it does say read only in the upper right hand corner when not logged in

willow briar May 23, 2024, 7:59 PM

#

Yeah, it says I have read-only access

#

Can you send a message, just want to see if I get the same thing

analog palm May 23, 2024, 7:59 PM

#

Sent

willow briar May 23, 2024, 7:59 PM

#

Yup, same thing

analog palm May 23, 2024, 7:59 PM

#

thank goodness, I'm not crazy. 🙂

willow briar May 23, 2024, 8:01 PM

#

And I created a feed so I can test

analog palm May 23, 2024, 8:02 PM

#

Ok - I was just about to write a few lines of python. 🙂

willow briar May 23, 2024, 8:20 PM

#

Oooohhhhh

#

You changed it to SSL, didn't you?

analog palm May 23, 2024, 8:21 PM

#

Yes, but I could have sworn I changed it right back to not use SSL on the MQTT connection. I'm afraid to go look now.

#

yeah, I did, let me change it back, I'm sorry

willow briar May 23, 2024, 8:22 PM

#

That should fix it

#

the ESP32SPI is coded in a way it can only handle 1 SSL connection. I have no idea why (if it's a limitation of the chip or something else)

analog palm May 23, 2024, 8:23 PM

#

Interesting. Sorry to waste your time tracking that one down. Running it now

willow briar May 23, 2024, 8:24 PM

#

Actually, I'm glad you did. I had no idea of this bug/limitation

#

at the minimum, I want to update raise OSError(23) to something that will help people understand

analog palm May 23, 2024, 8:26 PM

#

Yup, it worked!

willow briar May 23, 2024, 8:26 PM

#

oh good

analog palm May 23, 2024, 8:27 PM

#

I spoke too soon:

[15:26:44.675] 3405.663: DEBUG - KeepAlive period elapsed - requesting a PINGRESP from the server...
[15:26:44.677] 3405.665: DEBUG - Sending PINGREQ
[15:26:44.677] Writing: b'\xc0\x00'
[15:26:44.679] *** Closing socket #0
[15:26:44.681] Traceback (most recent call last):
[15:26:44.681]   File "main.py", line 271, in <module>
[15:26:44.682]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 969, in loop
[15:26:44.682]   File "adafruit_minimqtt/adafruit_minimqtt.py", line 617, in ping
[15:26:44.683]   File "adafruit_esp32spi/adafruit_esp32spi_socketpool.py", line 125, in send
[15:26:44.683]   File "adafruit_esp32spi/adafruit_esp32spi.py", line 796, in socket_write
[15:26:44.684] ConnectionError: Failed to send 2 bytes (sent 0)
[15:26:44.684]
[15:26:44.685] Code done running.

#

soon as it went back to wait for more messages

willow briar May 23, 2024, 8:28 PM

#

yup

#

remove the cm._free_sockets(force=True)

#

Since that closes anything that's open

analog palm May 23, 2024, 8:29 PM

#

Running it now

#

ESP32 not responding, trying again

#

Looking good - loaded new artwork and the loop is running

#

Sent a couple messages and it's still running. I need to afk a bit, I'll leave it running. Thank you so much!

willow briar May 23, 2024, 8:45 PM

#

awesome

#

@fresh terrace how would I go about finding out what the TLS limitation is for the ESP32SPI?

fresh terrace May 23, 2024, 8:47 PM

#

I would just try some extremely simple examples first to verifiy your hunch. I've been running this for a couple of hours.

willow briar May 23, 2024, 8:47 PM

#

So this blocks it: https://github.com/adafruit/Adafruit_CircuitPython_ESP32SPI/blob/main/adafruit_esp32spi/adafruit_esp32spi.py#L720C1-L721C62

fresh terrace May 23, 2024, 8:48 PM

#

📎 code.py

willow briar May 23, 2024, 8:48 PM

#

The issue is 2 open sockets. In this case one to the MQTT server and then a separate one to fetch data

fresh terrace May 23, 2024, 8:48 PM

#

and I would do some websearching about TLS and NINA-FW

#

and I would look at the code

willow briar May 23, 2024, 8:49 PM

#

Sounds good. I'm also just going to comment that all out and see what happens

fresh terrace May 23, 2024, 8:49 PM

#

i think Paul's program can be reduced to a simple example

#

i have to start cooking dinner...

willow briar May 23, 2024, 8:51 PM

#

Sounds good. I can easily make a simple test

#

Do you know if there will be another beta for 9.1.0? I would at least like to get a better error in there if I can

fresh terrace May 23, 2024, 8:56 PM

#

yes, there will probably be another beta, and the frozen libs will be updated before the release candidates

#

in other words, don't worry, the latest libraries will get in

#

I am thinking about whether SSLError should eventually be raised by the native wifi code. It would seem to be a lot more informative than some errors I'm seeing now ("X509 blah blah")

willow briar May 23, 2024, 8:59 PM

#

Some used to be more specific until Jeff standardized code so it was the same

#pyportal @Paul Cutler