Motion Blinds integration show all entities as unavailable

haberda commented 3 years ago

The problem

I have a problem with the new (as of 2020.12.x) Motion Blinds integration using 2021.1.0 and it still seems to be an issue with 2021.1.1.

Basically, the integration never fully starts and the logs show errors related to initializing the integration. I see that there were commits related to discovery in 2021.0. When I roll back to 2020.12.2 it works again.

For reference I am using a supervised install on an x86 Debian 10, kernel 5.9.

I also attempted to setup this integration on a RasPi3 Running OS 5.10, same deal.

Environment

Home Assistant Core release with the issue: 2021.1.x
Last working Home Assistant Core release (if known): 2020.12.2
Operating environment (OS/Container/Supervised/Core): Supervised Debian and HassOS 5.10 RasPi3
Integration causing this issue: Motion Blinds
Link to integration documentation on our website: https://www.home-assistant.io/integrations/motion_blinds/

Problem-relevant `configuration.yaml`

This is a UI based integration. I simply followed the setup flow. This works fine in 2020.12.x but fails in 2021.1.x. I also tried: remove the integration->upgrade to 2021.1.x->install the integration, with the same result.

Traceback/Error logs

Here are some relevant debug logs:

2021-01-09 08:39:08 INFO (MainThread) [homeassistant.setup] Setting up motion_blinds
2021-01-09 08:39:08 INFO (MainThread) [homeassistant.setup] Setup of domain motion_blinds took 0.1 seconds
2021-01-09 08:39:08 INFO (SyncWorker_13) [motionblinds.motion_blinds] Creating multicast socket
2021-01-09 08:39:08 DEBUG (MainThread) [homeassistant.components.motion_blinds.gateway] Initializing with host 192.168.2.xxx (key b9e...)
2021-01-09 08:39:09 DEBUG (MainThread) [homeassistant.components.motion_blinds.gateway] Motion gateway mac: 807d6aaa3f50, protocol: 0.9 2021-01-09 08:39:14 DEBUG (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred at 1 attempts while waiting on multicast push from update request, trying again...detected
2021-01-09 08:39:19 DEBUG (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred at 2 attempts while waiting on multicast push from update request, trying again...
2021-01-09 08:39:24 DEBUG (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred at 3 attempts while waiting on multicast push from update request, trying again...
2021-01-09 08:39:29 DEBUG (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred at 4 attempts while waiting on multicast push from update request, trying again...
2021-01-09 08:39:34 ERROR (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred on 5 attempts while waiting on multicast push from update request, communication between gateway and blind might be bad.
2021-01-09 08:39:39 DEBUG (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred at 1 attempts while waiting on multicast push from update request, trying again...
2021-01-09 08:39:41 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: motion_blinds
2021-01-09 08:39:44 DEBUG (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred at 2 attempts while waiting on multicast push from update request, trying again...
2021-01-09 08:39:49 DEBUG (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred at 3 attempts while waiting on multicast push from update request, trying again...
2021-01-09 08:39:54 DEBUG (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred at 4 attempts while waiting on multicast push from update request, trying again...
2021-01-09 08:39:59 ERROR (SyncWorker_2) [motionblinds.motion_blinds] Timeout of 5.0 sec occurred on 5 attempts while waiting on multicast push from update request, communication between gateway and blind might be bad.

Things go on like that for some time then:

2021-01-09 08:42:04 DEBUG (MainThread) [homeassistant.components.motion_blinds] Finished fetching Motion Gateway data in 175.025 seconds
2021-01-09 08:42:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=motion_blinds>
But nothing is actually available. Then:

2021-01-09 08:42:05 DEBUG (MainThread) [homeassistant.helpers.translation] Cache miss for en: cover.motion_blinds, sensor.motion_blinds, motion_blinds
2021-01-09 08:42:05 DEBUG (SyncWorker_15) [homeassistant.util.json] JSON file not found: /usr/src/homeassistant/homeassistant/components/motion_blinds/translations/cover.en.json
2021-01-09 08:42:05 DEBUG (SyncWorker_15) [homeassistant.util.json] JSON file not found: /usr/src/homeassistant/homeassistant/components/motion_blinds/translations/sensor.en.json

Additional information

Rolling back to 2020.12.x on both the Supervised and HassOS install resolves the issue and the blinds become available again. I have seen other people note problems with vlans and this integration in other reported issues. I do have this on an IOT vlan, but my supervised install has multiple NICs with one NIC being on the vlan. The RasPi is on my primary vlan. My firewall rules are set to allow communication from primary vlan->IOT vlan but not the other way. This has never been a problem for me, as just about everything IOT is on that vlan and works fine. I just thought I would mention it.

probot-home-assistant[bot] commented 3 years ago

motion_blinds documentation motion_blinds source _{^{(message by IssueLinks)}}

probot-home-assistant[bot] commented 3 years ago

Hey there @starkillerog, mind taking a look at this issue as its been labeled with an integration (motion_blinds) you are listed as a codeowner for? Thanks! _{^{(message by CodeOwnersMention)}}

starkillerOG commented 3 years ago

The newest version of the motion_blinds integration uses UDP multicast communication with the gateway. The errors in the log you posted indeed indicate that the UDP multicast pushes never arrive at HomeAssistant. This can have 2 causes: 1) The motion gateway is not able to communicate with the blinds (but in that case you schould also be having trouble moving the blinds through the motion blinds app). 2) Your network setup is blocking UDP multicast messages sent by the motion gateway to arrive at the device running HomeAssistant.

It sounds very much like situation 2 is going on. I am not an expert in these kinds of networking issues... Maybe @aboogerd could explain how he solved it.

One thing you could try is using a diffrent interface for the multicast communication, also not an expert on that topic, but you could try binding the socket to the IP of the device running HomeAssistant. The HomeAssistant integration does not yet support that, but the underlying library does. You can test it by running the following python script:

from motionblinds import MotionMulticast, MotionGateway

motion_multicast = MotionMulticast(interface='192.168.1.IP_HOMEASSISTANT')
motion_multicast.Start_listen()

m = MotionGateway(ip = "192.168.1.IP_GATEWAY", key = "12ab345c-d67e-8f", multicast = motion_multicast)
m.GetDeviceList()
m.Update()
for blind in m.device_list.values():
    blind.Update()
    print(blind)

motion_multicast.Stop_listen()

This test script will produce timeout errors when the UDP multicast communication is blocked (interface='any' is used) and might work when you use the HomeAssistant IP as interface. You need to fill in your IPs/key for:

interface='192.168.1.IP_HOMEASSISTANT'
ip = "192.168.1.IP_GATEWAY"
key = "12ab345c-d67e-8f"

haberda commented 3 years ago

This is my output from the python script: Timeout of 5.0 sec occurred on 5 attempts while waiting on multicast push from update request, communication between gateway and blind might be bad. Traceback (most recent call last): File "test.py", line 10, in <module> blind.Update() File "/home/dan/.local/lib/python3.8/site-packages/motionblinds/motion_blinds.py", line 855, in Update raise socket.timeout socket.timeout

starkillerOG commented 3 years ago

@haberda, that is with interface='192.168.1.IP_HOMEASSISTANT'?

Could you then try to run the same python script from a device/computer that is on the same part of your network as the motion gateway? (same acces point/router and in the same vlan)

aboogerd commented 3 years ago

I moved my motion hub to the same vlan as HA. This because I don't had the time for any problem solving.

The problem I had: Blinds showing in HA but unavailable for control.

The motion API documentation describes the following communication:

Motion hub receive UDP multicast 238.0.0.18:32100
Motion hub sending UDP multicast 238.0.0.18:32101

Think opening these ports between HA and the VLAN of the Motion Hub should work

starkillerOG commented 3 years ago

@aboogerd, thanks for your clarification. Sounds very logical, indeed UDP multicast 238.0.0.18:32100 and 238.0.0.18:32101 are used in the communication between the gateway and homeassistant. I will see if I can add something to the docs and maybe the error messages.

haberda commented 3 years ago

@starkillerOG the script was run on my supervised Debian install.

Just to make sure everything is right, I installed python3->used pip3 to install motionblinds->ran 'python3 test.py'

In terms of the script itself: IP_HOMEASSISTANT is the ip address of my supervised home-assistant box. I ran this twice because I have a NIC on both vlans, so I tried both vlans from that box. I can install the script on my laptop and connect to the other vlan and try that too.

The IP_GATEWAY is the motion gateway right? Not the generic network gateway (e.g. dhcp server), right? I used the motion gateway here.

Key, same key I use in home assistant which works in 2020.12.x

I'll try this on my laptop while on the same vlan as the motion gateway in a little bit and see if it works.

If it doesn't, I will setup some firewall rules to always allow the UDP multicast in your comment above. I run an OpenWRT router with Ubiquity access points, so my problem could be either at the ubiquity access point level, or the OpenWRT level. In both cases, everything in the UI have multicast enabled so aside from just making a firewall rule to allow the specific multicast pathways you stated above I'm not sure what else to try.

haberda commented 3 years ago

Ok, so I made some progress. When I turn off the Ubiquity access point, and have my OpenWRT router act as my wifi access point the transmission appears to go through when on the same vlan, at least in terms of the python script. Here is my output:

<MotionBlind mac: 807d3aee3f500001, type: RollerBlind, status: Closing, position: 0 %, angle: 0.0, limit: Limits, battery: 8.64 %, 10.59 V, RSSI: -51 dBm> <MotionBlind mac: 807d3aee3f500002, type: RollerBlind, status: Closing, position: 0 %, angle: 0.0, limit: Limits, battery: 70.0 %, 11.94 V, RSSI: -70 dBm> <MotionBlind mac: 807d3aee3f500003, type: RollerBlind, status: Closing, position: 0 %, angle: 0.0, limit: Limits, battery: 67.27 %, 11.88 V, RSSI: -62 dBm> <MotionBlind mac: 807d3aee3f500004, type: RollerBlind, status: Closing, position: 10 %, angle: 180.0, limit: Limits, battery: 73.64 %, 12.02 V, RSSI: -61 dBm> <MotionBlind mac: 807d3aee3f500005, type: RollerBlind, status: Closing, position: 0 %, angle: 0.0, limit: Limits, battery: 70.0 %, 11.94 V, RSSI: -61 dBm> <MotionBlind mac: 807d3aee3f500006, type: RollerBlind, status: Closing, position: 0 %, angle: 0.0, limit: Limits, battery: 70.45 %, 11.95 V, RSSI: -60 dBm> <MotionBlind mac: 807d3aee3f500007, type: RollerBlind, status: Closing, position: 0 %, angle: 0.0, limit: Limits, battery: 75.45 %, 12.06 V, RSSI: -56 dBm> This only works when on the same vlan, whereas with 2012.12.x it worked across vlans with my same network infrastructure. So it appears I have 2 problems here:

Communication across vlans
Something with my ubiquity access point (with every setting I can find for multicast enabled)

Just curious, is it possible for the code to fail over to the other method if the new discovery method fails? It worked brilliantly before using 2020.12.x across vlans using my very new (as of late 2019) ubiquity access point.

I will keep trying to get the ubiquity access point to work, but for now my OpenWRT instance will have to act as access point for my IOT devices, or I have to keep running 2020.12.2.

haberda commented 3 years ago

Another addendum. On my supervised install with multiple NICs, the python script works when pointed to the appropriate vlan. But home assistant does not. I assume it's because home assistant is using my primary vlan.

starkillerOG commented 3 years ago

@haberda did you manage to get it working by placing the motion gateway on the same vlan as HomeAssistant?

Regarding the old way of 2020.12.x, it is not the discovery method that fails, but the update of the data. Updates now take the data directly form the blinds instead of the cache of the gateway (old 2020.12.x method). In principle if I were to just not set the devices to unavailable, they would still work but there are some issues with that method:

the update interval is now set at 10 minutes, so states would only be updated every 10 minutes with an update getting the info of the cache of the gateway, this means an update always lacks behind 1 update for the real data comming from the blind. Therefore your data would always lack behind by 20 minutes. (Increasing the update interval is not advised because it now actually communicates with the blinds, so that would start draining the battery of the blinds occording to the manufacturer).
- you will not get instante state updates when a blind moves.

But the real reason why I am hesitant to make it possible to run the integration withouth proper multicast communication is that I will probably get a lot of issues/complaints from users about things not working properly/states that are not correct or lacking behind which basically are caused by the multicast communication beeing blocked.

Therfore I would much rather advise people to just place the motion gateway on the same vlan as the HomeAssistant device. Of course if someone figures out how to allow the multicast messages across vlan's, that would also be great and I would be happy to include those instructions in the documentation.

haberda commented 3 years ago

@starkillerOG yes, I was able to get it working on the same vlan. I moved the motion gateway to the primary vlan. I'm not sure why my ubiquity AP was causing an issue before, but it's working fine now. I was not able to get the multicast to route between vlans no matter what I tried.

Thanks for the additional info!

starkillerOG commented 3 years ago

@haberda glad to hear it is working now! Could you close this issue, since it has been resolved?

home-assistant / core