search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.58k forks source link

[silvercrest] Plugs stay offline #3229

Closed NorthyIE closed 3 years ago

NorthyIE commented 6 years ago

Expected Behavior

New WiFi Plugs should be discovered automatically by the binding With existing WiFi Plugs, openHAB should be able to recieve information from the Plugs telling the status (switched on/off).

Current Behavior

My setup was working previously. I recently got another ALDI Wifi Plug and added it via the paper UI. The first thing I noticed was that the Plug was not discovered automatically in the Paper UI Inbox. I added it manually (using MAC address, IP address and correct type). As of that moment, all three Wifi Plugs now show “Offline” in OpenHAB. I can switch them on/off as always, but the status is not being pulled from the Plugs

I turned on DEBUG logging for the SilverCrest Binding and it shows the following: 2018-02-08 15:54:57.262 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Begin of Socket keep alive thread routine. Current configuration update interval: 60 seconds. 2018-02-08 15:54:57.268 [DEBUG] [handler.SilvercrestWifiSocketHandler] - It has been passed 1518101697 seconds since the last update on socket with mac address 009569A640D0. 2018-02-08 15:54:57.273 [DEBUG] [handler.SilvercrestWifiSocketHandler] - No updates have been received for a long time, search the mac address 009569A640D0 in network... 2018-02-08 15:54:57.278 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Will query for device with mac address 009569A640D0 in network with broadcast address /192.168.100.255 2018-02-08 15:54:57.283 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Sent packet to address: /192.168.100.255 and port 8530 2018-02-08 15:54:57.283 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.2. Will process the packet... 2018-02-08 15:54:57.289 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket. 2018-02-08 15:54:57.294 [DEBUG] [handler.SilvercrestWifiSocketHandler] - No updates have been received for a long long time will put the thing with mac address 009569A640D0 OFFLINE. 2018-02-08 15:54:57.299 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Send command for mac addr: 009569A640D0 with type: GPIO_STATUS with hostaddress: 192.168.100.252 2018-02-08 15:54:57.304 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Sent packet to address: /192.168.100.252 and port 8530 2018-02-08 15:54:57.316 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.252. Will process the packet... 2018-02-08 15:54:57.320 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket. 2018-02-08 15:54:57.323 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.252. Will process the packet... 2018-02-08 15:54:57.327 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket. 2018-02-08 15:54:57.333 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Begin of Socket keep alive thread routine. Current configuration update interval: 60 seconds. 2018-02-08 15:54:57.338 [DEBUG] [handler.SilvercrestWifiSocketHandler] - It has been passed 1518101697 seconds since the last update on socket with mac address 009569A6907C. 2018-02-08 15:54:57.341 [DEBUG] [handler.SilvercrestWifiSocketHandler] - No updates have been received for a long time, search the mac address 009569A6907C in network... 2018-02-08 15:54:57.347 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Will query for device with mac address 009569A6907C in network with broadcast address /192.168.100.255 2018-02-08 15:54:57.350 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Sent packet to address: /192.168.100.255 and port 8530 2018-02-08 15:54:57.350 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.2. Will process the packet... 2018-02-08 15:54:57.353 [DEBUG] [handler.SilvercrestWifiSocketHandler] - No updates have been received for a long long time will put the thing with mac address 009569A6907C OFFLINE. 2018-02-08 15:54:57.355 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket. 2018-02-08 15:54:57.358 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Send command for mac addr: 009569A6907C with type: GPIO_STATUS with hostaddress: 192.168.100.251 2018-02-08 15:54:57.362 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Sent packet to address: /192.168.100.251 and port 8530 2018-02-08 15:54:57.416 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Begin of Socket keep alive thread routine. Current configuration update interval: 60 seconds. 2018-02-08 15:54:57.418 [DEBUG] [handler.SilvercrestWifiSocketHandler] - It has been passed 1518101697 seconds since the last update on socket with mac address 009569A636F8. 2018-02-08 15:54:57.420 [DEBUG] [handler.SilvercrestWifiSocketHandler] - No updates have been received for a long time, search the mac address 009569A636F8 in network... 2018-02-08 15:54:57.422 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Will query for device with mac address 009569A636F8 in network with broadcast address /192.168.100.255 2018-02-08 15:54:57.425 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.2. Will process the packet... 2018-02-08 15:54:57.425 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Sent packet to address: /192.168.100.255 and port 8530 2018-02-08 15:54:57.426 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket. 2018-02-08 15:54:57.426 [DEBUG] [handler.SilvercrestWifiSocketHandler] - No updates have been received for a long long time will put the thing with mac address 009569A636F8 OFFLINE. 2018-02-08 15:54:57.429 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Send command for mac addr: 009569A636F8 with type: GPIO_STATUS with hostaddress: 192.168.100.253 2018-02-08 15:54:57.434 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Sent packet to address: /192.168.100.253 and port 8530 2018-02-08 15:54:57.526 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.253. Will process the packet... 2018-02-08 15:54:57.529 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket.

Steps to Reproduce

  1. install openHAB on Raspbian Stretch
  2. install the Silvercrest Binding
  3. Try to scan for new items / Add the items manually

Troubleshooting

I tried removing and reinstalling the devices, the binding and openHAB. To make sure that I was not causing problems with my configuration, I used an empty configuration in openHAB, just installed the binding and adding the Plugs.

I’ve installed a fresh openHAB on a spare raspberry pi and the issue is the same. I have only added the silvercrest binding, and enabled debug logging. This shows up in the logs:

` 2018-02-09 18:40:53.315 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.251. Will process the packet... 2018-02-09 18:40:53.318 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket. 2018-02-09 18:41:24.361 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.2. Will process the packet... 2018-02-09 18:41:24.365 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket.

` The message is triggered everytime my “normal” openHAB (192.168.100.2) checks for an update or the plugs send the update (when I press the button on the plug, the message appears immediately with the plug’s IP address). It seems like the data cannot be read from the UDP packets sent by the plugs. The Android app works fine for all three so it is unlikely that the problem is with the plugs. I also checked that the firmware has not changed from when I bought them. ## Your Environment openHAB 2.2 Silvercrest Binding 2.2.0 Raspbian Stretch (up to date) on Raspbian Pi2 and Pi3 Latest Java, I also tried Zulu. IP addresses: 192.168.100.2 rasbperry 192.168.100.251 WiFiPlug-1 192.168.100.251 WiFiPlug-2 192.168.100.251 WiFiPlug-3
NorthyIE commented 6 years ago

@jmvaz and @Ronson1909 , if you have the possibility to have a look at this, I would greatly appreciate it.

I have captured the packets from one of my WiFi Plugs using wireshark while turning it on and off manually: 01:44:00:95:69:a6:90:7c:10:76:e3:10:a0:64:a7:b4:3c:09:5b:7b:ea:18:a6:fe:4f 01:44:00:95:69:a6:90:7c:10:c2:46:98:62:cb:1d:5e:20:42:1c:c0:80:11:8b:25:8f 01:44:00:95:69:a6:90:7c:10:18:81:2c:aa:2d:cc:e4:9a:30:e0:6e:a4:da:fc:15:c2 01:44:00:95:69:a6:90:7c:10:ed:b9:a3:d6:73:86:64:9e:20:9e:1d:e5:0e:21:5d:70 ... I have attached the wireshark dump file: WiFiPlug1.zip

I am trying to decipher the message and compare it to https://github.com/Ronson1909/openhab2-addons/blob/12956713c0cee3910f57138f70925ab01521f1aa/addons/binding/org.openhab.binding.silvercrestwifisocket/src/main/java/org/openhab/binding/silvercrestwifisocket/internal/utils/WifiSocketPacketConverter.java, however I'm not really good at this.

I also enabled trace logging on the binding, which shows the following:

2018-02-10 11:37:30.374 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Begin of Socket keep alive thread routine. Current configuration update interval: 60 seconds. 2018-02-10 11:37:30.377 [TRACE] [handler.SilvercrestWifiSocketHandler] - Latest Update: -1 Now: 1518259050377 Delta: 1518259050 seconds 2018-02-10 11:37:30.382 [DEBUG] [handler.SilvercrestWifiSocketHandler] - It has been passed 1518259050 seconds since the last update on socket with mac address 009569A640D0. 2018-02-10 11:37:30.385 [DEBUG] [handler.SilvercrestWifiSocketHandler] - No updates have been received for a long time, search the mac address 009569A640D0 in network... 2018-02-10 11:37:30.388 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Will query for device with mac address 009569A640D0 in network with broadcast address /192.168.100.255 2018-02-10 11:37:30.390 [TRACE] [rnal.utils.WifiSocketPacketConverter] - Encrypted data={00FFFFC21192DD23009569A640D00202} 2018-02-10 11:37:30.393 [TRACE] [rnal.utils.WifiSocketPacketConverter] - Decrypted data={F3972479237D7B0E7818D9B7AA8BCE0C} 2018-02-10 11:37:30.395 [TRACE] [rnal.utils.WifiSocketPacketConverter] - Request Packet: 0140009569A640D010F3972479237D7B0E7818D9B7AA8BCE0C 2018-02-10 11:37:30.397 [TRACE] [rnal.utils.WifiSocketPacketConverter] - Request packet decrypted data: [00FFFFC21192DD23009569A640D00202] with lenght: 32 2018-02-10 11:37:30.400 [TRACE] [handler.SilvercrestWifiSocketHandler] - Preparing packet to send... 2018-02-10 11:37:30.402 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.2. Will process the packet... 2018-02-10 11:37:30.402 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Sent packet to address: /192.168.100.255 and port 8530 2018-02-10 11:37:30.404 [DEBUG] [handler.SilvercrestWifiSocketHandler] - No updates have been received for a long long time will put the thing with mac address 009569A640D0 OFFLINE. 2018-02-10 11:37:30.404 [TRACE] [rnal.utils.WifiSocketPacketConverter] - The packet received is not one response! 2018-02-10 11:37:30.405 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket. 2018-02-10 11:37:30.406 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Send command for mac addr: 009569A640D0 with type: GPIO_STATUS with hostaddress: 192.168.100.252 2018-02-10 11:37:30.408 [TRACE] [rnal.utils.WifiSocketPacketConverter] - Encrypted data={00FFFFC21192DD020000000004040404} 2018-02-10 11:37:30.410 [TRACE] [rnal.utils.WifiSocketPacketConverter] - Decrypted data={7950A5EC83322479AD8A6F8F93B39C8C} 2018-02-10 11:37:30.411 [TRACE] [rnal.utils.WifiSocketPacketConverter] - Request Packet: 0140009569A640D0107950A5EC83322479AD8A6F8F93B39C8C 2018-02-10 11:37:30.413 [TRACE] [rnal.utils.WifiSocketPacketConverter] - Request packet decrypted data: [00FFFFC21192DD020000000004040404] with lenght: 32 2018-02-10 11:37:30.415 [TRACE] [handler.SilvercrestWifiSocketHandler] - Preparing packet to send... 2018-02-10 11:37:30.417 [DEBUG] [handler.SilvercrestWifiSocketHandler] - Sent packet to address: /192.168.100.252 and port 8530 2018-02-10 11:37:30.491 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.252. Will process the packet... 2018-02-10 11:37:30.492 [TRACE] [rnal.utils.WifiSocketPacketConverter] - The packet received is not one response! 2018-02-10 11:37:30.494 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket. 2018-02-10 11:37:30.496 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - Received packet from: 192.168.100.252. Will process the packet... 2018-02-10 11:37:30.497 [TRACE] [rnal.utils.WifiSocketPacketConverter] - The packet received is not one response! 2018-02-10 11:37:30.499 [DEBUG] [restWifiSocketUpdateReceiverRunnable] - The message received is not one response. Probably the message received is one broadcast message looking for the socket. 2018-02-10 11:37:40.510 [TRACE] [restWifiSocketUpdateReceiverRunnable] - Socket Timeout receiving packet.

Is there a way to comfirm if the data sent from my Plugs is valid?

jmvaz commented 6 years ago

On a quick look, seems that the incomming message protocol has changed. I dont have any socket to test, should be @Ronson1909 to look this problem.

Ronson1909 commented 6 years ago

Hi @NorthyIE ,

from the first 4 Wireshark packets I recognize that it seems to be a Silvercrest (Lidl) device. Is that correct?

FYI: You can manually analyse this with the great documentation on https://wiki.fhem.de/wiki/Silvercrest_SWS_A1_Wifi If you decrypt the encrypted part (I was trying to find an online tool do give you a link but I was not successful in finding an online tool that exactly works the way Java is doing for our plugs, so I did but using the openhab code) you get

000029C1117150010000FFFF04040404

for the first of your provided message. There you can find C1 and 7150 with is both for Silvercrest. However, in the traces you provided I see messages with C2 and 92DD which are the values for EasyHome (Aldi).

So long story short: Can you confirm that you have a SilverCrest and have you configured the plug as Silvercrest? I assume you have a Silvercrest but configured it as EasyHome and therefore it's not working.

NorthyIE commented 6 years ago

Hi @Ronson1909 and @jmvaz, thanks for the replies and for the very useful link!

I can confirm that the WiFi Plugs are all from ALDI. They are the exact same make and model, same production date (05/16) even the firmware is the same. Here is a picture of the plug: img_20180213_160940

I have tried switching the Plugs to Lidl in the Silvercrest binding, but that did not change anything - all Plugs are still shown as offline.

To add to the confusion: I tried resetting WiFiPlug1 and WiFiPlug2 to factory default in the WebInterface and add them again using the Smart2Connect-App for Android. After this, WiFiPlug-3 showed online in openHAB (using the ALDI setting), even though I did not change anything on that Plug at all.. image

I then removed WiFiPlug-3 and re-added it in the Paper UI and the binding is still able to communicate with the Plug: 2018-02-13 16:29:09.176 [hingStatusInfoChangedEvent] - 'silvercrestwifisocket:wifiSocket:009569A636F8' changed from ONLINE to REMOVING 2018-02-13 16:29:09.186 [hingStatusInfoChangedEvent] - 'silvercrestwifisocket:wifiSocket:009569A636F8' changed from REMOVING to REMOVED 2018-02-13 16:29:09.200 [hingStatusInfoChangedEvent] - 'silvercrestwifisocket:wifiSocket:009569A636F8' changed from REMOVED to UNINITIALIZED 2018-02-13 16:29:09.237 [hingStatusInfoChangedEvent] - 'silvercrestwifisocket:wifiSocket:009569A636F8' changed from REMOVED to UNINITIALIZED (HANDLER_MISSING_ERROR) 2018-02-13 16:30:13.974 [hingStatusInfoChangedEvent] - 'silvercrestwifisocket:wifiSocket:009569A636F8' changed from UNINITIALIZED to INITIALIZING 2018-02-13 16:30:13.985 [hingStatusInfoChangedEvent] - 'silvercrestwifisocket:wifiSocket:009569A636F8' changed from INITIALIZING to ONLINE 2018-02-13 16:30:14.025 [me.event.ThingUpdatedEvent] - Thing 'silvercrestwifisocket:wifiSocket:009569A636F8' has been updated. 2018-02-13 16:30:14.975 [hingStatusInfoChangedEvent] - 'silvercrestwifisocket:wifiSocket:009569A636F8' changed from ONLINE to OFFLINE 2018-02-13 16:31:15.124 [me.event.ThingUpdatedEvent] - Thing 'silvercrestwifisocket:wifiSocket:009569A636F8' has been updated. 2018-02-13 16:31:15.128 [hingStatusInfoChangedEvent] - 'silvercrestwifisocket:wifiSocket:009569A636F8' changed from OFFLINE to ONLINE

I'm (at least yet!) not able to get any information for WiFiPlug-1 and WiFiPlug-2 though.

Ronson1909 commented 6 years ago

Hi @NorthyIE ,

that's exactly the plug I have, so I assume it should work. You also never wrote what the actual problem is. Have you included it e.g. in a BasicUI and tried to switch it on and off and did(n't) it work? Just to understand that: Do you have three physical plugs or only one?

I assume you only have one because you never said that you have more than one. During a factory reset (I never have tried that) maybe the plug also changes its MAC address. That would explain why it was first identified as WiFiPlug-1, then WiFiPlug-2 and finally WiFiPlug-3 (always with different MAC addresses) and only that last one is online. So the other 2 cannot be used anymore and you won't "get any information" for them anymore.

hmerk commented 3 years ago

closed due to inactivity