rstrouse / ESPSomfy-RTS

A controller for Somfy RTS shades and blinds
The Unlicense
430 stars 32 forks source link

Radio not initialized #283

Closed ElmarJordan closed 4 months ago

ElmarJordan commented 4 months ago

Hardware

ESP32

Firmware version

v2.3.3

Application version

v2.3.3

What happened? What did you expect to happen?

The application has been unavailable on the network for 2 days. The WEB interface appears in the browser but with the message "Radio not initialized".

image

Hardware is accessible on the network:

64 bytes from 192.168.178.73: icmp_seq=28418 ttl=255 time=7.252 ms 64 bytes from 192.168.178.73: icmp_seq=28419 ttl=255 time=8.362 ms 64 bytes from 192.168.178.73: icmp_seq=28420 ttl=255 time=8.836 ms 64 bytes from 192.168.178.73: icmp_seq=28421 ttl=255 time=7.145 ms 64 bytes from 192.168.178.73: icmp_seq=28422 ttl=255 time=6.712 ms 64 bytes from 192.168.178.73: icmp_seq=28423 ttl=255 time=6.097 ms

Reinstallation brings no change

How to reproduce it (step by step)

1. Go to...
2. Click on...
...

Logs

No response

rstrouse commented 4 months ago

Are you accessing it using the IP address or the domain name? If you are not use the IP address and if you know how can you check to see if there are any errors in the browser console when you reload the page.

ElmarJordan commented 4 months ago

Using the IP address

Message from the Google Chrome Console:

image

rstrouse commented 4 months ago

The response in the browser is simply that it cannot connect to the socket. Did anything change before this? Can you connect the device to the a serial port so you can see the log?

ElmarJordan commented 4 months ago

here is the log after a reset device:

Connecting to AP Set hostname to:ESPSomfyRTS


Successfully Connected to WiFi!!!!192.168.178.73 (-53dbm) MDNS Responder Started: serverId=A053A8 Max Heap: 110580 Free Heap: 176108 Min Heap: 173140 App Version:2.3.3 shades.cfg exists so we are using that Reading header at 0 version:20 len:66 roomSize:29 roomRecs:0 shadeSize:276 shadeRecs:12 groupSize:194 groupRecs: 4 pos:66 Applying radio settings Setting Data Pins RX:12 TX:13 Setting SPI Pins SCK:18 MISO:19 MOSI:23 CSN:5 Radio Pins Configured! Successfully set up the radio Enabled receive on Pin #12 Timing: 1 Initializing RX Queue Timing Net: 5010ms Check github for updates... Max Heap: 110580 Free Heap: 175520 Min Heap: 166516 Internet is Available: 1862ms [HTTPS] GET... code: 200 [HTTPS] GET... code: 200 - -1 Max Heap: 110580 Free Heap: 172396 Min Heap: 121524

when I visit the website : Timing WebServer: 9017ms Timing Net: 5010ms Timing Net: 5009ms Timing Net: 5010ms Timing Net: 5010ms Socket [0] Disconnected! Timing Net: 5012ms Timing Net: 5010ms Timing Net: 5010ms Socket [0] Disconnected!

Ping at the same time: 64 bytes from 192.168.178.73: icmp_seq=56461 ttl=255 time=5.436 ms 64 bytes from 192.168.178.73: icmp_seq=56462 ttl=255 time=5.581 ms 64 bytes from 192.168.178.73: icmp_seq=56463 ttl=255 time=13.839 ms 64 bytes from 192.168.178.73: icmp_seq=56464 ttl=255 time=6.176 ms 64 bytes from 192.168.178.73: icmp_seq=56465 ttl=255 time=7.671 ms 64 bytes from 192.168.178.73: icmp_seq=56466 ttl=255 time=6.795 ms 64 bytes from 192.168.178.73: icmp_seq=56467 ttl=255 time=8.722 ms

and Internet Access: image

rstrouse commented 4 months ago

What I see in that response is very odd. Your icmp latency is acceptable and even when the esp32 is communicating with the internet it is retrieving the data in less than 2 seconds. But locally it is taking 9 seconds to send a response first client request and 5 seconds for each subsequent one. Which of course should time out the socket and give you the dead message from the browser.

I have to wonder if the negotiation between the adapters are including 802.11b packets which are not being resolved by either the client or router adapter. By chance, do you have this enabled in your router? If you do then you should probably disable it. Most routers and modern network interfaces do not handle this very well, as a result, it has a negative impact on your overall network.

I cannot imagine you have any devices that use it so before you get FOMO the primary device set that used this were PCMCIA slot network cards. The only other thing that could cause the delivery on the WiFi radio to be delayed is a flood of Bluetooth but that would have to be dramatic.

ElmarJordan commented 4 months ago

Thanks for the hints. Yes 802.1b is active on my network, not because I need it but because my system (Unifi Network Controller) doesn't give me the option to turn it off. I think Bluetooth I have no exceptional usage and we can exclude it.

Is there any other way to get the system up and running again? It worked all the time with 802.1b, I have no explanation (new devices etc.) why it doesn't work anymore.

rstrouse commented 4 months ago

On many of the Unifi routers they dumbed the setting down a bit and called it Legacy Support. By default it is typically turned off (unchecked) but it appears the checkbox on some routers does nothing. I am spit-balling with this suggestion though.

I suppose it is possible that there is some issue with the WiFi radio on the ESP32 but it is very odd that the issue only affects a browser connecting to it internally. I say this because in the log above when the ESP32 is checking to see if the internet is available it returns in 1862ms or 1.8 seconds.

This would mean that the HTTP client is working just fine attempting to communicate with github but the HTTP server is struggling to get out its server responses. This indicates that there is something between the local web client that does not exist between the ESP32 and github. Both are on the same WiFi connection.

The message Radio not Initialized is a red herring as in your log output above it is happily initializing the radio but it simply cannot tell the browser about its success. Maybe we can get some hints as to what the browser is actually doing if we clear its cache. You can do this by hard refreshing the browser and watching the network tab in the developer tools. This will tell us if it is simply not responding to the preflights or if something else is going on.

ElmarJordan commented 4 months ago

Yes, I am known about the legacy function. In the current Controller Version 8.0.28 , you can only set the "Minimum Data Rate". There is no option for switching it off. I have also experimented with this, but my WiFi scanner always says that 802.1b is active and the error does not change.

image

image

Experimenting with the browser cache doesn't really help me because that doesn't solve the Problem with the Home Assistant Integration.

I have just reinstalled the system and after restoring the backup the homepage is available:

image

the Log: Successfully Connected to WiFi!!!!192.168.178.73 (-52dbm) MDNS Responder Started: serverId=A053A8 SSDP: urn:schemas-rstrouse-org:device:ESPSomfyRTS:1 - true Connected to SSDP... Max Heap: 110580 Free Heap: 169060 Min Heap: 168496 App Version:2.3.3 shades.cfg exists so we are using that Reading header at 0 version:20 len:66 roomSize:29 roomRecs:0 shadeSize:276 shadeRecs:12 groupSize:194 groupRecs: 4 pos:66 Applying radio settings Setting Data Pins RX:12 TX:13 Setting SPI Pins SCK:18 MISO:19 MOSI:23 CSN:5 Radio Pins Configured! Successfully set up the radio Enabled receive on Pin #12 Timing: 1 Initializing RX Queue Check github for updates... Max Heap: 110580 Free Heap: 167988 Min Heap: 160416 Internet is Available: 1872ms [HTTPS] GET... code: 200 [HTTPS] GET... code: 200 - -1 Max Heap: 69620 Free Heap: 162788 Min Heap: 111404 Timing WebServer: 4041ms Socket [1] Connected from 192.168.178.95 url: / Socket [0] Connected from 192.168.178.60 url: / Max Heap: 69620 Free Heap: 160968 Min Heap: 111404 Setting Transceiver Json

IP 192.168.178.95 is my Homeassistant IP 192.168.178.95 is my Macbook

but after a reboot the error returns

image

Helps this Information for analysis?

rstrouse commented 4 months ago

Now that is puzzling. It can stand up a reliable socket but only one time. Upload your backup maybe there is something in there.

ElmarJordan commented 4 months ago

Here is my backup file, but it still worked with this one. It only stopped working after a new reboot.

ESPSomfyRTS 2023-12-28T08_55_13.backup.zip

rstrouse commented 4 months ago

Just checking to see if there is a buffer overrun somewhere that might be data related. Update to 2.4.0 so we can be on the same platform.

rstrouse commented 4 months ago

I restored your backup and managed to get it to fail. It looks like the ntp server may be invalid but I am going to do some more testing. Did you stand up your own ntp server on 192.168.178.1?

rstrouse commented 4 months ago

.., And that was it. Your ntp server is not correct and is not resolving properly.

If you have the ability to send a curl command then you can simply send this command from a command prompt. Give it several seconds, then it should magically start responding.

curl -X PUT -H "Content-Type: application/json" -d '{"ntpServer":"pool.ntp.org"}' http://192.168.178.73/setGeneral

ElmarJordan commented 4 months ago

Yes, that was it. Sorry, I had forgotten about the time server or didn't associate it with my fault.

I would like to thank you once again for your support, it couldn't have been better.

I would also like to praise your development, I am delighted with the solution.

rstrouse commented 4 months ago

It really is too bad that it has a blocking delay in a simply request to get the time. I'll find a workaround for it doing that.