cover.isy994 error: Unable to close the cover

[hoopty]

Home Assistant release (hass --version):
0.33.4 and also tried 0.34.0.dev0 (just cloned @dev from GitHub)

Python release (python3 --version):
Python 3.5.2

Component/platform:
isy994
cover.isy994

Description of problem:
Get the below error logged when closing a (program based) cover.isy994 entity. FWIW, it also causes the gate to re-open, even though it does close:
homeassistant.components.cover.isy994: Unable to close the cover

Expected:
No error logged, and no attempt to re-open the cover. When the program is triggered, I expected HA to be a happy camper once it executes the runElse of the program actions. If there is required behavior of the status, etc. then it would help to know more info about that.

Problem-relevant configuration.yaml entries and steps to reproduce:

isy994:
  host: http://isy.local:80
  username: !secret isy_username
  password: !secret isy_password
  sensor_string: 'Sensor'
  hidden_string: '~'

logger:
  default: info
  logs:
    homeassistant.components.isy994: debug
    homeassistant.components.cover.isy994: debug

Here's the ISY program setup:

Traceback (if applicable):

Additional info:
The '~Gate Closed Sensor' is a binary sensor and 'Gate Opener' is a switch that that triggers the gate to open AND close (it is a toggle, do no have discrete relays). The state for Gate Opener reverts back to Off shortly after it is turned On since the z-wave device is set to be a momentary trigger (http://www.fortrezz.com/shop/mimo-lite). Also note that it normally take ~30 seconds for the gate to close and the '~Gate Closed Sensor' state to change.

Everything works as expected when I interact directly with that ISY, I assume it is related to the interaction on HA and the ISY program(s).

Log activity:

16-12-01 11:38:34 homeassistant.core: Bus:Handling <Event call_service[L]: service_data=entity_id=cover.gate, domain=cover, service=close_cover, service_call_id
16-12-01 11:38:34 homeassistant.components.isy994: ISY Request: http://isy.local:80/rest/programs/0006/runElse
16-12-01 11:38:34 homeassistant.components.isy994: ISY Update Received:
<?xml version="1.0"?><Event seqnum="40" sid="uuid:150"><control>_0</control><action>120</action><node></node><eventInfo></eventInfo></Event>
16-12-01 11:38:34 homeassistant.components.isy994: ISY HEARTBEAT: 2016-12-01T11:38:34.652917
16-12-01 11:38:34 homeassistant.components.isy994: ISY Response Recieved
16-12-01 11:38:34 homeassistant.components.isy994: ISY ran else in program: 0006
16-12-01 11:38:34 homeassistant.components.isy994: ISY Update Received:
<?xml version="1.0"?><Event seqnum="41" sid="uuid:150"><control>_1</control><action>0</action><node></node><eventInfo><id>6</id><on /><nr /><r>161201 11:38:39</
16-12-01 11:38:34 homeassistant.components.isy994: ISY Updated Program: 0006
16-12-01 11:38:34 homeassistant.components.isy994: ISY Update Received:
<?xml version="1.0"?><Event seqnum="42" sid="uuid:150"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
16-12-01 11:38:34 homeassistant.components.isy994: ISY Update Received:
<?xml version="1.0"?><Event seqnum="43" sid="uuid:150"><control>DON</control><action uom="78" prec="0">100</action><node>ZW004_1</node><eventInfo></eventInfo></
16-12-01 11:38:34 homeassistant.components.isy994: ISY Update Received:
<?xml version="1.0"?><Event seqnum="44" sid="uuid:150"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
16-12-01 11:38:34 homeassistant.components.isy994: ISY Update Received:
<?xml version="1.0"?><Event seqnum="45" sid="uuid:150"><control>_1</control><action>0</action><node></node><eventInfo><id>6</id><on /><nr /><r>161201 11:38:39</
16-12-01 11:38:34 homeassistant.components.isy994: ISY Updated Program: 0006
16-12-01 11:38:34 homeassistant.components.isy994: ISY Update Received:
<?xml version="1.0"?><Event seqnum="46" sid="uuid:150"><control>_1</control><action>3</action><node></node><eventInfo>[     ZW004_1]      DON 100 (uom=78 prec=0
16-12-01 11:38:34 homeassistant.components.isy994: ISY Update Received:
<?xml version="1.0"?><Event seqnum="47" sid="uuid:150"><control>DOF</control><action uom="78" prec="0">0</action><node>ZW004_104</node><eventInfo></eventInfo></
16-12-01 11:38:35 homeassistant.components.isy994: ISY Request: http://isy.local:80/rest/programs/0006?subfolders=true
16-12-01 11:38:35 homeassistant.components.isy994: ISY Response Recieved
16-12-01 11:38:35 homeassistant.components.isy994: ISY Loaded/Updated Programs
16-12-01 11:38:35 homeassistant.components.cover.isy994: Unable to close the cover

@Teagan42, I may just be misunderstanding how the ISY is to be setup for covers to work but I think it is a good use case to have a binary sensor that reports cover status and a (toggle) switch to open and close the cover. Thanks!

[Teagan42]

@hoopty
If you want a binary sensor to report the status in your situation, use that device as the condition in the cover program's status.

As for your issue - can you clarify exactly what is happening? It sounds like you have a momentary relay that will reset after about 30 seconds (Normally Off). You turn the relay on to open a gate, about 30 so seconds, the relay turns itself off, correct? When you trigger this cover program in HA, does the relay respond or does it respond but quickly turn off? What exactly is happening?

Also, I just looked at the PyISY library - the library HA uses to talk to ISY - and it looks like there is a small bug in the "Program: Run Else" method where if it fails, it returns False (expected) but if it succeeds, it returns NOTHING. In Python if False: is also equivalent to if None: - so it thinks it didn't actually work, even if it did work.

        """ Runs the ELSE clause of the object. """
        response = self.parent.parent.conn.programRunElse(self._id)

        if response is None:
            self.parent.parent.log.warning("ISY couldn't run else in program: "
                                           + self._id)
            return False
        else:
            self.parent.parent.log.info('ISY ran else in program: ' + self._id)
            self.update(_change2update_interval)

Obviously the "else" is running successfully because I see ISY ran else in program: 0006 in your log (corresponding to the first line in the else). But because it's not returning True - HA logs an error Unable to close the cover.

So, if your concern is just that there is an error message in the log - you can ignore it, and I will submit an update to PyISY to fix this bug. If your issue is that the relay is not responding correctly at all, then please provide more detail on what is happening physically on the device.

Thank you so much for the logs, those helped greatly in looking into this issue so far!

[hoopty]

Thanks @Teagan42 for the response, I'll try to respond to each of your paragraphs below:

1. Got it, I think I'm doing that right. I have the If condition for the status program set to:

Status `~Gate Closed Sensor` On

and that is indeed ZW004_104, which is the binary sensor that tells us when the gate is CLOSED.

2. The real issue is that once the gate is closed after executing cover.close, HA is telling it to open again! The relay is triggered properly to open and to close the gate but something in HA is telling the ISY to turn ZW004_1 ON again.

3. Good to know on the erroneous logging, I was jumping to conclusions and assuming that seeing that error was causing HA to run the Else program again (or otherwise causing the gate to be triggered again).

4. No problem on the logs, it helped me learn what is going on as well. One nit-pick complaint is that the XML responses from the ISY are on a separate HA log line (not concatenated) than the ISY Update Received: entries and as such is can't just grep for homeassistant.components.isy994 because if when I do it excludes all the valuable XML.

[Teagan42]

In regards to #4 - we don't have any real control over that. Python's logging puts each on it's own line.

In regards to #3 - it definitely should not be doing that. There's nothing in HA, that I'm aware of, that tries to send a service call again if failed.

I'll keep digging - assuming your log is complete (it does look cut off some) - something about ISY is doing this.

1. "ran else program 0006" - says we're sending off the command to execute the else. Expected
2. ISY says "ZW device is on" <?xml version="1.0"?><Event seqnum="43" sid="uuid:150"><control>DON</control><action uom="78" prec="0">100</action><node>ZW004_1</node><eventInfo></eventInfo>
3. Almost immediately after it says "ZW device is off" <?xml version="1.0"?><Event seqnum="47" sid="uuid:150"><control>DOF</control><action uom="78" prec="0">0</action><node>ZW004_104</node><eventInfo></eventInfo><

There is no extra command (that I'm seeing) between the DON and the DOF updates that ISY is reporting.

If you go into the ISY control panel and go to Programs and right click on the Gate -> Actions and click "Run Else" - does it behave as expected?

Do you know if this worked before the September rearchitecture of the ISY component in HA?

I'll be back online in a bit - this is very odd.

[Teagan42]

Use awk for multiline regex

[hoopty]

• No worries on the logging (and thx for awk idea) - I came up with a regex that works, I was just being lazy ;)
• I'm recreating the issue & getting a more complete logs right now, will paste shortly
• Yes, Run Else from the ISY admin panel works fine (everything does) but will confirm
• I didn't try the isy994 cover before the Sept rearchitecture, so no more info there.

[hoopty]

tldr; Hold of before digging any further!

OK, I'm now starting to better understand how the programs work on the ISY controller (the ISY wiki leaves much to be desired) and I think my behavior is a result of how I have my programs setup on the ISY and not a problem with HA. Let me kick this around some more before you dig in any further. If I do figure this out, I will likely have HA doc suggestions.

[Teagan42]

Sounds good, thanks

…

On Thu, Dec 1, 2016 at 11:15 PM, Bryce Edwards ***@***.***> wrote: tldr; Hold of before digging any further! OK, I'm now starting to better understand how the programs work on the ISY controller (the ISY wiki leaves much to be desired) and I think my behavior is a result of how I have my programs setup on the ISY and not a problem with HA. Let me kick this around some more before you dig in any further. If I do figure this out, I will likely have HA doc suggestions. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#4662 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AC2fZfJGU3qQGyW70AbtYq4UTRfengr9ks5rD7dygaJpZM4LBvcO> .

[hoopty]

Yep, it was how I had things setup - closing this issue.

The 'actions' program needed to be disabled, as to not have it auto execute on status changes. The 'status' program needs to stay enable so that it's state changes when the sensor device does. I also had two other programs (one to close the gate and one to open it) that I needed to create since I needed the 'If' condition evaluated (I check that the gate is not already opened/closed before triggering the toggle to open/close the cover) and those programs must also stay disabled.