Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Shelly Pro Devices get flooded with requests from Openhab instance #17892

Open
MiniOh opened this issue Dec 12, 2024 · 5 comments
Open

Shelly Pro Devices get flooded with requests from Openhab instance #17892

MiniOh opened this issue Dec 12, 2024 · 5 comments
Labels
bug An unexpected problem or unintended behavior of an add-on

Comments

@MiniOh
Copy link

MiniOh commented Dec 12, 2024

Hello,

since the firmware updates to version 1.3x and 1.4x, all my Pro Shellys have problems.

I have been using some Shelly Pro 4 PMs for about 3 years, and also a Shelly Pro 3 EM.

The Pro 4 PMs are some of the first to come onto the market in 2021.
So far, these have always worked without problems and were always accessible via WiFi.

Since the updates to 1.3.2 and 1.4.4, all of my devices have been running very unstable.

There are a lot of ping losses.
The uptime of the devices, which used to be 1 year in some cases, is only between 5 and 30 minutes.
The devices also restart very frequently.
After a few days, some of the devices are not accessible at all and only switching off the power supply helps.

Switching off the ECO mode provides some relief.
This alleviates the problems somewhat. Still very unsatisfactory compared to the time before the firmware update.

I contacted Shelly Support about the issue.
It turned out that the devices were being flooded with requests every second from the Openhab instance.
According to Shelly, these thousands of requests are to blame for the crashes.

So the question at this point is, why so many requests sent by Openhab?
The query interval is set to 60 seconds.

The Openhab version is the current openHAB 4.2.3.
But I also tested the current snapshot version of the Openhab binding.
The behavior is the same here.

All my 40 non Pro Devices has no Problems, but they only beeing contaced every 60 seconds by openhab.

This is the according log, which floods the log a hundred times a minute.

13:19:35.094 [DEBUG] [shelly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: WebSocket connected /192.168.0.xxx:33552<-/192.168.0.xxx:80, Idle Timeout=2147483647
13:19:36.063 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Closing Rpc API (socket is connected, discovery=true)
13:19:36.063 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Disconnect Rpc Socket
13:19:36.064 [DEBUG] [shelly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: Disconnecting WebSocket (/192.168.0.xxx:33552 -> /192.168.0.xxx:80)
13:19:36.065 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: WebSocket connection closed, status = 1006/Disconnected
13:19:36.067 [DEBUG] [.discovery.ShellyDiscoveryParticipant] - shellypro4pm-123456789123: Shelly device discovered: IP-Adress=192.168.0.xxx, type=shellypro4pm
13:19:36.132 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Closing Rpc API (socket is connected, discovery=true)
13:19:36.133 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Disconnect Rpc Socket
13:19:36.133 [DEBUG] [shelly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: Disconnecting WebSocket (/192.168.0.xxx:41414 -> /192.168.0.xxx:80)
13:19:36.134 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: WebSocket connection closed, status = 1006/Disconnected
13:19:36.137 [DEBUG] [.discovery.ShellyDiscoveryParticipant] - shellypro4pm-123456789123: Shelly device discovered: IP-Adress=192.168.0.xxx, type=shellypro4pm
13:19:36.204 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Closing Rpc API (socket is connected, discovery=true)
13:19:36.205 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Disconnect Rpc Socket
13:19:36.206 [DEBUG] [shelly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: Disconnecting WebSocket (/192.168.0.xxx:41418 -> /192.168.0.xxx:80)
13:19:36.207 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: WebSocket connection closed, status = 1006/Disconnected
13:19:36.209 [DEBUG] [.discovery.ShellyDiscoveryParticipant] - shellypro4pm-123456789123: Shelly device discovered: IP-Adress=192.168.0.xxx, type=shellypro4pm
13:19:36.227 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Connect Rpc Socket (discovery = true)
13:19:36.228 [DEBUG] [shelly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: Connect WebSocket, URI=ws://192.168.0.xxx/rpc
13:19:36.231 [DEBUG] [ng.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Connect Rpc Socket (discovery = true)
13:19:36.232 [DEBUG] [shelly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: Connect WebSocket, URI=ws://192.168.0.xxx/rpc

Thank you in advance.
@MiniOh MiniOh added the bug An unexpected problem or unintended behavior of an add-on label Dec 12, 2024
@MiniOh
Copy link
Author

MiniOh commented Dec 17, 2024

Hello,

I have had a lot of contact with Shelly Support, but they see the error on Openhab's side
and also categorically reject a firmware downgrade.

I decided to buy another Shelly Pro 4PM and test it with "old" firmware.

The result is almost as expected.

With firmware 1.0.7, the Shelly works completely normally, there is a websocket login from Openhab,
which also remains.

All Pro Shellys with FW 1.4.4, however, show the above-mentioned behavior, with a websocket connect / disconnect between the Openhab instance and Shelly taking place hundreds of times per minute.

@lsiepel
Copy link
Contributor

lsiepel commented Dec 18, 2024

All Pro Shellys with FW 1.4.4, however, show the above-mentioned behavior, with a websocket connect / disconnect between the Openhab instance and Shelly taking place hundreds of times per minute.

Maybe the new firmware requires some setting, handshake or similar. To fix this we need a proper error message or documentation. The log does not show anything usefull for fixing it.

I would be interested if the trace level logs anything before disconnecting. Or even better if you have any documentation it would be recommended.

@MiniOh
Copy link
Author

MiniOh commented Dec 18, 2024 •
edited
Loading

All Pro Shellys with FW 1.4.4, however, show the above-mentioned behavior, with a websocket connect / disconnect between the Openhab instance and Shelly taking place hundreds of times per minute.

Maybe the new firmware requires some setting, handshake or similar. To fix this we need a proper error message or documentation. The log does not show anything usefull for fixing it.

I would be interested if the trace level logs anything before disconnecting. Or even better if you have any documentation it would be recommended.

Hello Isiepel,

this is the trace level Log, so the 401 could be the problem?

2024-12-18 20:46:10.513 [DEBUG] [discovery.ShellyDiscoveryParticipant] - shellypro4pm-123456789123: Shelly device discovered: IP-Adress=192.168.0.8, type=shellypro4pm

2024-12-18 20:46:10.515 [TRACE] [shelly.internal.api.ShellyHttpClient] - shellypro4pm-123456789123: HTTP GET http://192.168.0.8/shelly

Accept-Encoding: gzip

User-Agent: Jetty/9.4.54.v20240208

Content-Type: application/x-www-form-urlencoded

2024-12-18 20:46:10.515 [DEBUG] [helly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: WebSocket connected /192.168.0.108:36572<-/192.168.0.8:80, Idle Timeout=2147483647

2024-12-18 20:46:10.550 [TRACE] [shelly.internal.api.ShellyHttpClient] - shellypro4pm-123456789123: HTTP Response 401: 

WWW-Authenticate: Digest qop="auth", realm="shellypro4pm-123456789123", nonce="1734551170", algorithm=SHA-256

Content-Length: 0

Server: ShellyHTTP/1.0.0

Connection: close

2024-12-18 20:46:10.550 [TRACE] [shelly.internal.api.ShellyHttpClient] - shellypro4pm-123456789123: HTTP POST http://192.168.0.8/rpc

Accept-Encoding: gzip

User-Agent: Jetty/9.4.54.v20240208

Authorization: Digest username="admin", realm="shellypro4pm-123456789123", uri="/rpc", nonce="1734551170", cnonce="2796740f", nc="00000001", qop="auth",response="9edc404e0abef6ceeed4cc55c500714b86c95125ce8f6c71f933394e0bc8b280", algorithm="SHA-256", 

Content-Type: application/json; charset=UTF-8

{"id":615799068,"src":"openhab-","method":"Shelly.GetConfig"}

2024-12-18 20:46:10.574 [TRACE] [shelly.internal.api.ShellyHttpClient] - shellypro4pm-123456789123: HTTP Response 200: {"name":"SHELLYPRO4PM-01","id":"shellypro4pm-123456789123","mac":"123456789123","slot":1,"model":"SPSW-004PE16EU","gen":2,"fw_id":"20241011-114451/1.4.4-g6d2a586","ver":"1.4.4","app":"Pro4PM","auth_en":true,"auth_domain":"shellypro4pm-123456789123"}

Content-Type: application/json

Content-Length: 249

Pragma: no-cache

Server: ShellyHTTP/1.0.0

Connection: close

2024-12-18 20:46:10.574 [TRACE] [helly.internal.api2.Shelly2ApiClient] - shellypro4pm-123456789123: API value null was mapped to UNKNOWN

2024-12-18 20:46:10.574 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Connect Rpc Socket (discovery = true)

2024-12-18 20:46:10.574 [DEBUG] [helly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: Connect WebSocket, URI=ws://192.168.0.8/rpc

2024-12-18 20:46:10.576 [TRACE] [shelly.internal.api.ShellyHttpClient] - shellypro4pm-123456789123: HTTP POST http://192.168.0.8/rpc

Accept-Encoding: gzip

User-Agent: Jetty/9.4.54.v20240208

Content-Type: application/json; charset=UTF-8

{"id":1107434443,"src":"openhab-","method":"Shelly.GetConfig"}

2024-12-18 20:46:10.660 [DEBUG] [helly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: WebSocket connected /192.168.0.108:36612<-/192.168.0.8:80, Idle Timeout=2147483647

2024-12-18 20:46:10.678 [TRACE] [shelly.internal.api.ShellyHttpClient] - shellypro4pm-123456789123: HTTP Response 200: {"id":615799068,"src":"shellypro4pm-123456789123","dst":"openhab-","result":{"ble":{"enable":false,"rpc":{"enable":true},"observer":{"enable":false}},"bthome":{},"cloud":{"enable":true,"server":"shelly-72-eu.shelly.cloud:6022/jrpc"},"eth":{"enable":false,"ipv4mode":"dhcp","ip":null,"netmask":null,"gw":null,"nameserver":null},"input:0":{"id":0,"name":null,"type":"switch","enable":true,"invert":false},"input:1":{"id":1,"name":null,"type":"switch","enable":true,"invert":false},"input:2":{"id":2,"name":null,"type":"switch","enable":true,"invert":false},"input:3":{"id":3,"name":null,"type":"switch","enable":true,"invert":false},"knx":{"enable":false,"ia":"15.15.255","routing":{"addr":"224.0.23.12:3671"}},"mqtt":{"enable":false,"server":null,"client_id":"shellypro4pm-123456789123","user":null,"ssl_ca":null,"topic_prefix":null,"rpc_ntf":true,"status_ntf":false,"use_client_cert":false,"enable_rpc":true,"enable_control":true},"switch:0":{"id":0, "name":null,"in_mode":"follow","initial_state":"restore_last", "auto_on":false, "auto_on_delay":60.00, "auto_off":false, "auto_off_delay":60.00,"power_limit":4480,"voltage_limit":280,"undervoltage_limit":0,"autorecover_voltage_errors":false,"current_limit":16.000},"switch:1":{"id":1, "name":null,"in_mode":"follow","initial_state":"restore_last", "auto_on":false, "auto_on_delay":60.00, "auto_off":false, "auto_off_delay":60.00,"power_limit":4480,"voltage_limit":280,"undervoltage_limit":0,"autorecover_voltage_errors":false,"current_limit":16.000},"switch:2":{"id":2, "name":null,"in_mode":"follow","initial_state":"restore_last", "auto_on":false, "auto_on_delay":60.00, "auto_off":false, "auto_off_delay":60.00,"power_limit":4480,"voltage_limit":280,"undervoltage_limit":0,"autorecover_voltage_errors":false,"current_limit":16.000},"switch:3":{"id":3, "name":null,"in_mode":"follow","initial_state":"restore_last", "auto_on":false, "auto_on_delay":60.00, "auto_off":false, "auto_off_delay":60.00,"power_limit":4480,"voltage_limit":280,"undervoltage_limit":0,"autorecover_voltage_errors":false,"current_limit":16.000},"sys":{"device":{"name":"SHELLYPRO4PM-01","mac":"123456789123","fw_id":"20241011-114451/1.4.4-g6d2a586","discoverable":true,"eco_mode":false},"location":{"tz":"Europe/Berlin","lat":49.248600,"lon":6.864500},"debug":{"level":2,"file_level":null,"mqtt":{"enable":false},"websocket":{"enable":true},"udp":{"addr":null}},"ui_data":{},"rpc_udp":{"dst_addr":null,"listen_port":null},"sntp":{"server":"time.google.com"},"cfg_rev":69},"ui":{"idle_brightness":50},"wifi":{"ap":{"ssid":"ShellyPro4PM-123456789123","is_open":true, "enable":false, "range_extender": {"enable":false}},"sta":{"ssid":"WLAN","is_open":false, "enable":true, "ipv4mode":"dhcp","ip":null,"netmask":null,"gw":null,"nameserver":null},"sta1":{"ssid":null,"is_open":true, "enable":false, "ipv4mode":"dhcp","ip":null,"netmask":null,"gw":null,"nameserver":null},"roam":{"rssi_thr":-80,"interval":60}},"ws":{"enable":false,"server":null,"ssl_ca":"ca.pem"}}}

Content-Type: application/json

Content-Length: 2986

Server: ShellyHTTP/1.0.0

Connection: close

2024-12-18 20:46:10.679 [TRACE] [shelly.internal.api.ShellyHttpClient] - shellypro4pm-123456789123: HTTP Response 401: 

WWW-Authenticate: Digest qop="auth", realm="shellypro4pm-123456789123", nonce="1734551170", algorithm=SHA-256

Content-Length: 0

Server: ShellyHTTP/1.0.0

Connection: close

2024-12-18 20:46:10.679 [TRACE] [helly.internal.api2.Shelly2ApiClient] - shellypro4pm-123456789123: API value follow was mapped to edge

2024-12-18 20:46:10.679 [TRACE] [helly.internal.api2.Shelly2ApiClient] - shellypro4pm-123456789123: API value follow was mapped to edge

2024-12-18 20:46:10.679 [TRACE] [shelly.internal.api.ShellyHttpClient] - shellypro4pm-123456789123: HTTP POST http://192.168.0.8/rpc

Accept-Encoding: gzip

User-Agent: Jetty/9.4.54.v20240208

Authorization: Digest username="admin", realm="shellypro4pm-123456789123", uri="/rpc", nonce="1734551170", cnonce="71b02cf", nc="00000001", qop="auth",response="12341234123412231231231231231231123131313123123123131313132123123", algorithm="SHA-256", 

Content-Type: application/json; charset=UTF-8

{"id":1107434443,"src":"openhab-","method":"Shelly.GetConfig"}

2024-12-18 20:46:10.679 [TRACE] [helly.internal.api2.Shelly2ApiClient] - shellypro4pm-123456789123: API value follow was mapped to edge

2024-12-18 20:46:10.679 [TRACE] [helly.internal.api2.Shelly2ApiClient] - shellypro4pm-123456789123: API value follow was mapped to edge

2024-12-18 20:46:10.680 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Closing Rpc API (socket is connected, discovery=true)

2024-12-18 20:46:10.680 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: Disconnect Rpc Socket

2024-12-18 20:46:10.680 [DEBUG] [helly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: Disconnecting WebSocket (/192.168.0.108:36572 -> /192.168.0.8:80)

2024-12-18 20:46:10.680 [TRACE] [helly.internal.api2.Shelly2RpcSocket] - shellypro4pm-123456789123: Rpc connection closed: 1006 - Disconnected

2024-12-18 20:46:10.680 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellypro4pm-123456789123: WebSocket connection closed, status = 1006/Disconnected

2024-12-18 20:46:10.682 [DEBUG] [discovery.ShellyDiscoveryParticipant] - shellypro4pm-123456789123: Shelly device discovered: IP-Adress=192.168.0.8, type=shellypro4pm

2024-12-18 20:46:10.684 [TRACE] [shelly.internal.api.ShellyHttpClient] - shellypro4pm-123456789123: HTTP GET http://192.168.0.8/shelly

Accept-Encoding: gzip

User-Agent: Jetty/9.4.54.v20240208

Content-Type: application/x-www-form-urlencoded

@lsiepel
Copy link
Contributor

lsiepel commented Dec 18, 2024

401 means the Shelly actively rejects the request due to some authentication issue.

It might be something simple as rejected user agent as well as some complex encryption schema. Are you aware of other projects having similar connectivity issue with this firmware version? Maybe we can look at how others solved the Shelly connection.

@MiniOh
Copy link
Author

MiniOh commented Dec 18, 2024

I'm not sure if the 401 error is really a problem.
After that 401 comes "Authorization: Digest username="admin" ...
and then later "shellypro4pm-123456789123: Disconnecting WebSocket (/192.168.0.108:36572 -> /192.168.0.8:80)"
It actually looks like Openhab is actively terminating the connection, right?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug An unexpected problem or unintended behavior of an add-on
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@lsiepel @MiniOh