Crash when pressing button associated with a scene or device

kevinkahn / softconsole

Soft Console for ISY and/or Home Assistant Home Automation based on Raspberry Pi

Apache License 2.0

22 stars 6 forks source link

Crash when pressing button associated with a scene or device #2

Closed bpaauwe closed 8 years ago

bpaauwe commented 8 years ago

I don't get this with every button press, sometimes it's the first, sometimes the second, and always by the third press. In this case, the button is associated with a scene. It looks like it's not happy with the message my ISY is sending back.

My ISY has the 5.0.1 firmware installed.

The scene has a dimmer switch and keypad button in it and it looks like it picked the keypad button as the device to represent the scene.

1465530937.86 Skipping item in stream: 239 : _0 : None : None : 120 1465530949.9 New watchlist: ['Status', u'B 79 72 1', u'5 78 97 1', u'1 3E A 1', u'1 3E A 4', u'11 26 B0 1'] 1465530949.9 Status update in stream: 240 : Status : 5 78 97 1 : None : {'action-uom': '100', 'action-prec': '0'} Qsize at daemon 1 Q size at main loop 1 1465530949.91 ISY reports change: Key: ('Node', '5 78 97 1', {'action-uom': '100', 'action-prec': '0'}) 1465530949.91 Other update in stream: 241 : Status : 14 9F EB 1 : None Traceback (most recent call last): : File "console.py", line 163, in {'acti nextscreen = config.CurrentScreen.HandleScreen(prevscreen <> config.CurrentScreen) on-uom': '100 File "/home/pi/softconsole/screens/keyscreen.py", line 102, in HandleScreen ', 'action-prec': '0'} ActState = int(choice[1][1]) <> 0 TypeError: int() argument must be a string or a number, not 'dict' 1465530949.91 Other update in stream: 242 : Status : 17 D E1 1 : None : {'action-uom': '100', 'action-prec': '0'} 1465530949.92 Other update in stream: 243 : Trigger : None : [ 5 78 97 1] ST 0 (uom=100 prec=0) : 3 Signal: 15 pid: 6743 1465530951.01 Console Exiting

kevinkahn commented 8 years ago

Hmm. I don't have the v5 firmware. The "Status" report on v4 always just has a single field value which is the %on of the device. It looks like your device on v5 is reporting that tuple action-uon:100 action-prec:0 which gets parsed into a dict and causes the error. I'm not sure what the formats are for v5 messages - a quick look (all I had time for this morning) didn't show me the right documentation on the UDI website. The Node Server SDK document might have it but I couldn't find it. Are the devices that are involved Insteon devices? I also don't have any Zwave devices and previously found at least one difference with those that I fixed. I'll search around more this afternoon/evening. By the way - the reason you are probably seeing some timing differences is that the message in question is a status update that comes from the ISY in the subscription stream. Those can get delayed a little bit at times behind that actual button push. Thanks for finding and turning on debug! Would have had no clue without that. I'll get back to you when I find more info.

Sorry for the issue,

Kevin

On Thu, Jun 9, 2016 at 9:10 PM Bob Paauwe notifications@github.com wrote:

I don't get this with every button press, sometimes it's the first, sometimes the second, and always by the third press. In this case, the button is associated with a scene. It looks like it's not happy with the message my ISY is sending back.

My ISY has the 5.0.1 firmware installed.

The scene has a dimmer switch and keypad button in it and it looks like it picked the keypad button as the device to represent the scene.

1465530937.86 Skipping item in stream: 239 : _0 : None : None : 120 1465530949.9 New watchlist: ['Status', u'B 79 72 1', u'5 78 97 1', u'1 3E A 1', u'1 3E A 4', u'11 26 B0 1'] 1465530949.9 Status update in stream: 240 : Status : 5 78 97 1 : None : {'action-uom': '100', 'action-prec': '0'} Qsize at daemon 1 Q size at main loop 1 1465530949.91 ISY reports change: Key: ('Node', '5 78 97 1', {'action-uom': '100', 'action-prec': '0'}) 1465530949.91 Other update in stream: 241 : Status : 14 9F EB 1 : None Traceback (most recent call last): : File "console.py", line 163, in {'acti nextscreen = config.CurrentScreen.HandleScreen(prevscreen <> config.CurrentScreen) on-uom': '100 File "/home/pi/softconsole/screens/keyscreen.py", line 102, in HandleScreen ', 'action-prec': '0'} ActState = int(choice[1][1]) <> 0 TypeError: int() argument must be a string or a number, not 'dict' 1465530949.91 Other update in stream: 242 : Status : 17 D E1 1 : None : {'action-uom': '100', 'action-prec': '0'} 1465530949.92 Other update in stream: 243 : Trigger : None : [ 5 78 97 1] ST 0 (uom=100 prec=0) : 3 Signal: 15 pid: 6743 1465530951.01 Console Exiting

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/kevinkahn/softconsole/issues/2, or mute the thread https://github.com/notifications/unsubscribe/APSFijdU8Izb-hPZF4t_Q2FmF2ZeTBVIks5qKOOagaJpZM4Iym1l .

Kevin Kahn 503-701-8781 kevin@coral-zone.com

bpaauwe commented 8 years ago

I've only added Insteon devices (and scenes with only Insteon devices) in the config.txt file for SoftConsole. I do have a couple of z-wave devices but they shouldn't be involved.

I can dump the full XML that the ISY is sending, but it may take a few days.

Are you looking only at that messages that have control=ST? The parsing code that I have for those messages only ever looks at the actionInfo for a couple of messages from the thermostat. For everything else I just grab the value. It's been a while since I've looked the parsing the subscription stream.

kevinkahn commented 8 years ago

Yes - think only Status item are looked at - been a while since I've been in that part of the code.

On Fri, Jun 10, 2016 at 8:36 AM Bob Paauwe notifications@github.com wrote:

I've only added Insteon devices (and scenes with only Insteon devices) in the config.txt file for SoftConsole. I do have a couple of z-wave devices but they shouldn't be involved.

I can dump the full XML that the ISY is sending, but it may take a few days.

Are you looking only at that messages that have control=ST? The parsing code that I have for those messages only ever looks at the actionInfo for a couple of messages from the thermostat. For everything else I just grab the value. It's been a while since I've looked the parsing the subscription stream.

— You are receiving this because you commented.

Reply to this email directly, view it on GitHub https://github.com/kevinkahn/softconsole/issues/2#issuecomment-225216694, or mute the thread https://github.com/notifications/unsubscribe/APSFihDsAcDvA0pd_LXf1G0Jd1Fg-c2gks5qKYRvgaJpZM4Iym1l .

Kevin Kahn 503-701-8781 kevin@coral-zone.com

kevinkahn commented 8 years ago

I pushed a version as currentbeta that adds a debug print of the raw stream as the library gets it. If you get a chance could you try running that, causing the bug, and send me the debug output? At least perhaps I can see what v5 is putting in the stream. There doesn't seem to be much documentation on this on the UDI website (or I'm not looking in the right place) but it looks like they have added the ability for a node to specify its unit of measure and precision so that new nodes can tell observers what their status values mean. I'd guess for dimmers that the 100 is saying that the unit is a percentage with no decimal points. But what I don't see in the existing debug is where the actual value is being stashed. I suspect that there is some stuff there I'm not printing with the existing debug statement because I wasn't expecting it.

Kevin

On Fri, Jun 10, 2016 at 8:50 AM Kevin Kahn kevin@coral-zone.com wrote:

Yes - think only Status item are looked at - been a while since I've been in that part of the code.

On Fri, Jun 10, 2016 at 8:36 AM Bob Paauwe notifications@github.com wrote:

I've only added Insteon devices (and scenes with only Insteon devices) in the config.txt file for SoftConsole. I do have a couple of z-wave devices but they shouldn't be involved.

I can dump the full XML that the ISY is sending, but it may take a few days.

Are you looking only at that messages that have control=ST? The parsing code that I have for those messages only ever looks at the actionInfo for a couple of messages from the thermostat. For everything else I just grab the value. It's been a while since I've looked the parsing the subscription stream.

— You are receiving this because you commented.

Reply to this email directly, view it on GitHub https://github.com/kevinkahn/softconsole/issues/2#issuecomment-225216694, or mute the thread https://github.com/notifications/unsubscribe/APSFihDsAcDvA0pd_LXf1G0Jd1Fg-c2gks5qKYRvgaJpZM4Iym1l .

Kevin Kahn 503-701-8781 kevin@coral-zone.com

Kevin Kahn 503-701-8781 kevin@coral-zone.com

bpaauwe commented 8 years ago

Here's the debug dump with your added message.

1465789278.81 Skipping item in stream: 240 : _5 : None : None : 1 1465789279.84 Skipping item in stream: 241 : TPW : 18 F3 B3 1 : None : {'action-uom': '102', 'action-prec': '0'} 1465789279.85 Skipping item in stream: 242 : _5 : None : None : 0 1465789279.85 Skipping item in stream: 243 : _1 : None : [ 18 F3 B3 1] TPW 479783 (uom=102 prec=0) : 3 1465789288.37 New watchlist: ['Status', u'B 79 72 1', u'5 78 97 1', u'1 3E A 1', u'1 3E A 4', u'11 26 B0 1'] 1465789288.37 Status update in stream: 244 : Status : 11 26 B0 1 : None : {'action-uom': '100', 'action-prec': '0'} 1465789288.37 Raw stream item: {'control': 'ST', 'node': '11 26 B0 1', 'eventInfo': None, 'Event-seqnum': '244', 'fmtAct': '80%', 'action': {'action-uom': '100', 'action-prec': '0'}, 'Event-sid': 'uuid:169'} Qsize at daemon 1 Traceback (most recent call last): File "console.py", line 172, in nextscreen = config.CurrentScreen.HandleScreen(prevscreen <> config.CurrentScreen) File "/home/pi/softconsole/screens/keyscreen.py", line 102, in HandleScreen ActState = int(choice[1][1]) <> 0 TypeError: int() argument must be a string or a number, not 'dict' 1465789288.38 Other update in stream: 245 : Status : 17 D 96 1 : None : {'action-uom': '100', 'action-prec': '0'} 1465789288.38 Raw stream item: {'control': 'ST', 'node': '17 D 96 1', 'eventInfo': None, 'Event-seqnum': '245', 'fmtAct': '100%', 'action': {'action-uom': '100', 'action-prec': '0'}, 'Event-sid': 'uuid:169'} 1465789288.38 Other update in stream: 246 : Trigger : None : [ 11 26 B0 1] ST 204 (uom=100 prec=0) : 3 1465789288.39 Raw stream item: {'control': '_1', 'node': None, 'eventInfo': '[ 11 26 B0 1] ST 204 (uom=100 prec=0)', 'Event-seqnum': '246', 'action': '3', 'Event-sid': 'uuid:169'} 1465789288.39 Other update in stream: 247 : Trigger : None : [ 17 D 96 1] ST 255 (uom=100 prec=0) : 3 1465789288.39 Raw stream item: {'control': '_1', 'node': None, 'eventInfo': '[ 17 D 96 1] ST 255 (uom=100 prec=0)', 'Event-seqnum': '247', 'action': '3', 'Event-sid': 'uuid:169'} Signal: 15

kevinkahn commented 8 years ago

Interesting but odd - they seem to not being reporting the actual status value for the device in the "status" item. They do report it, sort of, in text for with that 80% but the real value 204 doesn't seem to be there. I'll need to ask them about that since v4 does and it would seem sensible to actually provide the status in a status record. They do report it in the Trigger record but at the moment I'm ignoring those. I'll have to think about how to fix this one.

By the way, I got annoyed enough at myself for making debug hard to use that I have fixed that in the current beta. You can set a debug flag in the config file now and the Maintenance screen now has a subscreen to let you change the state of the flags dynamically.

bpaauwe commented 8 years ago

Here's the raw XML. It looks like the value is there (255) in both cases.

6/13/2016 6:22:02 AM xml= <Event seqnum="242" sid="uuid:171"><control>ST</control><action uom="100" prec="0">255<action><node>5 78 97 1</node><eventInfo></eventInfo><fmtAct>100%</fmtAct></Event> 6/13/2016 6:22:02 AM xml= <Event seqnum="243" sid="uuid:171"><control>ST</control><action uom="100" prec="0">255<action><node>14 9F EB 1</node><eventInfo></eventInfo><fmtAct>100%</fmtAct></Event>

kevinkahn commented 8 years ago

Hmm. In that case the bug must be in evilpete's ISY library since that is what I use to get the stream. Maybe he can look at this for us.

bpaauwe commented 8 years ago

I think I see the problem in the ISYEvent library. My python is really rusty, but in the function et2d(), it seems to be making the assumption that tags with attributes will never have values associated with them, probably because up until the 5.x firmware they didn't. It wouldn't be hard to change that assumption.

I'm not sure how to go about testing it though. Do you have an easy way to use a modified version of ISYlib or know how I can? Can I just clone the ISYlib git repository on my RPi and do a make / make install to install a new version of the library?

kevinkahn commented 8 years ago

Looks like you and I were working in parallel - I was just about to write you that the problem was in et2d in that he handles either tags or text but not both. :-) I can modify the library but I have to figure out how to actually return the value since right now he returns a dict where the value for an item is either the text or the attributes as a dict. I suppose that I could "invent" an attribute name and add the value to the dict entry but that seems odd. I'll see what I can come up with.

bpaauwe commented 8 years ago

My thought was to modify it to check if there's text, and if so just use that and only build the dict with the attributes if there's no text. That should work for now and verify that that's the problem. As you say, a correct solution will require more thought.

For my code that parses the ISY event stream, I ignore all the attributes except for the ones in the eventInfo since they provide quite a bit of information when present. That's worked for me for all ISY firmware releases to date.

kevinkahn commented 8 years ago

OK - I think I have patched the lib and figured out how to handle both v4 and v5 streams and pushed these to the currentbeta release on github. What I did was for the case of an element with attributes and a text, I add an item to the attributes dict which is the element name so what you should see is something like: 'action':{'action-uom':100, 'action-prec':0, action:255}. Then in my daemon if I see a dict there I pull up the value to send to the main process. I added some debug prints if you turn on the "Daemon" debug flag that should show this happening. By the way - this version has the easier debug flag on/off improvement. You can just add Daemon = true to the start of your config.txt file to get it turned on or alternately go to the maintenance screen then flags and turn it on/off there. Hope I got this all right since I can't test it at my end completely. If you can give it a try and let me know that would be great.

Kevin

bpaauwe commented 8 years ago

Ok, that looks like it will work. I'll try it when I get home tonight. It's hard to press that touchscreen remotely :)

Thanks!

bpaauwe commented 8 years ago

Kevin,

Your change worked!

I played around with it some more and thought about how the et2d function was working. I think the problem is that it's currently expecting a tag to have either attributes or text and it shouldn't. It already creates separate entries in the dictionary for each attribute using a key "tag_name-attribute_name" so why does it need to put the list of attributes in the tag_name key? I changed the et2d function to always put the text (or "") in the dictionary key tag_name and never append the attribute list. This works without having to change anything in watchdaemon. Here's my patch.

diff --git a/IsyEvent.py b/IsyEvent.py
index b0db741..c263dee 100644
--- a/IsyEvent.py
+++ b/IsyEvent.py
@@ -252,23 +252,24 @@ class ISYEvent(object):
                if et.attrib:
                        for k, v in list(et.items()):
                                d[et.tag + "-" + k] = v
-                       d[et.tag] = et.text
                if children:
                        for child in children:
                                if child.tag in d:
                                        if type(d[child.tag]) != list:
                                                t = d[child.tag]
                                                d[child.tag] = [t]
-                               if list(child) or child.attrib:
+                               if list(child):
                                        if child.tag in d:
                                                d[child.tag].append(self.et2d(child))
                                        else:
                                                d[child.tag] = self.et2d(child)
-                               else:
+                               if child.text:
                                        if child.tag in d:
                                                d[child.tag].append(child.text)
                                        else:
                                                d[child.tag] = child.text
+                               else:
+                                       d[child.tag] = ""
                return d

        @staticmethod

What do you think?

kevinkahn commented 8 years ago

Glad the fix worked.

Not sure the "best" way to handle all this. I actually don't like that he currently does the item-attrib thing. Mucking with names like that is generally harder to use later. It seems to me that ideally you would simply use the data structures to handle the relationships so for an element there would be a dict that contained any attributes using their simple name and the "value" of the item with "no" name. I.e., for the "action" element we've been dealing with you would get back something like {uom:100,prec:0,'':255}. I was about to say that in Python there is no empty name to use but surprise - there is. You actually can say x={'':255}

to the empty string would have probably been a better choice to use, though I won't change it now lest I break things again.

My reasoning for this approach of putting the attributes in a dict is that I think were I doing something else with the results of the event feed I would want the value and its attributes together so that I could deal with them as a unit. Of course, this is Peter's library so ultimately he can do what he thinks best (assuming he sees my mail and gets to it). For the moment I think I'll just leave what I did as is since I know now it works and I'm loathe to change anything that I can't easily test myself - even careful blind fixes are likely to go wrong.

Do let me know of any other problems that arise - I'll try to respond with fixes as quickly as I can should there be any issues. And, of course, suggestions for changes always accepted.

Kevin

On Mon, Jun 13, 2016 at 9:26 PM Bob Paauwe notifications@github.com wrote:

Kevin,

Your change worked!

I played around with it some more and thought about how the et2d function was working. I think the problem is that it's currently expecting a tag to have either attributes or text and it shouldn't. It already creates separate entries in the dictionary for each attribute using a key "tag_name-attribute_name" so why does it need to put the list of attributes in the tag_name key? I changed the et2d function to always put the text (or "") in the dictionary key tag_name and never append the attribute list. This works without having to change anything in watchdaemon. Here's my patch.

`diff --git a/IsyEvent.py b/IsyEvent.py index b0db741..c263dee 100644 --- a/IsyEvent.py +++ b/IsyEvent.py @@ -252,23 +252,24 @@ class ISYEvent(object): if et.attrib: for k, v in list(et.items()): d[et.tag + "-" + k] = v
d[et.tag] = et.text if children: for child in children: if child.tag in d: if type(d[child.tag]) != list: t = d[child.tag] d[child.tag] = [t]

if list(child) or child.attrib:

if list(child): if child.tag in d: d[child.tag].append(self.et2d(child)) else: d[child.tag] = self.et2d(child)

else:

if child.text: if child.tag in d: d[child.tag].append(child.text) else: d[child.tag] = child.text
else:
                           d[child.tag] = ""
 return d
@staticmethod`
What do you think?

— You are receiving this because you commented.

Reply to this email directly, view it on GitHub https://github.com/kevinkahn/softconsole/issues/2#issuecomment-225776889, or mute the thread https://github.com/notifications/unsubscribe/APSFilmfIFnThDR5A-JNTtJ0lHNJPxAVks5qLi2BgaJpZM4Iym1l .

Kevin Kahn 503-701-8781 kevin@coral-zone.com

bpaauwe commented 8 years ago

Not sure the "best" way to handle all this. I actually don't like that he currently does the item-attrib thing. Mucking with names like that is generally harder to use later. It seems to me that ideally you would simply use the data structures to handle the relationships so for an element there would be a dict that contained any attributes using their simple name and the "value" of the item with "no" name. I.e., for the "action" element we've been dealing with you would get back something like {uom:100,prec:0,'':255}. I was about to say that in Python there is no empty name to use but surprise - there is. You actually can say x={'':255}

to the empty string would have probably been a better choice to use, though I won't change it now lest I break things again.

I think I agree, but since he's already written the library to create the item-attribute naming I thought it best to work with that. My goal was to find a way to fix the library so that no changes are needed in existing code (like yours) that make use of the library.

To me it looks like the library is currently very inconsistent in how it handles parsing the XML into the dictionary:

<tag>value</tag> is converted to d[tag] = value <tag attrib1=x attrib2=y></tag> is converted to d[tag] = { attrib1:x, attrib2:y}, d[tag-attrib1] = x, d[tag-attrib2] = y <tag attrb=x>value</tag> is converted to d[tag] = { attrib:x}, d[tag-attrib] = x and ignores the value <tag>value1</tag><tag>value2> is converted to d[tag] = {value1, value2}

At least that what I think it's doing. I find the logic in that function a bit hard to follow but that may be because of my lack of Python experience.

So my reasoning is that d[tag] should be set to the value or list of values. If the value is empty, then that's what it should be set to. Since the tag-attribute naming convention exist, keep it in place for all attributes. This should minimize the chance of breaking existing code and still support the changes happening with ISY v5+ firmware.

My reasoning for this approach of putting the attributes in a dict is that I think were I doing something else with the results of the event feed I would want the value and its attributes together so that I could deal with them as a unit. Of course, this is Peter's library so ultimately he can do what he thinks best (assuming he sees my mail and gets to it). For the moment I think I'll just leave what I did as is since I know now it works and I'm loathe to change anything that I can't easily test myself - even careful blind fixes are likely to go wrong.

Yeah, I understand about the blind changes. My concern with your existing fix is that special cases the action tag. What happens if UDI decides to add some attributes to the node or control tags next?

I think I'll go ahead and send Peter a pull request with the change I proposed after I do a bit more testing.

And I really appreciate the effort you've put into solving this. Your softconsole program is really cool, I had to go buy another RPi so that I could try it out (already had the display).

kevinkahn commented 8 years ago

OK - since I have had to add that library file to my git for now anyway I'll just leave things as is until Peter decides what he wants to do. I actually have been tempted to abandon that library anyway and monitor the stream directly for other reasons but haven't had the time to look at actually doing that. I get your compatibility issue - hadn't thought about it from that perspective since I only make use of that one capability and adjusting my code was no big issue. As an aside, there are 2 libraries that wrap the ISY for Python and neither is what I would have created from the perspective of an object oriented design methodology. I actually tried using the other library to read the basic ISY data structures and gave up on it because it did a really odd job of creating a Python structure that mirrored them. That's why you may notice that I do my own construction of the ISY mirror data structure in my program. It builds a full OO graph structure that mirrors the ISY one.

I've found the program addictive - or I should say my wife has. I started it because I had one Pi around I was using to interface an Echo to the ISY and wanted to do some other programming for it. Now I have 2 Pi 2's a Pi 0 and a Pi 3 and will probably get one more Pi0 for another wall unit. Ugh! :-)