Shelly Plus 2pm not discovered by binding and failing manual add

aenotiad · September 23, 2023, 6:02pm

Openhab Version 4.0.3 Openhabian Raspberry Pi 4B
Shelly binding installed from UI
Shelly Plus 2pm firmware version 1.0.3 in roller shutter mode
Description:
Fresh install of Openhab 4.0.3 (I run a longstanding 2.5.12 setup on a different pi and am preparing for a migration to Openhab 4 as well as introducing quite a few shelly plus devices in my setup). The binding discovers happily all my dimmer2 and switch25 devices but fails to discover a (pingable and connectable) plus25pm device on the same subnet and broadcast domain.
When I try to add it manually using the IP address I get the following debug log

2023-09-23 20:52:36.072 [DEBUG] [shelly.internal.ShellyHandlerFactory] - ShellyPro 2PM Roller: Create new thing of type shelly:shellypro2pm-roller using ShellyRelayHandler
2023-09-23 20:52:36.142 [DEBUG] [shelly.internal.ShellyHandlerFactory] - Thing handler for uid shelly:shellypro2pm-roller:dad78c9269 added, total things = 6
2023-09-23 20:52:36.146 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellypro2pm-roller:dad78c9269' changed from UNINITIALIZED to INITIALIZING
2023-09-23 20:52:38.151 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Using userId admin from bindingConfig
2023-09-23 20:52:38.152 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Device config: Device address=192.168.10.230, HTTP user/password=admin/***, update interval=60
2023-09-23 20:52:38.152 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Configured Events: Button: false, Switch (on/off): true, Push: true, Roller: true, Sensor: true, CoIoT: false, Enable AutoCoIoT: true
2023-09-23 20:52:38.153 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Start initializing for thing ShellyPro 2PM Roller, type shellypro2pm-roller, IP address 192.168.10.230, Gen2: true, CoIoT: false
2023-09-23 20:52:38.170 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellypro2pm-roller-dad78c9269: Connect Rpc Socket (discovery = false)
2023-09-23 20:52:38.170 [DEBUG] [helly.internal.api2.Shelly2RpcSocket] - ShellyPro 2PM Roller: Connect WebSocket, URI=ws://192.168.10.230/rpc
2023-09-23 20:52:38.205 [DEBUG] [helly.internal.api2.Shelly2RpcSocket] - ShellyPro 2PM Roller: WebSocket connected /192.168.10.231:37560<-/192.168.10.230:80, Idle Timeout=2147483647
2023-09-23 20:52:38.248 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Unable to initialize, retrying later
2023-09-23 20:52:38.251 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Update status job started, interval=20*3=60sec.
2023-09-23 20:52:38.154 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellypro2pm-roller:dad78c9269' changed from INITIALIZING to UNKNOWN (CONFIGURATION_PENDING): Initializing or device in sleep mode.

60 seconds later it retries initialisation with the following debug

2023-09-23 20:53:37.254 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Status update triggered thing initialization
2023-09-23 20:53:37.255 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Start initializing for thing ShellyPro 2PM Roller, type shellypro2pm-roller, IP address 192.168.10.230, Gen2: true, CoIoT: false
2023-09-23 20:53:37.257 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellypro2pm-roller-dad78c9269: Disconnect Rpc Socket on initialize
2023-09-23 20:53:37.258 [DEBUG] [helly.internal.api2.Shelly2RpcSocket] - ShellyPro 2PM Roller: Disconnecting WebSocket (/192.168.10.231:37560 -> /192.168.10.230:80)
2023-09-23 20:53:37.264 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellypro2pm-roller-dad78c9269: WebSocket connection closed, status = 1006/Disconnected
2023-09-23 20:53:37.267 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellypro2pm-roller-dad78c9269: Closing Rpc API (socket is disconnected, discovery=false)
2023-09-23 20:53:37.295 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellypro2pm-roller-dad78c9269: Connect Rpc Socket (discovery = false)
2023-09-23 20:53:37.296 [DEBUG] [helly.internal.api2.Shelly2RpcSocket] - ShellyPro 2PM Roller: Connect WebSocket, URI=ws://192.168.10.230/rpc
2023-09-23 20:53:37.367 [DEBUG] [helly.internal.api2.Shelly2RpcSocket] - ShellyPro 2PM Roller: WebSocket connected /192.168.10.231:54052<-/192.168.10.230:80, Idle Timeout=2147483647
2023-09-23 20:53:37.392 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Unable to refresh status: Unable to update status
2023-09-23 20:53:37.397 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellypro2pm-roller-dad78c9269: Enabling channel cache (20 updates / 60s)
2023-09-23 20:53:37.267 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellypro2pm-roller:dad78c9269' changed from UNKNOWN (CONFIGURATION_PENDING): Initializing or device in sleep mode. to OFFLINE (COMMUNICATION_ERROR): Unexpected error: WebSocket connection closed abnormal

and the error keeps alternating between

(COMMUNICATION_ERROR): Unexpected error: WebSocket connection closed abnormal

and

(CONFIGURATION_PENDING): Initializing or device in sleep mode.

I can see it is doing an initial connect and getting the right response including discovering the plus sensor add on but then something goes sideways…
Stumped I’m afraid so casting to the wider community
Have lots of MQTT, Modbus, Z-Wave, Shell Gen-1 and other assorted things running but this one is failing me…

Thanks!

/A

Rivi · September 24, 2023, 8:44am

I have no clue why, but two out of 4 of my shelly plus 2PM did the same on me 2 days ago. They appear totally ok on their own web interface. Just this morning I then did a factory reset and redid network and all other setup, now works again. I hope it’ll last.

aenotiad · September 24, 2023, 10:21am

Ok so that worked - but only partially
Thing now gets discovered and added BUT
while the Shelly add on with the DS sensor is discovered

[y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Shelly Add-On detected with at least 1 external sensor

The channel for add-on is never added or displayed…
The Shelly sends updates regularly

shellyplus2pm-c049ef8b2474: NotifyStatus update received: {"src":"shellyplus2pm-c049ef8b2474","dst":"shellyplus2pm-c049ef8b2474","method":"NotifyStatus","params":{"ts":1.69555071364E9,"temperature:100":{"id":100,"tC":35.31,"tF":95.56}}}

But there is no channel to bind to per the screenshot below

Any further clues?

Rivi · September 24, 2023, 11:13am

You may need to activate the “show advanced” box to see the channel.

aenotiad · September 24, 2023, 11:32am

I did already - no luck

I also watch the debug log when adding the channels and the add-on channel never appears during the initialisation phase (just retested - just in case)

2023-09-24 14:29:33.776 [DEBUG] [g.shelly.internal.api2.Shelly2ApiRpc] - shellyplus2pm-c049ef8b2474: NotifyStatus update received: {"id":311527238,"src":"shellyplus2pm-c049ef8b2474","dst":"shellyplus2pm-c049ef8b2474","params":{"ble":null,"cloud":{"connected":false},"mqtt":{"connected":false},"sys":{"mac":"C049EF8B2474","restart_required":false,"time":"14:29","unixtime":1695554973,"uptime":5005,"ram_size":257928,"ram_free":119032,"fs_size":458752,"fs_free":143360,"cfg_rev":10,"available_updates":null,"webhook_rev":1},"wifi":{"sta_ip":"192.168.10.230","status":"got ip","ssid":"HomeAuto","rssi":-52},"input:0":{"id":0},"input:1":{"id":1},"cover:0":{"id":0,"source":"init","state":"stopped","apower":0.0,"voltage":228.4,"current":0.0,"pf":0.0,"aenergy":{"total":0.653,"by_minute":[0.0,0.0,0.0],"minute_ts":1695554973},"pos_control":false,"temperature":{"tC":65.3,"tF":149.6}},"temperature:100":{"id":100,"tC":35.7,"tF":96.2}},"result":{"ble":{},"cloud":{"connected":false},"mqtt":{"connected":false},"sys":{"mac":"C049EF8B2474","restart_required":false,"time":"14:29","unixtime":1695554973,"uptime":5005,"ram_size":257928,"ram_free":119032,"fs_size":458752,"fs_free":143360,"cfg_rev":10,"available_updates":{},"webhook_rev":1},"wifi":{"sta_ip":"192.168.10.230","status":"got ip","ssid":"HomeAuto","rssi":-52},"input:0":{"id":0},"input:1":{"id":1},"cover:0":{"id":0,"source":"init","state":"stopped","apower":0.0,"voltage":228.4,"current":0.0,"pf":0.0,"aenergy":{"total":0.653,"by_minute":[0.0,0.0,0.0],"minute_ts":1695554973},"pos_control":false,"temperature":{"tC":65.3,"tF":149.6}},"temperature:100":{"id":100,"tC":35.7,"tF":96.2}}}
2023-09-24 14:29:33.777 [DEBUG] [helly.internal.api2.Shelly2ApiClient] - shellyplus2pm-c049ef8b2474: Roller status changed from stop to stop, updateChannels=true
2023-09-24 14:29:33.821 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Updating channel definitions, 3 channels
2023-09-24 14:29:33.822 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Adding channel roller#control
2023-09-24 14:29:33.823 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Adding channel roller#state
2023-09-24 14:29:33.823 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Adding channel roller#event
2023-09-24 14:29:33.842 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Channel definitions updated
2023-09-24 14:29:33.845 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Updating channel definitions, 2 channels
2023-09-24 14:29:33.846 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Adding channel roller#input1
2023-09-24 14:29:33.846 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Adding channel roller#input2
2023-09-24 14:29:33.868 [DEBUG] [y.internal.handler.ShellyBaseHandler] - shellyplus2pm-c049ef8b2474: Channel definitions updated

While the status update json above contains the temperature field the channel is never added…
- thanks for the help BTW

Rivi · September 24, 2023, 11:36am

Apart form adding the item linked manually as file (which I don’t think would work, but as a desperate last idea) I am afraid I can’t suggest anything else, as I don’t have addons.

aenotiad · September 24, 2023, 1:09pm

Thanks for the help. In the interests of clarity I will open a new thread with just the add on problem and mark your initial answer as solution