HA uses pymochad asynchrone

[gwijsman]

HA Bug report 2017.pdf

Bug report 2017-12-4 Mochad and Home Assistant I have a situation with a running mochad installation on a server with a local ip on port 1099 (as defaults suggest) I am migrating from OpenHab to Home Assistant (and before that openRemote) because I am a fan of MQTT and python. OpenHab and mochad work fine so Home Assistant should be able to do the job too. I have multiple iot devices I like to integrate but first I want to control the lights. I have 5 very old Marmitec (x10) devices and 3 less old Marmitek devices. Marmitek does not sell these x10 devices any more but I have them installed in my walls. My super user (My Wife) will not approve my new solution if the lights wont turn on or off. So here my motivation to solve this issue with you. I found out that with the HA is using a asynchronous way of starting up devices. I added some nasty debug logging to the sources to find out what goes wrong.

2017-12-04 20:54:59 DEBUG (Thread-5) [pymochad.device] get status for c12
2017-12-04 20:54:59 DEBUG (Thread-2) [pymochad.device] get status for c1
2017-12-04 20:54:59 DEBUG (Thread-8) [pymochad.device] get status for c2
2017-12-04 20:54:59 DEBUG (Thread-5) [pymochad.controller] Send command from controller: getstatus c12
2017-12-04 20:54:59 DEBUG (Thread-2) [pymochad.controller] Send command from controller: getstatus c1
2017-12-04 20:54:59 DEBUG (Thread-8) [pymochad.controller] Send command from controller: getstatus c2
2017-12-04 20:54:59 DEBUG (Thread-5) [pymochad.controller] Start read data from controller
2017-12-04 20:54:59 DEBUG (Thread-2) [pymochad.controller] Start read data from controller
2017-12-04 20:54:59 DEBUG (Thread-2) [pymochad.controller] data read: off
on
on
2017-12-04 20:54:59 DEBUG (Thread-8) [pymochad.controller] Start read data from controller
2017-12-04 20:54:59 DEBUG (Thread-2) [homeassistant.components.light.mochad] Got device status: off
on
on for c1

just a snapshot of the logging but you can see what goes wrong. Status for lights c12, c1 and c2 are queried. So the commands are sent off to pymochad. And stuff is read. But thread-2 (light c1) got all results off, on and on. So I tried some locking to make stuff atomic.

def _get_device_status(self):
"""Get the status of the light from mochad."""
from threading import Lock
lock = Lock()
lock.acquire()
_LOGGER.debug("Start getting light device status for %s", self._address)
status = self.device.get_status().rstrip()
_LOGGER.debug("Got device status: %s for %s", status, self._address)
lock.release()
return status == 'on'

So I got a logging like this:

2017-12-04 21:00:43 DEBUG (Thread-7) [homeassistant.components.switch.mochad] Start getting switch device status for c2
2017-12-04 21:00:43 DEBUG (Thread-7) [pymochad.device] get status for c2
2017-12-04 21:00:43 DEBUG (Thread-2) [homeassistant.components.switch.mochad] Start getting switch device status for c12
2017-12-04 21:00:43 DEBUG (Thread-5) [homeassistant.components.light.mochad] Start getting light device status for c1
2017-12-04 21:00:43 DEBUG (Thread-7) [pymochad.controller] Send command from controller: getstatus c2

So this is definitely not the solution. My idea towards a solution is that pymochad (the external pipy module) should not accept new commands (requests) from HA before answering a former request. Maybe someone can shine some lights on this? What is the best way to approach?

[mtreinish]

I'm not exactly sure how pymochad would solve this problem, the way home-assistant is leveraging pymochad it instantiates a controller object for the global mochad component. (the master one, not the individual devices) and that where socket connection object lives. This is shared between all the individual devices. What the bug here looks like is that we want to serialize each pair of ctrl.send_cmd() and ctrl.read_data() calls so that in the case of multiple threads we don't have a read or a write to the socket in the middle of another's communication on the socket. Ideally I think adding a sempahore to the global mochad component and then having it acquire before send_cmd calls and release after read_data() calls would work would be the best way. I guess in theory we could add that semaphore object to the base pymochad.controller class, but the access patterns from home-assistant aren't something pymochad can know about, which is why I feel keeping the semaphore in home assistant makes more sense. What do you think? I can try to hack together a home-assistant patch in the next few days to give this a try (I've got some travel the next couple of days)

[mtreinish]

Also, as an aside, if I remember how I wrote the home-assistant components the getstatus() is just used to get the initial state, as a guess because most x10 devices I've dealt with are 1 way, so the call just returns the last state the mochad daemon remembers sending, not the actual state of the device. It's to just guess a better state on starting home-assistant. If it is reading the wrong state at init() because of multiple devices racing with each other (which from home-assistant perspective really isn't any different then mochad getting out of sync with the actual state of a 1-way device) it should correct itself after flipping the switch once. In other words getstatus() reads the wrong status and sets your 'on' switch as 'off'. But, when you turn the switch off it just sends the 'off' command to mochad which doesn't do anything except update the home-assistant device state. From then on I would expect the state in homeassistant to match the actual device. (at least until the next home-assistant restart)

While this is a pretty bad solution I'm just wondering if this is not the case for you? Either way I think we should try to be better about the serialization of requests over the socket, I'm just curious.

[mtreinish]

The above commit was a first stab at serializing the request pairs for everything mochad in home-assistant. However, I think it may not work, or at the very least is probably not doing things in a home-assistant way. But since I don't have access to an X10 environment anymore testing this will be interesting...

[mtreinish]

Ok, can you test the latest commit from my branch above. The first one should work more or less the same way, but I feel the second is closer to the state it would merge in. If that works for you, I'll open a PR against home-assistant with it

[gwijsman]

Hi Matthew thanks for you very quick response. I have to spend time after work in such a way i do not neglect my wife, so i have not the opportunity to be as responsive ;-) I will add your patch to my dev installation and test it for you.

About the getstatus guess, you're right, it is indeed a guess but quite a good guess so if serializing does the job lets go for that!

I will at it to the switch device too, that is exactly the same issue.

After testing I come back to you!

[mtreinish]

The locking landed in home assistant. I'm going to close this issue now, if you still have issues feel free to reopen this

[gwijsman]

I did additional testing

All is fine!

Thanks!

Gert

Van: Matthew Treinish [mailto:notifications@github.com] Verzonden: vrijdag 8 december 2017 18:28 Aan: mtreinish/pymochad pymochad@noreply.github.com CC: Gert Wijsman gert@wijsman.net; Author author@noreply.github.com Onderwerp: Re: [mtreinish/pymochad] HA uses pymochad asynchrone (#4)

The locking landed in home assistant. I'm going to close this issue now, if you still have issues feel free to reopen this

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/mtreinish/pymochad/issues/4#issuecomment-350321760 , or mute the thread https://github.com/notifications/unsubscribe-auth/AFkpK9FTEGUfLno9dJBYbUYScUsy1kPJks5s-XGNgaJpZM4Q1P0P . https://github.com/notifications/beacon/AFkpK3TKVNm4lRVJQ2ICmSeKwtiIaRsUks5s-XGNgaJpZM4Q1P0P.gif