
johnnyt
Members-
Posts
1253 -
Joined
-
Last visited
Everything posted by johnnyt
-
The one related to the most recent set of posts is only about a week or two old but it is using the older type (design anyway) single band PLM. The first one - at the start of this thread - was maybe a month or so old at that time and had a dual band PLM.
-
I don't have anything connected to the inputs other than 5&6 to gnd and I don't have the kind of busy ISY situation I used to see when I had to query 10 IO Lincs, pre-EZIO8SA. Incidentally, in case anyone is thinking "just stop querying and your problems will go away", the reason I do the querying is because whenever I've not done it in the past, I would sometimes find things that weren't working as they should. The 3AM "query all" would also end up reporting something wrong just about everyday. While one might be tempted to say that at 3AM the insteon network and ISY are busy so it's just that query problem misreporting things, the reality is there aren't that many problems at 3 AM the times where I'm querying throughout the day. Also, while nothing is such that an HA failure will cause damage to my HVAC system, I kind of want my HVAC controls to be reliable and "self healing" when something doesn't work for comms or other reasons, given that insteon does not promise the reliability of a hard wired solution. ISY for its part has been great for reliability and for the self healing aspect when the querying works but the latter does need to work properly for the self healing to work properly. Thinking something is OFF when it's ON causes the system to actually be "self breaking"... For testing purposes I will try disabling all querying for a few days to see what happens, then move to querying only a few times in a day. I'll combine this with some manual "query insteon engine" or scene tests at different times to see if I can uncover (or rule out?) comms issues as the probable cause of these chronic intermittent problems. In the meantime, any other insights and suggestions would be appreciated.
-
ELA, Thanks for trying to sift through my troubles and for the suggestion. I just ran about 4 query insteon engine commands against node 1 of the EZIO8SA. On the last one I first initiated my query testing "suite" with a 10 second delay before it queries the EZIO8SA. The thinking was that I would create a collision. The results were all similar and I was surprised to find no trace of the device query from my program within the query engine trace. I'm guessing the regular query command was trumped by the query insteon engine command. FWIW, I've attached the result of the last one here. I'll try again at other times of the day and look for other ways to hammer the insteon network when I do it. I presume there's no way to call for a "query insteon engine" from within a program. Otherwise I would add that into the mix. Would a scene test work? I would mention that the only things on the circuit are 3 IO Lincs and the EZIO8SA on a 14 AWG power bar that doesn't have any built in filtering. In the past I had an HRV, chest freezer and 24VAC power supply that were found to cause problems despite being on a 15A ACT filter but they were moved to another circuit. I'm sure I must be missing something so I'd like to tell you what I see when I look at the event viewer entries hoping you can help. I see that ISY sends out a query for the relays, gets a response 4 secs later, considers that too long so waits 5 secs and sends another query for relays. Rinse. Repeat. Until it gets a response quickly enough and then it queries the input. In this case, the response comes twice - perhaps a remnant from a previous query because of comm problems that don't show up in the max hops / remain hops - and ISY confuses it (or the variable that got updated while this is happening) as being a change in status for 4 of the 8 relays with relays 2 & 4 the wrong status. Were relays 5 & 6 ON all along or is that also a reverse status? I also noticed that an output status response came twice too (that one with an indication of a comms issue) but it was handled okay. I see this flow as problematic but figure I must be misinterpreting what's happening. Thanks again for your help.
-
Thanks for clarifying the querying. Still, why three queries of the relays and such a long wait to query the input? And why does the following summary update of the relays only occur after the input is queried and over 20 secs after the first query? Sun 03/09/2014 07:33:37 AM : [ 23 8D 7C 2] ST 0 Sun 03/09/2014 07:33:38 AM : [ 23 8D 7C 4] ST 0 Sun 03/09/2014 07:33:38 AM : [ 23 8D 7C 5] ST 255 Sun 03/09/2014 07:33:38 AM : [ 23 8D 7C 6] ST 255 I've attached the log from 1PM 03/08 to 3:35PM 03/09 and the event viewer L3 log from 9PM 03/08 to ~8AM 03/09. Also, the attached screenshot shows how often a problem is caught by my automated testing. The arrow shows the device I chose to track for my post. Logs20140308-20140309.zip
-
Thanks for looking through this stuff, LeeG. Here's what I thought were three queries without a response. I guess I meant three queries with only ONE response. I could certainly be misinterpreting what this is but I saw the word "query" three times and what I interpret to be a single response "RINPUT", although is the third instance of "RINPUT" a duplicate? Sun 03/09/2014 07:33:12 AM : [ Time] 07:33:23 0(0) Sun 03/09/2014 07:33:14 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 4F 02 Sun 03/09/2014 07:33:14 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 4F 02 06 IOCTL (QUERY) Sun 03/09/2014 07:33:18 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 4F 0A IOCTL (0A) Sun 03/09/2014 07:33:18 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:33:23 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 4F 02 Sun 03/09/2014 07:33:23 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 4F 02 06 IOCTL (QUERY) Sun 03/09/2014 07:33:28 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 4F 0A IOCTL (0A) Sun 03/09/2014 07:33:28 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:33:28 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 23 4F 0A IOCTL (0A) Sun 03/09/2014 07:33:28 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Sun 03/09/2014 07:33:32 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 4F 02 Sun 03/09/2014 07:33:32 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 4F 02 06 IOCTL (QUERY) Sun 03/09/2014 07:33:32 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 4F 0A IOCTL (0A) Sun 03/09/2014 07:33:32 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:33:32 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 49 00 Sun 03/09/2014 07:33:32 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 49 00 06 RINPUT (00) Sun 03/09/2014 07:33:33 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 49 30 RINPUT (30) Sun 03/09/2014 07:33:33 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:33:34 AM : [ Time] 07:33:45 0(0) Sun 03/09/2014 07:33:34 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 23 49 30 RINPUT (30) Sun 03/09/2014 07:33:34 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Sun 03/09/2014 07:33:37 AM : [ 23 8D 7C 2] ST 0 Sun 03/09/2014 07:33:38 AM : [ 23 8D 7C 4] ST 0 Sun 03/09/2014 07:33:38 AM : [ 23 8D 7C 5] ST 255 Sun 03/09/2014 07:33:38 AM : [ 23 8D 7C 6] ST 255 The above events were the result of the query test program sequence that ran at 7:33:22, i.e. “the related one at 7:23:22†2014/03/09, 07:33:22, 1-Initiate Query Test ran True If needed, I can upload the complete log file and event viewer trace if you think I might have missed something. Thanks again.
-
Okay, so Smartenit sent me a new EZIO8SA/PLM Combo but this time with a single band PLM hoping it would solve the problems I'm seeing but it didn't. As the issue is intermittent and Smartenit can't reproduce it, I'm coming back here for advice on what I'm seeing and/or missing in troubleshooting this. I'll recap then build on what I've provided so far using up to date data generated by the single band PLM instead of the dual band one that came with the EZIO8SA initially. I won't repeat a desciption of the programs that I posted earlier to automate the testing in my attempts to catch this intermittent problem. Here's a typical winter time set of HVAC related events I control with three IO Lincs and the EZIO8SA. First the log entries below show a call for heat detected by an IOLinc (15.BB.45) that triggers a query scene made up of the three IOLinc sensors monitoring HVAC calls, one for heat, one for AC and one for Furnace Fan. (Someday I might separate the three but for now a change in any of the them triggers a query of all three). X10 K8 Sat 2014/03/08 09:12:48 PM System Log X10 K8 Off (11) Sat 2014/03/08 09:12:48 PM System Log Scene:1-MISC (Non Lighting) / HVAC / HVAC Sensors Status Query Sat 2014/03/08 09:12:54 PM Program Log 1-MISC (Non Lighting) / HVAC / Sensor - Heat Off - Office Da Status 0% Sat 2014/03/08 09:12:54 PM System Log 1-MISC (Non Lighting) / HVAC / Old Office Damper (for LED) Status 0% Sat 2014/03/08 09:12:55 PM System Log Notes: 1. The IO Lincs are configured to send X10 commands. This and the sensor query are safeguards for reliability, which are needed because ISY does not always see / act on an IO Linc sensor change. 2. Because the IOLinc sensor is ON when the stat call is OFF, the device name above shows that "Heat Off" has turned OFF, meaning heat is ON. 3. "Heat Off" device is the IO Linc sensor and the "Old Office Damper (for LED)" is the relay of the same IOLinc. As I learned not that long ago, an IOLinc query of either the sensor or the relay returns the value of both. I use the relay state only for its matching LED state to provide a visual indicator of the Office Damper (in a scene with the EZIO8SA relay that controls the damper). Noteworthy here, and what seems like a bug, is that there isn't a log entry for the sensor change. The event can be seen in the event viewer (see below) and does cause the query program to run (6 seconds later, as designed) so it seems that a log entry is simply not posted. This is consistent behavior. Here are the L3 event viewer entries from the IO Linc Sensor: Sat 03/08/2014 09:12:36 PM : [ Time] 21:12:42 1(0) Sat 03/08/2014 09:12:41 PM : [iNST-SRX ] 02 50 15.BB.45 00.00.01 CB 11 00 LTONRR (00) Sat 03/08/2014 09:12:41 PM : [std-Group ] 15.BB.45-->Group=1, Max Hops=3, Hops Left=2 Sat 03/08/2014 09:12:41 PM : [ 15 BB 45 1] DON 0 Sat 03/08/2014 09:12:41 PM : [iNST-SRX ] 02 50 15.BB.45 24.1B.FE 41 11 01 LTONRR (01) Sat 03/08/2014 09:12:41 PM : [std-Cleanup ] 15.BB.45-->ISY/PLM Group=1, Max Hops=1, Hops Left=0 Sat 03/08/2014 09:12:41 PM : [iNST-DUP ] Previous message ignored. And below are the event viewer entries aligned to the log entries above. The other two IO Lincs in the scene that is queried are 15.BB.62 and 17.71.EA. What seems a little weird to me is that the status response of those other sensors does NOT end up in the log. When I manually run a query, log entries are posted whether or not the status is a change but when queried here by a program, the only entry logged is for the heat call IO Linc (see above). Side question: 1) what does the INST-ERX message at 09:12:50 represent? Sat 03/08/2014 09:12:42 PM : [X10-RX ] 02 52 3D 00 Sat 03/08/2014 09:12:42 PM : [ X10] K8 Sat 03/08/2014 09:12:42 PM : [X10-RX ] 02 52 33 80 Sat 03/08/2014 09:12:42 PM : [ X10] K8/Off (11) Sat 03/08/2014 09:12:48 PM : [ Time] 21:12:53 1(0) Sat 03/08/2014 09:12:48 PM : [iNST-TX-I1 ] 02 62 15 BB 45 0F 19 01 Sat 03/08/2014 09:12:48 PM : [iNST-ACK ] 02 62 15.BB.45 0F 19 01 06 LTSREQ (01) Sat 03/08/2014 09:12:48 PM : [iNST-SRX ] 02 50 15.BB.45 24.1B.FE 2B 0D 00 (00) Sat 03/08/2014 09:12:48 PM : [std-Direct Ack] 15.BB.45-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 03/08/2014 09:12:48 PM : [iNST-TX-I1 ] 02 62 15 BB 45 0F 19 00 Sat 03/08/2014 09:12:48 PM : [iNST-ACK ] 02 62 15.BB.45 0F 19 00 06 LTSREQ (LIGHT) Sat 03/08/2014 09:12:48 PM : [iNST-SRX ] 02 50 15.BB.45 24.1B.FE 2B 0D 00 (00) Sat 03/08/2014 09:12:48 PM : [std-Direct Ack] 15.BB.45-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 03/08/2014 09:12:48 PM : [iNST-TX-I1 ] 02 62 15 BB 62 0F 19 01 Sat 03/08/2014 09:12:49 PM : [iNST-ACK ] 02 62 15.BB.62 0F 19 01 06 LTSREQ (01) Sat 03/08/2014 09:12:49 PM : [iNST-SRX ] 02 50 15.BB.62 24.1B.FE 2B 08 00 (00) Sat 03/08/2014 09:12:49 PM : [std-Direct Ack] 15.BB.62-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 03/08/2014 09:12:49 PM : [iNST-TX-I1 ] 02 62 15 BB 62 0F 19 00 Sat 03/08/2014 09:12:49 PM : [iNST-ACK ] 02 62 15.BB.62 0F 19 00 06 LTSREQ (LIGHT) Sat 03/08/2014 09:12:49 PM : [iNST-SRX ] 02 50 15.BB.62 24.1B.FE 2B 08 00 (00) Sat 03/08/2014 09:12:49 PM : [std-Direct Ack] 15.BB.62-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 03/08/2014 09:12:49 PM : [iNST-TX-I1 ] 02 62 17 71 EA 0F 19 01 Sat 03/08/2014 09:12:50 PM : [iNST-ACK ] 02 62 17.71.EA 0F 19 01 06 LTSREQ (01) Sat 03/08/2014 09:12:50 PM : [iNST-ERX ] 02 51 15 BB 62 24 1B FE 10 F7 C0 66 DF C0 03 EE FE 81 44 01 0A 0D 3A AA 7D Sat 03/08/2014 09:12:50 PM : [Ext-Direct ] 15.BB.62-->ISY/PLM Group=0, Max Hops=0, Hops Left=0 Sat 03/08/2014 09:12:50 PM : [iNST-SRX ] 02 50 15.BB.62 24.1B.FE 2B 08 00 (00) Sat 03/08/2014 09:12:50 PM : [std-Direct Ack] 15.BB.62-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 03/08/2014 09:12:50 PM : [iNST-SRX ] 02 50 15.BB.62 24.1B.FE 23 08 00 (00) Sat 03/08/2014 09:12:50 PM : [std-Direct Ack] 15.BB.62-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Sat 03/08/2014 09:12:51 PM : [iNST-SRX ] 02 50 17.71.EA 24.1B.FE 2B 00 01 (01) Sat 03/08/2014 09:12:51 PM : [std-Direct Ack] 17.71.EA-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 03/08/2014 09:12:51 PM : [iNST-TX-I1 ] 02 62 17 71 EA 0F 19 00 Sat 03/08/2014 09:12:51 PM : [iNST-ACK ] 02 62 17.71.EA 0F 19 00 06 LTSREQ (LIGHT) Sat 03/08/2014 09:12:52 PM : [iNST-SRX ] 02 50 17.71.EA 24.1B.FE 2B 00 FF (FF) Sat 03/08/2014 09:12:52 PM : [std-Direct Ack] 17.71.EA-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 03/08/2014 09:12:52 PM : [ 15 BB 45 1] ST 0 Sat 03/08/2014 09:12:52 PM : [ 15 BB 45 2] ST 0 Moving to the EZIO8SA side of things. The above action resulted in my Humidifier going on as desired, however, setting the humidifer ON also reported the status of two other EZIO relays that surprised ISY. Relays 1 and 2 were found to be the opposite of what ISY thought. 1-MISC (Non Lighting) / HVAC / Humidifier-EZIO.8(really7) On 255 Sat 2014/03/08 09:13:05 PM Program Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status 0% Sat 2014/03/08 09:13:06 PM System Log 1-MISC (Non Lighting) / HVAC / Fan On-EZIO.2 Status 100% Sat 2014/03/08 09:13:06 PM System Log 1-MISC (Non Lighting) / HVAC / Humidifier-EZIO.8(really7) Status 100% Sat 2014/03/08 09:13:06 PM System Log Here is the event viewer L3 trace that aligns to the above log entries: Sat 03/08/2014 09:13:01 PM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 45 07 Sat 03/08/2014 09:13:01 PM : [ Time] 21:13:05 1(0) Sat 03/08/2014 09:13:01 PM : [iNST-ACK ] 02 62 23.8D.7C 0F 45 07 06 IOON (07) Sat 03/08/2014 09:13:01 PM : [ Time] 21:13:06 1(0) Sat 03/08/2014 09:13:01 PM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 45 82 IOON (82) Sat 03/08/2014 09:13:01 PM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 03/08/2014 09:13:01 PM : [ 23 8D 7C 1] ST 0 Sat 03/08/2014 09:13:01 PM : [ 23 8D 7C 2] ST 255 Sat 03/08/2014 09:13:01 PM : [ 23 8D 7C 8] ST 255 A little over a min later ISY initiates my query testing (the set of programs explained in an earlier post), which does a query of the EZIO8SA and confirms (or updates) the device status reported a minute earlier: 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status Query Sat 2014/03/08 09:14:06 PM Program Log Overnight all worked well as the furnace cycled on and off, repeating the above pattern but without any surprises, and "Fan On-EZIO.2" remained ON throughout. At 7:30 AM the next day, however, the EZIO8SA query surprised ISY again. (A search of the log for "Fan On-EZIO.2" confirms there are no entries between 9:13:06 PM and 7:33:45 AM.) 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status Query Sun 2014/03/09 07:33:25 AM Program Log 1-MISC (Non Lighting) / HVAC / Fan On-EZIO.2 Status 0% Sun 2014/03/09 07:33:45 AM System Log 1-MISC (Non Lighting) / HVAC / Office Damper-EZIO.4 Status 0% Sun 2014/03/09 07:33:45 AM System Log 1-MISC (Non Lighting) / HRV / HRV Low-EZIO.5 Status 100% Sun 2014/03/09 07:33:45 AM System Log 1-MISC (Non Lighting) / HRV / HRV High-EZIO.6 Status 100% Sun 2014/03/09 07:33:45 AM System Log Below are the related event viewer entries. What surprises me are the three queries, each within 10 secs of the previous one. Only one query is sent in my program logic unless the response surprises ISY, in which case a second round of testing is initiated about 13 secs later in the hope it might provide a clue as to what's going on. The second instance relies on the response to the first but there is no response here until the third query about 20 secs after the query is initiated and logged. There is also what appears to be a duplicate query message at 07:33:28 with Max Hops=3, Hops Left=0 in an environment that's otherwise pretty reliable comms-wise. Sun 03/09/2014 07:33:12 AM : [ Time] 07:33:23 0(0) Sun 03/09/2014 07:33:14 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 4F 02 Sun 03/09/2014 07:33:14 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 4F 02 06 IOCTL (QUERY) Sun 03/09/2014 07:33:18 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 4F 0A IOCTL (0A) Sun 03/09/2014 07:33:18 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:33:23 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 4F 02 Sun 03/09/2014 07:33:23 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 4F 02 06 IOCTL (QUERY) Sun 03/09/2014 07:33:28 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 4F 0A IOCTL (0A) Sun 03/09/2014 07:33:28 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:33:28 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 23 4F 0A IOCTL (0A) Sun 03/09/2014 07:33:28 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Sun 03/09/2014 07:33:32 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 4F 02 Sun 03/09/2014 07:33:32 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 4F 02 06 IOCTL (QUERY) Sun 03/09/2014 07:33:32 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 4F 0A IOCTL (0A) Sun 03/09/2014 07:33:32 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:33:32 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 49 00 Sun 03/09/2014 07:33:32 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 49 00 06 RINPUT (00) Sun 03/09/2014 07:33:33 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 49 30 RINPUT (30) Sun 03/09/2014 07:33:33 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:33:34 AM : [ Time] 07:33:45 0(0) Sun 03/09/2014 07:33:34 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 23 49 30 RINPUT (30) Sun 03/09/2014 07:33:34 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Sun 03/09/2014 07:33:37 AM : [ 23 8D 7C 2] ST 0 Sun 03/09/2014 07:33:38 AM : [ 23 8D 7C 4] ST 0 Sun 03/09/2014 07:33:38 AM : [ 23 8D 7C 5] ST 255 Sun 03/09/2014 07:33:38 AM : [ 23 8D 7C 6] ST 255 Just to confirm it wasn't a program that runs/queries twice, I create a custom notification/log when it runs. Here are those entries including the one before and two after the related one at 7:23:22. This also shows the two rounds of automated testing that occured at 7:40 seen further below. 2014/03/09, 07:22:38, 1-Initiate Query Test ran True 2014/03/09, 07:33:22, 1-Initiate Query Test ran True 2014/03/09, 07:40:03, 1-Initiate Query Test ran True 2014/03/09, 07:40:15, 1-Run Query Test Again ran True About 6 mins later, when the heat call ends, ISY is again surprised for two of the EZIO8SA devices : X10 K8 Sun 2014/03/09 07:38:47 AM System Log X10 K8 Sun 2014/03/09 07:38:47 AM System Log X10 K8 On (3) Sun 2014/03/09 07:38:48 AM System Log Scene:1-MISC (Non Lighting) / HVAC / HVAC Sensors Status Query Sun 2014/03/09 07:38:52 AM Program Log 1-MISC (Non Lighting) / HVAC / Sensor - Heat Off - Office Da Status 100% Sun 2014/03/09 07:38:52 AM System Log Bedrooms / Boys Bedroom Table Lamp Status Query Sun 2014/03/09 07:40:00 AM Program Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status Query Sun 2014/03/09 07:40:05 AM Program Log 1-MISC (Non Lighting) / HVAC / Fan On-EZIO.2 Status 100% Sun 2014/03/09 07:40:05 AM System Log 1-MISC (Non Lighting) / HRV / HRV High-EZIO.6 Status 0% Sun 2014/03/09 07:40:05 AM System Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status Query Sun 2014/03/09 07:40:18 AM Program Log Here are the related event viewer L3 entries: Sun 03/09/2014 07:39:53 AM : [ Time] 07:40:05 0(0) Sun 03/09/2014 07:39:53 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 4F 02 Sun 03/09/2014 07:39:53 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 4F 02 06 IOCTL (QUERY) Sun 03/09/2014 07:39:53 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 4F 0A IOCTL (0A) Sun 03/09/2014 07:39:53 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:39:53 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 49 00 Sun 03/09/2014 07:39:53 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 49 00 06 RINPUT (00) Sun 03/09/2014 07:39:53 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 49 30 RINPUT (30) Sun 03/09/2014 07:39:53 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:39:54 AM : [ 23 8D 7C 2] ST 255 Sun 03/09/2014 07:39:54 AM : [ 23 8D 7C 6] ST 0 Sun 03/09/2014 07:40:05 AM : [ Time] 07:40:17 0(0) Sun 03/09/2014 07:40:06 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 4F 02 Sun 03/09/2014 07:40:06 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 4F 02 06 IOCTL (QUERY) Sun 03/09/2014 07:40:06 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 4F 0A IOCTL (0A) Sun 03/09/2014 07:40:06 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 03/09/2014 07:40:06 AM : [iNST-TX-I1 ] 02 62 23 8D 7C 0F 49 00 Sun 03/09/2014 07:40:06 AM : [iNST-ACK ] 02 62 23.8D.7C 0F 49 00 06 RINPUT (00) Sun 03/09/2014 07:40:07 AM : [iNST-SRX ] 02 50 23.8D.7C 24.1B.FE 2B 49 30 RINPUT (30) Sun 03/09/2014 07:40:07 AM : [std-Direct Ack] 23.8D.7C-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 While it would be nice to see log entries for IO Linc sensor changes (and that certainly would have helped me in the past), the only thing that concerns me at this point are the three queries in a row being sent out without responses. I'm also hoping without the dual band PLM in play, it's easy to pinpoint the problem for me to tell Smartnenit. Any suggestions?
-
Hi Michel, Was just looking back and and it seems there's something more than simply a duplicate message going on.
-
It's about 2 months old. Yes, it's dual band. Sent from my iPad using Tapatalk
-
38link, thanks for posting despite the trouble you ran into. After another week and a half of testing (mostly automated) I thought I would provide an update and mention what Smartenit has said about the issue. Below are examples of how ISY is being surprised on a daily basis by the EZIO8SA status following a query. While it doesn’t happen every time the device is queried - and never, so far, when I manually do it - it isn’t a rare occurrence as it happens to varying degrees every day. Just to recap, the programs outlined in my previous post do the following: 1) before a query, the status ISY has is recorded in a variable for all my EZIO8SA relays and programs that look for an unexpected state are enabled 2) the EZIO8SA is queried and for any device that isn't as expected, ISY sends an email 3) After sending the email a second round of query testing is run for that device after a short delay to see if it changes again following the subsequent query. I guesstimate that 10% - 20% of the time there is an unexpected state, the first email is followed by a second email indicating the was now the opposite state. In addition to sending an email, ISY also writes the notification to a custom log file, which augments notifications sent by another program when the relay controlling a humidifier is turned [on /off], as well as when the query test is initiated. Here are 2 sets of custom log entries aligned with the emails shown in my 1st screenshot below. I've highlighted the messages from the Query Test (prefixed by QT). 2014/02/14, 15:36:28, Notification of Humidifier OFF ran True 2014/02/14, 15:43:51, Query HVAC Devices on Sensor ran True 2014/02/14, 15:44:01, QT-Humidifier - Notify Change ON ran because device was showing OFF when it was ON 2014/02/14, 15:44:01, Notification of Humidifier ON ran True 2014/02/14, 15:44:15, QT-Humidifier - Notify Change OFF ran because device was showing ON when it was OFF 2014/02/14, 15:44:15, Notification of Humidifier OFF ran True The above shows: 1) The last recorded activity for the humidifier prior to the query (OFF) 2) ISY is surprised to learn the humidifier is ON 3) The notification that the humidifier is now recorded as ON 4) The query test is run again (although not logged) and again ISY is surprised to learn the humidifier is now OFF 5) The notification that the humidifier is now recorded as OFF Similarly, about an hour later the following was recorded: 2014/02/14, 16:46:51, Notifiication of Humidifier ON ran True 2014/02/14, 16:52:19, Query HVAC Devices on Sensor ran True 2014/02/14, 16:52:30, QT-Basement Damper- Notify Change ON ran because device was showing OFF when it was ON 2014/02/14, 16:52:31, QT-Humidifier - Notify Change OFF ran because device was showing ON when it was OFF 2014/02/14, 16:52:31, Notifiication of Humidifier OFF ran False 2014/02/14, 16:52:45, QT-Basement Damper- Notify Change OFF ran because device was showing ON when it was OFF 2014/02/14, 16:52:46, QT-Humidifier - Notify Change ON ran because device was showing OFF when it was ON 2014/02/14, 16:52:46, Notifiication of Humidifier ON ran True 2014/02/14, 16:52:47, QT-Humidifier - Notify Change ON ran because device was showing OFF when it was ON 2014/02/14, 16:52:47, QT-Basement Damper- Notify Change OFF ran because device was showing ON when it was OFF 2014/02/14, 16:58:06, Notifiication of Humidifier OFF ran True The 1st screenshot below shows a sampling of how frequently these unexpected statuses followed by the reversal can happen. The 2nd screenshot shows a sampling of the occurrences when ISY is surprised by the status and the second query does not see the reverse. A day can could go by without me seeing the first scenario but no day has gone by since I put these test programs in a few week ago where I haven’t had a message from ISY about an unexpected EZIO8SA status. If every time an entry changed it would change back, or if every time I queried the EZIO8SA ALL relay statuses were unexpected, I would think it's only a problem with querying (unexplained messages shown by LeeG) but because that's not the case, I'm thinking something is changing the EZIO8SA relays without ISY knowing. The problem now is that - unless I'm missing something - catching this would require having to sit there for probably hours at a time and watch devices controlled by the EZIO8SA (since there are no LED's on the EZIO) alongside an ISY console session running the event viewer at level 3 hoping I actually catch it happen during the query test window and before ISY takes action that might change the device back to what ISY thinks it's supposed to be. That's about as appealing to me as the idea of watching paint dry. Smartenit can't replicate the problem and has suggested an older model PLM (pre-dual band) would fix the problem. Have asked them to send me one to try that but am concerned that these older PLMs aren't or won't be supported for much longer. While they have some inventory today, are older PLM's still being made/licensed by smartlabs? What is the longer term fix? How will an older PLM hold up with i2CS and future changes? Asking UDI to ignore the extra messages occasionally sent by the newer PLMs would presumably fix the query problem, but what about the mysterious state changes that may not be about these extra messages? Also, I didn't see anything come out to fix the duplicate messages that sometimes come from an IO Linc. How different would ignoring extra messages from an EZIO8SA be from the perspective of UDI putting something in? I'm kind of stuck because there are problems with both IO Lincs and the EZIO8SA. Are there other options available today or on the horizon, e.g. zwave?
-
Here's an example of a query that surprised ISY with 6 incorrect statuses, followed by the related level 3 events. It looks like there are a couple of extra queries and other messages along the way before the answer arrives, a full 10 seconds after the query and 8-9 seconds after the log entries are posted. Sat 02/08/2014 12:16:15 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 4F 02 Sat 02/08/2014 12:16:15 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 4F 02 06 IOCTL (QUERY) Sat 02/08/2014 12:16:15 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 4F 07 IOCTL (07) Sat 02/08/2014 12:16:15 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 02/08/2014 12:16:15 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 49 00 Sat 02/08/2014 12:16:15 PM : [iNST-ACK ] 02 62 28.AD.BD 00 4F 02 06 IOCTL (QUERY) Sat 02/08/2014 12:16:16 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 20 B0 C7 (C7) Sat 02/08/2014 12:16:16 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=0, Hops Left=0 Sat 02/08/2014 12:16:16 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 20 B0 C7 (C7) Sat 02/08/2014 12:16:16 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=0, Hops Left=0 Sat 02/08/2014 12:16:16 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 20 4F 02 IOCTL (QUERY) Sat 02/08/2014 12:16:16 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=0, Hops Left=0 Sat 02/08/2014 12:16:25 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 49 00 Sat 02/08/2014 12:16:25 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 49 00 06 RINPUT (00) Sat 02/08/2014 12:16:25 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 49 30 RINPUT (30) Sat 02/08/2014 12:16:25 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 For comparison, here's what an event trace looks like when there are no surprises. Sat 02/08/2014 12:30:51 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 4F 02 Sat 02/08/2014 12:30:51 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 4F 02 06 IOCTL (QUERY) Sat 02/08/2014 12:30:52 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 4F 13 IOCTL (13) Sat 02/08/2014 12:30:52 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 02/08/2014 12:30:52 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 49 00 Sat 02/08/2014 12:30:52 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 49 00 06 RINPUT (00) Sat 02/08/2014 12:30:52 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 49 30 RINPUT (30) Sat 02/08/2014 12:30:52 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2
-
I got lucky today and was able to catch a blast of the problem I see intermittently with the event viewer at level 3. First let me set up what I have in place. I have up to two rounds of device querying to catch/notify me when any of my EZIO relays report a status that ISY did not have in its records. At least that's what I think I'm doing. Below are the programs involved. This first one is called by another program that gets triggered every 15 mins or when an IOLinc sensor that monitors stat call changes (today a heat call, in the summer an AC call), or when an X10 command from an IO Linc is received. The X10 command was put in as a backup. If - No Conditions - (To add one, press 'Schedule' or 'Condition') Then $iRunQueryTestAgain = 0 $sHVAC.Query.Count = 0 Run Program 'QT-Basement Damper- Set Variable' (If) Run Program 'QT-Fan ON - Set Variable' (If) Run Program 'QT-Furnace Damper- Set Variable' (If) Run Program 'QT-Office Damper- Set Variable' (If) Run Program 'QT-HRV Low - Set Variable' (If) Run Program 'QT-HRV High - Set Variable' (If) Run Program 'QT-Humidifier - Set Variable' (If) Send Notification to 'me' content 'Generic Program Log' Wait 3 seconds Set '1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1' Query Wait 10 seconds Run Program '1-Run Query Test Again' (If) Else - No Actions - (To add one, press 'Action') There are then seven times each of the three following programs; one for each EZIO relay I use. All variables in the three programs below are integer variables. Program 'QT-Basement Damper- Set Variable' If Status '1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1' is 100% Then $a.StateOfBasementDamper = 1 Wait 1 second Enable Program 'QT-Basement Damper- Notify Change ON' Enable Program 'QT-Basement Damper- Notify Change OFF' Wait 8 seconds Disable Program 'QT-Basement Damper- Notify Change ON' Disable Program 'QT-Basement Damper- Notify Change OFF' Else $a.StateOfBasementDamper = 0 Wait 1 second Enable Program 'QT-Basement Damper- Notify Change ON' Enable Program 'QT-Basement Damper- Notify Change OFF' Wait 8 seconds Disable Program 'QT-Basement Damper- Notify Change ON' Disable Program 'QT-Basement Damper- Notify Change OFF' Program 'QT-Basement Damper- Notify Change ON' If Status '1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1' is 100% And $a.StateOfBasementDamper is 0 Then Send Notification to 'me' content 'Device Changed ON After Query' $iRunQueryTestAgain = 1 Else - No Actions - (To add one, press 'Action') Program 'QT-Basement Damper- Notify Change OFF' If Status '1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1' is Off And $a.StateOfBasementDamper is 1 Then Send Notification to 'Jean' content 'Device Changed OFF After Query' $iRunQueryTestAgain = 1 Else - No Actions - (To add one, press 'Action') Should one of the latter two above run, it set $iRunQueryTestAgain = 1 for the following second round of testing If $iRunQueryTestAgain > 0 Then $sHVAC.Query.Count = 0 Run Program 'QT-Basement Damper- Set Variable' (If) Run Program 'QT-Fan ON - Set Variable' (If) Run Program 'QT-Furnace Damper- Set Variable' (If) Run Program 'QT-Office Damper- Set Variable' (If) Run Program 'QT-HRV Low - Set Variable' (If) Run Program 'QT-HRV High - Set Variable' (If) Run Program 'QT-Humidifier - Set Variable' (If) Send Notification to 'Jean' content 'Generic Program Log' Wait 3 seconds Set '1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1' Query $iRunQueryTestAgain = 0 Else - No Actions - (To add one, press 'Action') This afternoon I got a flood of notifications showing an unexpected device status from the 1st query test followed by the reverse status from the second query test. See attached screenshot at the bottom. Below are the related log events. The first chunk shows the events from one heat call change / query test prior to the (second) one that resulted in the notifications getting sent. X10 K8 Fri 2014/02/07 02:17:14 PM System Log X10 K8 Fri 2014/02/07 02:17:15 PM System Log X10 K8 Off (11) Fri 2014/02/07 02:17:15 PM System Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status Query Fri 2014/02/07 02:17:23 PM Program Log Scene:1-MISC (Non Lighting) / HVAC / HVAC Sensors Status Query Fri 2014/02/07 02:17:30 PM Program Log 1-MISC (Non Lighting) / HVAC / Sensor - Heat Off - Office Da Status 0% Fri 2014/02/07 02:17:31 PM System Log 1-MISC (Non Lighting) / HVAC / Humidifier-EZIO.8(really7) On 255 Fri 2014/02/07 02:17:41 PM Program Log 1-MISC (Non Lighting) / HVAC / Humidifier-EZIO.8(really7) Status 100% Fri 2014/02/07 02:17:41 PM System Log Scene:1-MISC (Non Lighting) / HVAC / Office Damper for Prgs On Fri 2014/02/07 02:17:44 PM Program Log 1-MISC (Non Lighting) / HVAC / Old Office Damper (for LED) Status 100% Fri 2014/02/07 02:17:44 PM System Log 1-MISC (Non Lighting) / HVAC / Office Damper-EZIO.4 Status 100% Fri 2014/02/07 02:17:44 PM System Log Scene:1-MISC (Non Lighting) / HRV / HRV High for Prgs On Fri 2014/02/07 02:17:49 PM Program Log 1-MISC (Non Lighting) / HRV / Back KPL.G - HRV High (XLink) Status 100% Fri 2014/02/07 02:17:49 PM System Log 1-MISC (Non Lighting) / HRV / Back KPL.H - HRV High (XLink) Status 100% Fri 2014/02/07 02:17:49 PM System Log 1-MISC (Non Lighting) / HRV / HRV High-EZIO.6 Status 100% Fri 2014/02/07 02:17:49 PM System Log Scene:1-MISC (Non Lighting) / HRV / HRV Low for Prgs Off 0 Fri 2014/02/07 02:18:00 PM Program Log 1-MISC (Non Lighting) / HRV / Back KPL.F - HRV Low Status 0% Fri 2014/02/07 02:18:00 PM System Log 1-MISC (Non Lighting) / HRV / HRV Low-EZIO.5 Status 0% Fri 2014/02/07 02:18:00 PM System Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Off 0 Fri 2014/02/07 02:18:14 PM Program Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status 0% Fri 2014/02/07 02:18:14 PM System Log And here is the set of log entries related to the notifications. X10 K8 Fri 2014/02/07 02:24:06 PM System Log X10 K8 Fri 2014/02/07 02:24:06 PM System Log X10 K8 On (3) Fri 2014/02/07 02:24:06 PM System Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status Query Fri 2014/02/07 02:24:15 PM Program Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status 100% Fri 2014/02/07 02:24:16 PM System Log 1-MISC (Non Lighting) / HVAC / Fan On-EZIO.2 Status 100% Fri 2014/02/07 02:24:16 PM System Log 1-MISC (Non Lighting) / HVAC / Furnace Rm Damper-EZIO.3 Status 100% Fri 2014/02/07 02:24:16 PM System Log 1-MISC (Non Lighting) / HRV / HRV High-EZIO.6 Status 0% Fri 2014/02/07 02:24:16 PM System Log 1-MISC (Non Lighting) / HVAC / Humidifier-EZIO.8(really7) Status 0% Fri 2014/02/07 02:24:16 PM System Log Scene:1-MISC (Non Lighting) / HRV / HRV High for Prgs On Fri 2014/02/07 02:24:22 PM Program Log Scene:1-MISC (Non Lighting) / HVAC / HVAC Sensors Status Query Fri 2014/02/07 02:24:22 PM Program Log 1-MISC (Non Lighting) / HRV / HRV High-EZIO.6 Status 100% Fri 2014/02/07 02:24:22 PM System Log 1-MISC (Non Lighting) / HVAC / Sensor - Heat Off - Office Da Status 100% Fri 2014/02/07 02:24:23 PM System Log 1-MISC (Non Lighting) / HVAC / Humidifier-EZIO.8(really7) On 255 Fri 2014/02/07 02:24:26 PM Program Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status 0% Fri 2014/02/07 02:24:26 PM System Log 1-MISC (Non Lighting) / HVAC / Fan On-EZIO.2 Status 0% Fri 2014/02/07 02:24:26 PM System Log 1-MISC (Non Lighting) / HVAC / Furnace Rm Damper-EZIO.3 Status 0% Fri 2014/02/07 02:24:26 PM System Log 1-MISC (Non Lighting) / HVAC / Humidifier-EZIO.8(really7) Status 100% Fri 2014/02/07 02:24:26 PM System Log Now the related level 3 event viewer entries, the first block being what ISY would end up with in its records when the second block of commands is sent/received. Fri 02/07/2014 02:17:13 PM : [ X10] K8 Fri 02/07/2014 02:17:13 PM : [X10-RX ] 02 52 3D 00 Fri 02/07/2014 02:17:13 PM : [ X10] K8 Fri 02/07/2014 02:17:13 PM : [X10-RX ] 02 52 33 80 Fri 02/07/2014 02:17:13 PM : [ X10] K8/Off (11) Fri 02/07/2014 02:17:20 PM : [ Time] 14:17:20 1(0) Fri 02/07/2014 02:17:21 PM : [VAR 2 68 ] 0 Fri 02/07/2014 02:17:21 PM : [ Time] 14:17:21 1(0) Fri 02/07/2014 02:17:21 PM : [VAR 2 78 ] 0 Fri 02/07/2014 02:17:21 PM : [VAR 2 79 ] 0 Fri 02/07/2014 02:17:21 PM : [VAR 2 77 ] 1 Fri 02/07/2014 02:17:21 PM : [VAR 2 76 ] 0 Fri 02/07/2014 02:17:21 PM : [VAR 2 73 ] 1 Fri 02/07/2014 02:17:21 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 4F 02 Fri 02/07/2014 02:17:21 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 4F 02 06 IOCTL (QUERY) Fri 02/07/2014 02:17:22 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 4F 11 IOCTL (11) Fri 02/07/2014 02:17:22 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:17:22 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 49 00 Fri 02/07/2014 02:17:22 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 49 00 06 RINPUT (00) Fri 02/07/2014 02:17:23 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 49 30 RINPUT (30) Fri 02/07/2014 02:17:23 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:17:23 PM : [ Time] 14:17:24 1(0) Fri 02/07/2014 02:17:23 PM : [ Time] 14:17:25 1(0) Fri 02/07/2014 02:17:29 PM : [iNST-TX-I1 ] 02 62 15 BB 45 0F 19 01 Fri 02/07/2014 02:17:29 PM : [iNST-ACK ] 02 62 15.BB.45 0F 19 01 06 LTSREQ (01) Fri 02/07/2014 02:17:29 PM : [iNST-SRX ] 02 50 15.BB.45 24.1B.FE 2B 0D 00 (00) Fri 02/07/2014 02:17:29 PM : [std-Direct Ack] 15.BB.45-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:17:29 PM : [iNST-TX-I1 ] 02 62 15 BB 45 0F 19 00 Fri 02/07/2014 02:17:29 PM : [iNST-ACK ] 02 62 15.BB.45 0F 19 00 06 LTSREQ (LIGHT) Fri 02/07/2014 02:17:29 PM : [iNST-SRX ] 02 50 15.BB.45 24.1B.FE 2B 0D 00 (00) Fri 02/07/2014 02:17:30 PM : [std-Direct Ack] 15.BB.45-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:17:30 PM : [iNST-TX-I1 ] 02 62 15 BB 62 0F 19 01 Fri 02/07/2014 02:17:30 PM : [iNST-ACK ] 02 62 15.BB.62 0F 19 01 06 LTSREQ (01) Fri 02/07/2014 02:17:30 PM : [iNST-SRX ] 02 50 15.BB.62 24.1B.FE 2B 08 00 (00) Fri 02/07/2014 02:17:30 PM : [std-Direct Ack] 15.BB.62-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:17:30 PM : [iNST-TX-I1 ] 02 62 15 BB 62 0F 19 00 Fri 02/07/2014 02:17:30 PM : [iNST-ACK ] 02 62 15.BB.62 0F 19 00 06 LTSREQ (LIGHT) Fri 02/07/2014 02:17:30 PM : [iNST-SRX ] 02 50 15.BB.62 24.1B.FE 2B 08 00 (00) Fri 02/07/2014 02:17:31 PM : [std-Direct Ack] 15.BB.62-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:17:31 PM : [iNST-TX-I1 ] 02 62 17 71 EA 0F 19 01 Fri 02/07/2014 02:17:31 PM : [iNST-ACK ] 02 62 17.71.EA 0F 19 01 06 LTSREQ (01) Fri 02/07/2014 02:17:31 PM : [iNST-SRX ] 02 50 17.71.EA 24.1B.FE 2B 00 01 (01) Fri 02/07/2014 02:17:31 PM : [std-Direct Ack] 17.71.EA-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:17:31 PM : [iNST-TX-I1 ] 02 62 17 71 EA 0F 19 00 Fri 02/07/2014 02:17:31 PM : [iNST-ACK ] 02 62 17.71.EA 0F 19 00 06 LTSREQ (LIGHT) Fri 02/07/2014 02:17:31 PM : [iNST-SRX ] 02 50 17.71.EA 24.1B.FE 2B 00 FF (FF) Fri 02/07/2014 02:17:32 PM : [std-Direct Ack] 17.71.EA-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:17:32 PM : [ Time] 14:17:33 1(0) Fri 02/07/2014 02:17:32 PM : [ Time] 14:17:33 1(0) Fri 02/07/2014 02:17:33 PM : [ 15 BB 45 1] ST 0 Fri 02/07/2014 02:17:33 PM : [VAR 2 52 ] -670 Fri 02/07/2014 02:17:33 PM : [VAR 2 12 ] -1 Fri 02/07/2014 02:17:35 PM : [VAR 2 58 ] 1756 Fri 02/07/2014 02:17:35 PM : [VAR 2 70 ] 1912 Fri 02/07/2014 02:17:37 PM : [VAR 2 59 ] 1962 Fri 02/07/2014 02:17:37 PM : [VAR 2 70 ] 1910 Fri 02/07/2014 02:17:39 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 45 07 Fri 02/07/2014 02:17:39 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 45 07 06 IOON (07) Fri 02/07/2014 02:17:40 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 45 91 IOON (91) Fri 02/07/2014 02:17:40 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:17:40 PM : [ 28 AD BD 8] ST 255 Fri 02/07/2014 02:17:41 PM : [VAR 2 50 ] 2106 Fri 02/07/2014 02:17:43 PM : [iNST-TX-I1 ] 02 62 00 00 16 CF 11 00 Fri 02/07/2014 02:17:43 PM : [ Time] 14:17:44 1(0) Fri 02/07/2014 02:17:43 PM : [iNST-ACK ] 02 62 00.00.16 CF 11 00 06 LTONRR (00) Fri 02/07/2014 02:17:43 PM : [ 15 BB 45 2] ST 255 Fri 02/07/2014 02:17:43 PM : [ 28 AD BD 4] ST 255 Fri 02/07/2014 02:17:43 PM : [VAR 2 62 ] 481 Fri 02/07/2014 02:17:45 PM : [VAR 2 60 ] 2006 Fri 02/07/2014 02:17:45 PM : [VAR 2 70 ] 1908 Fri 02/07/2014 02:17:49 PM : [ Time] 14:17:48 1(0) Fri 02/07/2014 02:17:49 PM : [iNST-TX-I1 ] 02 62 00 00 20 CF 11 00 Fri 02/07/2014 02:17:49 PM : [iNST-ACK ] 02 62 00.00.20 CF 11 00 06 LTONRR (00) Fri 02/07/2014 02:17:49 PM : [VAR 2 42 ] 1 Fri 02/07/2014 02:17:49 PM : [ 20 43 49 7] ST 255 Fri 02/07/2014 02:17:49 PM : [ 20 43 49 8] ST 255 Fri 02/07/2014 02:17:49 PM : [ 28 AD BD 6] ST 255 Fri 02/07/2014 02:17:49 PM : [ Time] 14:17:50 1(0) Fri 02/07/2014 02:17:49 PM : [VAR 2 68 ] 1 Fri 02/07/2014 02:17:50 PM : [VAR 2 33 ] 152 Fri 02/07/2014 02:17:53 PM : [VAR 2 32 ] 56 Fri 02/07/2014 02:17:59 PM : [iNST-TX-I1 ] 02 62 00 00 1F CF 13 00 Fri 02/07/2014 02:17:59 PM : [VAR 2 38 ] 0 Fri 02/07/2014 02:17:59 PM : [iNST-ACK ] 02 62 00.00.1F CF 13 00 06 LTOFFRR(00) Fri 02/07/2014 02:17:59 PM : [ 20 43 49 6] ST 0 Fri 02/07/2014 02:17:59 PM : [ 28 AD BD 5] ST 0 Fri 02/07/2014 02:18:02 PM : [VAR 2 12 ] 1 Fri 02/07/2014 02:18:12 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 46 00 Fri 02/07/2014 02:18:12 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 46 00 06 IOOFF (00) Fri 02/07/2014 02:18:13 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 46 A8 IOOFF (A8) Fri 02/07/2014 02:18:13 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:18:13 PM : [ 28 AD BD 1] ST 0 Fri 02/07/2014 02:24:03 PM : [ X10] K8 Fri 02/07/2014 02:24:04 PM : [X10-RX ] 02 52 3D 00 Fri 02/07/2014 02:24:04 PM : [ X10] K8 Fri 02/07/2014 02:24:04 PM : [X10-RX ] 02 52 32 80 Fri 02/07/2014 02:24:04 PM : [ X10] K8/On (3) Fri 02/07/2014 02:24:13 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 4F 02 Fri 02/07/2014 02:24:13 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 4F 02 06 IOCTL (QUERY) Fri 02/07/2014 02:24:13 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 4F A8 IOCTL (A8) Fri 02/07/2014 02:24:13 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:13 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 49 00 Fri 02/07/2014 02:24:13 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 49 00 06 RINPUT (00) Fri 02/07/2014 02:24:13 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 49 30 RINPUT (30) Fri 02/07/2014 02:24:13 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:15 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 21 89 0F (0F) Fri 02/07/2014 02:24:15 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=1, Hops Left=0 Fri 02/07/2014 02:24:15 PM : [ 28 AD BD 1] ST 255 Fri 02/07/2014 02:24:15 PM : [ 28 AD BD 2] ST 255 Fri 02/07/2014 02:24:15 PM : [ 28 AD BD 3] ST 255 Fri 02/07/2014 02:24:15 PM : [ 28 AD BD 6] ST 0 Fri 02/07/2014 02:24:15 PM : [ 28 AD BD 8] ST 0 Fri 02/07/2014 02:24:20 PM : [iNST-TX-I1 ] 02 62 00 00 20 CF 11 00 Fri 02/07/2014 02:24:20 PM : [iNST-ACK ] 02 62 00.00.20 CF 11 00 06 LTONRR (00) Fri 02/07/2014 02:24:20 PM : [iNST-TX-I1 ] 02 62 15 BB 45 0F 19 01 Fri 02/07/2014 02:24:20 PM : [iNST-ACK ] 02 62 15.BB.45 0F 19 01 06 LTSREQ (01) Fri 02/07/2014 02:24:20 PM : [iNST-SRX ] 02 50 15.BB.45 24.1B.FE 2B 0D 01 (01) Fri 02/07/2014 02:24:20 PM : [std-Direct Ack] 15.BB.45-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:20 PM : [iNST-TX-I1 ] 02 62 15 BB 45 0F 19 00 Fri 02/07/2014 02:24:20 PM : [iNST-ACK ] 02 62 15.BB.45 0F 19 00 06 LTSREQ (LIGHT) Fri 02/07/2014 02:24:21 PM : [iNST-SRX ] 02 50 15.BB.45 24.1B.FE 2B 0D FF (FF) Fri 02/07/2014 02:24:21 PM : [std-Direct Ack] 15.BB.45-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:21 PM : [iNST-TX-I1 ] 02 62 15 BB 62 0F 19 01 Fri 02/07/2014 02:24:21 PM : [iNST-ACK ] 02 62 15.BB.62 0F 19 01 06 LTSREQ (01) Fri 02/07/2014 02:24:21 PM : [iNST-SRX ] 02 50 15.BB.62 24.1B.FE 2B 08 00 (00) Fri 02/07/2014 02:24:21 PM : [std-Direct Ack] 15.BB.62-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:21 PM : [iNST-TX-I1 ] 02 62 15 BB 62 0F 19 00 Fri 02/07/2014 02:24:21 PM : [iNST-ACK ] 02 62 15.BB.62 0F 19 00 06 LTSREQ (LIGHT) Fri 02/07/2014 02:24:22 PM : [iNST-SRX ] 02 50 15.BB.62 24.1B.FE 2B 08 00 (00) Fri 02/07/2014 02:24:22 PM : [std-Direct Ack] 15.BB.62-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:22 PM : [iNST-TX-I1 ] 02 62 17 71 EA 0F 19 01 Fri 02/07/2014 02:24:22 PM : [iNST-ACK ] 02 62 17.71.EA 0F 19 01 06 LTSREQ (01) Fri 02/07/2014 02:24:22 PM : [iNST-SRX ] 02 50 17.71.EA 24.1B.FE 2B 00 01 (01) Fri 02/07/2014 02:24:22 PM : [std-Direct Ack] 17.71.EA-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:22 PM : [iNST-TX-I1 ] 02 62 17 71 EA 0F 19 00 Fri 02/07/2014 02:24:22 PM : [iNST-ACK ] 02 62 17.71.EA 0F 19 00 06 LTSREQ (LIGHT) Fri 02/07/2014 02:24:23 PM : [iNST-SRX ] 02 50 17.71.EA 24.1B.FE 2B 00 FF (FF) Fri 02/07/2014 02:24:23 PM : [std-Direct Ack] 17.71.EA-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:23 PM : [ Time] 14:24:25 1(0) Fri 02/07/2014 02:24:23 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 45 07 Fri 02/07/2014 02:24:23 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 45 07 06 IOON (07) Fri 02/07/2014 02:24:24 PM : [ Time] 14:24:26 1(0) Fri 02/07/2014 02:24:24 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 45 A8 IOON (A8) Fri 02/07/2014 02:24:24 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:24 PM : [ 28 AD BD 6] ST 255 Fri 02/07/2014 02:24:25 PM : [ 15 BB 45 1] ST 255 Fri 02/07/2014 02:24:26 PM : [ 28 AD BD 1] ST 0 Fri 02/07/2014 02:24:26 PM : [ 28 AD BD 2] ST 0 Fri 02/07/2014 02:24:27 PM : [ 28 AD BD 3] ST 0 Fri 02/07/2014 02:24:27 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 4F 02 Fri 02/07/2014 02:24:27 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 4F 02 06 IOCTL (QUERY) Fri 02/07/2014 02:24:27 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 4F A8 IOCTL (A8) Fri 02/07/2014 02:24:27 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:27 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 49 00 Fri 02/07/2014 02:24:27 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 49 00 06 RINPUT (00) Fri 02/07/2014 02:24:27 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 49 30 RINPUT (30) Fri 02/07/2014 02:24:27 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Fri 02/07/2014 02:24:29 PM : [ 28 AD BD 8] ST 255 Any insight into what's happening would be appreciated. Hopefully I've provided everything that's available but if not, please let me know.
-
Why then does the event log have a status entry for Front Light Companion Sw, one of the devices in the scene, right after calling that scene? Scene:All ON/OFF Downstairs Off 0 Mon 2014/02/03 10:50:50 PM Program Log Main Floor / Front Light Companion Sw Status 0% Mon 2014/02/03 10:50:50 PM System Log
-
wait, I take that back. The device that made me look into this (master bedroom ceiling light) and the boys bedroom ceiling light are not part of that scene.
-
Yes, I did, and it explains (or likely explains) the situation when the response is related to IO Lincs. I also have an explanation for the Front Inside Light That leaves the following unexplained: From my original post: Scene:My Lighting Status Query Sun 2014/02/02 03:00:03 AM Program Log Main Floor / Front Light Companion Sw Status 100% Sun 2014/02/02 03:00:30 AM System Log From my more recent post: Scene:My Lighting Status Query Sun 2014/01/19 04:45:13 PM Program Log X10 G9 Status = On ( Sun 2014/01/19 04:45:14 PM System Log X10 Transceiver Module Outlet Status 100% Sun 2014/01/19 04:45:14 PM System Log Now let me add to that what happened for the query all the night before last: Scene:My Lighting Status Query Mon 2014/02/03 03:00:03 AM Program Log Kitchen / Family Rm Wall Light Status 0% Mon 2014/02/03 03:00:24 AM System Log Kitchen / Kitchen Sink Area Light Status 0% Mon 2014/02/03 03:00:24 AM System Log Main Floor / Front Light Companion Sw Status 0% Mon 2014/02/03 03:00:31 AM System Log Kitchen / Bookcase Lights Status 0% Mon 2014/02/03 03:00:45 AM System Log X10 G9 Mon 2014/02/03 03:00:47 AM Program Log X10 G9 Status Request (10) Mon 2014/02/03 03:00:47 AM Program Log All the above, except for the X10 devices, were turned off by the All ON/OFF Downstairs scene earlier that evening. Here's the log showing that event Main Floor / FrontKPL.H-Sleep Status 100% Mon 2014/02/03 10:50:49 PM System Log Scene:All ON/OFF Downstairs Off 0 Mon 2014/02/03 10:50:50 PM Program Log Main Floor / Front Light Companion Sw Status 0% Mon 2014/02/03 10:50:50 PM System Log If I read this right, the only device that was turned off was Front Light Companion Sw and all the other devices in the scene were already OFF and therefore not logged. (The scene has 10 devices in it.) Other than for X10 devices, a common thread so far for the unexpected/unexplained statuses seems to be devices that are turned off by the scene All ON/OFF Downstairs. I suppose the other thing left unexplained is why ISY rebooted itself but I guess that really should be a separate thread (that I'm going to pass on at this point since I didn't catch it when it happened and there's little to go on other than what I've provided in my original post.)
-
Xathros, thanks for the screenshot. Although I was confused about the two query all's when I expected only one, it dawned on me from your screenshot why that happened. I have "Catch up schedules at Restart". See screenshot below. I guess if I wanted to prevent the query all from running a second time after a restart, I would have to either schedule it for 11:59:59 PM since the catch up is from 00:00:00 the day of the restart. That or turn off "Query at restart" and schedule the query all for shortly after midnight so a restart before 3AM - although unlikely - won't miss running it. The second thing that confused me was the fact that a second query all 3 minutes after the first returned some different statuses. While I know the 1D.5B.9E-Relay is my problematic v41 IO Linc that always responds (and is neither trigger reversed, nor in momentary mode), the status of the other devices should have been the same for the two queries. Scene:My Lighting Status Query Sun 2014/01/19 04:45:13 PM Program Log X10 G9 Status = On ( Sun 2014/01/19 04:45:14 PM System Log X10 Transceiver Module Outlet Status 100% Sun 2014/01/19 04:45:14 PM System Log 15 B9 70 2 Status 0% Sun 2014/01/19 04:45:24 PM System Log 1D.5B.9E-Relay Status 100% Sun 2014/01/19 04:45:49 PM System Log
-
Thanks. That would explain why this one happens daily without fail. I changed the program to send an OFF. I don't actually remember setting it to do a Fade Down but that's what was there. Probably did it to get a nice slow off since the local ramp rate is not that slow, but maybe I'll just create a scene to do it. I'm not going to notice / look for a companion switch being off when it should be on given that no load is attached to it so for this device I'm not too worried about it. For other things though, like my bedroom ceiling light (original post), this issue is of greater concern. I'll have to watch more closely and, I guess, run more overnight level 3 event viewer and sift through the data as I now think this may explain other misbehavior that I just ignored. For example I've occasionally gotten up in the middle of the night to find lights on downstairs and just turned them off without looking into it.
-
Thanks for the reply, LeeG. Am, not worried about the EZIO8SA here unless querying it caused or contributed to ISY crashing. I have another post on the EZIO8SA and will update that post when I have more data from some programs I added yesterday to do a second round of query tests when the status is not as expected. For this problem, I left the event viewer at level 3 overnight last night and the following two unexpected statuses were reported during the 3AM query: Scene:My Lighting Status Query Sun 2014/02/02 03:00:03 AM Program Log Main Floor / Front Inside Light Status 0% Sun 2014/02/02 03:00:29 AM System Log Main Floor / Front Light Companion Sw Status 100% Sun 2014/02/02 03:00:30 AM System Log Below is the event viewer data: Front Inside Light = 16.10.F6 Front Light Companion SW = 0F.D4.91 Sun 02/02/2014 03:00:22 AM : [iNST-TX-I1 ] 02 62 16 10 F6 0F 19 00 Sun 02/02/2014 03:00:22 AM : [iNST-ACK ] 02 62 16.10.F6 0F 19 00 06 LTSREQ (LIGHT) Sun 02/02/2014 03:00:22 AM : [iNST-SRX ] 02 50 16.10.F6 24.1B.FE 27 22 00 (00) Sun 02/02/2014 03:00:22 AM : [std-Direct Ack] 16.10.F6-->ISY/PLM Group=0, Max Hops=3, Hops Left=1 Sun 02/02/2014 03:00:23 AM : [iNST-TX-I1 ] 02 62 0F D4 91 0F 19 00 Sun 02/02/2014 03:00:23 AM : [iNST-ACK ] 02 62 0F.D4.91 0F 19 00 06 LTSREQ (LIGHT) Sun 02/02/2014 03:00:23 AM : [iNST-SRX ] 02 50 0F.D4.91 24.1B.FE 2B 0F FF PING (FF) Sun 02/02/2014 03:00:23 AM : [std-Direct Ack] 0F.D4.91-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sun 02/02/2014 03:00:23 AM : [iNST-TX-I1 ] 02 62 16 D9 56 0F 19 00 Sun 02/02/2014 03:00:23 AM : [iNST-SRX ] 02 50 0F.D4.91 24.1B.FE 23 0F FF PING (FF) Sun 02/02/2014 03:00:23 AM : [std-Direct Ack] 0F.D4.91-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Sun 02/02/2014 03:00:23 AM : [iNST-ACK ] 02 62 16.D9.56 0F 19 00 06 LTSREQ (LIGHT) Sun 02/02/2014 03:00:24 AM : [iNST-SRX ] 02 50 16.D9.56 24.1B.FE 2B 0A FF LNK-OFF(FF) Sun 02/02/2014 03:00:24 AM : [std-Direct Ack] 16.D9.56-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Did the Front Light Companion Sw respond twice? Both devices had been turned off earlier in the evening with the push of a Front KPL Sleep button. Here are the log entries showing that: Main Floor / FrontKPL.H-Sleep Status 100% Sat 2014/02/01 09:46:02 PM System Log Scene:All ON/OFF Downstairs Off 0 Sat 2014/02/01 09:46:03 PM Program Log Main Floor / Front Light Companion Sw Status 0% Sat 2014/02/01 09:46:03 PM System Log Kitchen / EatingKPL.1 Status 0% Sat 2014/02/01 09:46:03 PM System Log Kitchen / EatingKPL.1 Off 0 Sat 2014/02/01 09:46:06 PM Program Log 30 secs after KPL Sleep Button is pushed, Front Inside Light is turned off, per the program I have: Main Floor / Front Inside Light Fade Start 0 Sat 2014/02/01 09:46:33 PM Program Log Below is the corresponding event viewer data: Front Light Companion SW is part of All ON/OFF Downstairs scene, which I presume is the highlighted address below (in ISY the scene number is 51164) 17.A3.7B is FrontKPL address 18.58.D8 is EatingKPL address Sat 02/01/2014 09:46:04 PM : [iNST-SRX ] 02 50 17.A3.7B 00.00.08 C3 11 00 LTONRR (00) Sat 02/01/2014 09:46:04 PM : [std-Group ] 17.A3.7B-->Group=8, Max Hops=3, Hops Left=0 Sat 02/01/2014 09:46:04 PM : [ 17 A3 7B 8] DON 0 Sat 02/01/2014 09:46:04 PM : [iNST-SRX ] 02 50 17.A3.7B 24.1B.FE 41 11 08 LTONRR (08) Sat 02/01/2014 09:46:04 PM : [std-Cleanup ] 17.A3.7B-->ISY/PLM Group=8, Max Hops=1, Hops Left=0 Sat 02/01/2014 09:46:04 PM : [iNST-DUP ] Previous message ignored. Sat 02/01/2014 09:46:04 PM : [ 17 A3 7B 8] ST 255 Sat 02/01/2014 09:46:04 PM : [iNST-TX-I1 ] 02 62 00 00 14 CF 13 00 Sat 02/01/2014 09:46:04 PM : [iNST-ACK ] 02 62 00.00.14 CF 13 00 06 LTOFFRR(00) Sat 02/01/2014 09:46:04 PM : [ F D4 91 1] ST 0 Sat 02/01/2014 09:46:04 PM : [ 18 58 D8 1] ST 0 Sat 02/01/2014 09:46:07 PM : [iNST-TX-I1 ] 02 62 18 58 D8 0F 13 00 Sat 02/01/2014 09:46:07 PM : [iNST-ACK ] 02 62 18.58.D8 0F 13 00 06 LTOFFRR(00) Sat 02/01/2014 09:46:08 PM : [VAR 2 56 ] 34 Sat 02/01/2014 09:46:08 PM : [iNST-SRX ] 02 50 18.58.D8 24.1B.FE 2B 13 00 LTOFFRR(00) Sat 02/01/2014 09:46:08 PM : [std-Direct Ack] 18.58.D8-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Sat 02/01/2014 09:46:08 PM : [ Time] 21:46:07 4(0) and 30 secs later: Sat 02/01/2014 09:46:34 PM : [iNST-TX-I1 ] 02 62 16 10 F6 0F 17 00 Sat 02/01/2014 09:46:34 PM : [iNST-ACK ] 02 62 16.10.F6 0F 17 00 06 LTMCON (DOWN) Sat 02/01/2014 09:46:34 PM : [VAR 2 68 ] 3 Sat 02/01/2014 09:46:34 PM : [iNST-SRX ] 02 50 16.10.F6 24.1B.FE 23 17 00 LTMCON (DOWN) Sat 02/01/2014 09:46:34 PM : [std-Direct Ack] 16.10.F6-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 There are no other entries for those devices in either the log or the event viewer between 9:46 PM and 3 AM, and the Front Light was not on when I got up this morning (and no program would have turned it off if something had turned it on so it would have been on when I got up.)
-
I'm finding the 3 AM "query all" regularly returns unexpected statuses that are either likely false or confirmed false. In researching this, I also uncovered a nasty little surprise. More on that in a minute. First, looking back over the past two nights, starting with last night / this morning, the following events were recorded at 3AM: Scene:My Lighting Status Query Fri 2014/01/31 03:00:03 AM Program Log Main Floor / Front Inside Light Status 0% Fri 2014/01/31 03:00:37 AM System Log Bedrooms / Master Bedroom Ceiling Light Status 100% Fri 2014/01/31 03:00:46 AM System Log This had a downstream effect because I have a program that calls a night lighting scene (a bedroom floor lamp to about 20%) after the bedroom ceiling light has been on for 1 hour. So shortly after 4AM the last 2 nights, our bedroom floor lamp has gone ON to 20%. The Front Inside Light being at 0% should not have been a surprise to ISY as that light had been turned off several hours earlier. Similarly, the Master Ceilling Light had been turned OFF long before, and I can confirm that it was OFF all night or it would have woken me up / kept me from sleeping. The OFF events of earlier in the night are shown as having been picked up by ISY in these log entries: Bedrooms / Master Bedroom Ceiling Light Status 0% Thu 2014/01/30 08:34:32 PM System Log Main Floor / Front Inside Light Fade Start 0 Thu 2014/01/30 08:36:36 PM Program Log Here's an excerpt from the error log around 3AM. Fri 2014/01/31 03:00:49 AM System -170001 [uDSockets] HTTP:20 error:6 Fri 2014/01/31 03:00:52 AM System -10 n/a Fri 2014/01/31 03:00:54 AM System -170001 [uDSockets] HTTP:20 error:6 Fri 2014/01/31 03:00:59 AM System -170001 [uDSockets] HTTP:20 error:6 Fri 2014/01/31 03:01:04 AM System -170001 [uDSockets] HTTP:20 error:6 Fri 2014/01/31 03:01:09 AM System -170001 [uDSockets] HTTP:20 error:6 Fri 2014/01/31 03:01:14 AM System -170001 [uDSockets] HTTP:20 error:6 Fri 2014/01/31 03:01:19 AM System -170001 [uDSockets] HTTP:20 error:6 I was not able to find error -170001 on the wiki but found that error -10 means "UNEXPECTED DEVICE RESPONSE ". Of course in response to the 3AM query that could have been about any of many devices. Similarly, this happened last night and I can confirm that neither of the lights reported as ON were ON. Scene:My Lighting Status Query Sat 2014/02/01 03:00:03 AM Program Log Bedrooms / Master Bedroom Ceiling Light Status 100% Sat 2014/02/01 03:00:45 AM System Log Bedrooms / Boys Bedrm Ceiling Light Status 26% Sat 2014/02/01 03:00:52 AM System Log Bedrooms / Master Bedroom Ceiling Light Status 0% Fri 2014/01/31 07:50:34 PM System Log Bedrooms / Boys Bedrm Ceiling Light Status 0% Fri 2014/01/31 07:50:50 PM System Log Error Log around 3AM: Sat 2014/02/01 03:00:10 AM System -10 n/a Below are more 3AM query all log entries. 1D.5B.9E is a v41 IOLinc, which very frequently responds to being queried (causing programs to run when they shouldn't or don't need to) - I believe this to be a flaw in this particular IO Linc. I have 2 v41 IOLincs and 9 v36 IO Lincs and only this one behaves this way. Front Inside Light is a frequent repeat offender Scene:My Lighting Status Query Fri 2014/01/17 03:00:00 AM Program Log 1D.5B.9E-Sensor Status 0% Fri 2014/01/17 03:00:24 AM System Log 1D.5B.9E-Relay Status 0% Fri 2014/01/17 03:00:25 AM System Log 1D.5B.9E-Sensor Status 100% Fri 2014/01/17 03:00:25 AM System Log Main Floor / Front Inside Light Status 0% Fri 2014/01/17 03:00:27 AM System Log Scene:My Lighting Status Query Sat 2014/01/18 03:00:00 AM Program Log 1D.5B.9E-Sensor Status 0% Sat 2014/01/18 03:00:25 AM System Log 1D.5B.9E-Relay Status 0% Sat 2014/01/18 03:00:25 AM System Log 1D.5B.9E-Sensor Status 100% Sat 2014/01/18 03:00:26 AM System Log Main Floor / Front Inside Light Status 0% Sat 2014/01/18 03:00:28 AM System Log Scene:My Lighting Status Query Sun 2014/01/19 03:00:01 AM Program Log 1D.5B.9E-Sensor Status 0% Sun 2014/01/19 03:00:25 AM System Log 1D.5B.9E-Sensor Status 100% Sun 2014/01/19 03:00:26 AM System Log I'll stop there but these kinds of unexpected (to me) responses are a daily occurrence in the life of this log file. Now to the nasty surprise I uncovered. Looking back at all my "query all's" I noticed this little gem that was not initiated by me: 0 null Sun 2014/01/19 04:41:45 PM System Start Scene:My Lighting Status Query Sun 2014/01/19 04:42:29 PM System Log this was followed by about 3 mins and 250 status reporting entries in the log (which is more than the ~170 nodes I have), followed by a second "query all" with more responses Scene:My Lighting Status Query Sun 2014/01/19 04:45:13 PM Program Log X10 G9 Status = On ( Sun 2014/01/19 04:45:14 PM System Log X10 Transceiver Module Outlet Status 100% Sun 2014/01/19 04:45:14 PM System Log 15 B9 70 2 Status 0% Sun 2014/01/19 04:45:24 PM System Log 1D.5B.9E-Relay Status 100% Sun 2014/01/19 04:45:49 PM System Log Wouldn't ISY already know this from the query all just before? Unfortunately my error log doesn't go that far back (I have been doing a lot of level 3 event viewing lately so the error log is full) Below is what was happening just before the crash. The "web" entries indicates I was doing some testing of my new EZIO8SA at the time. I suspect this ISY crash only looked like a GUI crash to me, which happens with some regularity. And because at over 700 programs, 200 variables and 172 nodes the GUI takes so long to load for me, I believe I didn't notice / clue in to the fact that ISY had crashed so didn't know until now that's what happened. 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status Query Sun 2014/01/19 04:35:47 PM Program Log Scene:1-MISC (Non Lighting) / HVAC / HVAC Sensors Status Query Sun 2014/01/19 04:35:53 PM Program Log 1-MISC (Non Lighting) / HVAC / Sensor - Heat Off - Office Da Status 100% Sun 2014/01/19 04:35:53 PM System Log 50405 Status Query Sun 2014/01/19 04:36:13 PM Program Log Main Floor / Laundry Room Motion-Sensor Status 100% Sun 2014/01/19 04:36:56 PM System Log Main Floor / Laundry Room Motion-Sensor Status 0% Sun 2014/01/19 04:37:32 PM System Log Z-Unused Relay Sensors / Relay for Fan OFF Sensor Off Sun 2014/01/19 04:38:00 PM Web Log Z-Unused Relay Sensors / Relay for Fan OFF Sensor Status 0% Sun 2014/01/19 04:38:03 PM System Log 1-MISC (Non Lighting) / HVAC / Office Damper-EZIO.4 Off Sun 2014/01/19 04:38:21 PM Web Log 1-MISC (Non Lighting) / HVAC / Office Damper-EZIO.4 Status 0% Sun 2014/01/19 04:38:25 PM System Log Z-Unused Relay Sensors / Relay for Fan OFF Sensor Status Query Sun 2014/01/19 04:38:35 PM Program Log Z-Dusk and Low Bat Sensors / Laundry Room Dusk-Dawn Status 0% Sun 2014/01/19 04:38:38 PM System Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 On 255 Sun 2014/01/19 04:38:55 PM Program Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Error 1 Sun 2014/01/19 04:38:59 PM System Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Sun 2014/01/19 04:38:59 PM System -2 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Error 0 Sun 2014/01/19 04:39:00 PM System Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status 100% Sun 2014/01/19 04:39:00 PM System Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status Query Sun 2014/01/19 04:39:25 PM Web Log 1-MISC (Non Lighting) / HVAC / Basement Dampers - EZIO8SA.1 Status 100% Sun 2014/01/19 04:39:26 PM System Log Bedrooms / Boys Bedroom Table Lamp Status Query Sun 2014/01/19 04:40:00 PM Program Log 0 null Sun 2014/01/19 04:41:45 PM System Start What's going on with the query all responses, and is there any clue in the above as to why ISY crashed?
-
but it's intermittent - in practice this would mean I need to run at level 3 for as much as a day (it usually happens at least once a day) and hope it happens sooner rather than later. Long ago I was told not to leave the event viewer at level 3 as the disk (and ISY performance?) gets hammered with data logging. is it overly simplistic to suggest ISY simply ignore duplicate message to a single query command? - By duplicate message I assume you don't mean the second distinct message that comes in (one for the outputs, one for the inputs), e.g. RINPUT (00) and RINPUT (30) in this sample query I just ran: Thu 01/30/2014 07:48:21 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 4F 02 Thu 01/30/2014 07:48:21 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 4F 02 06 IOCTL (QUERY) Thu 01/30/2014 07:48:21 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 4F 4A IOCTL (4A) Thu 01/30/2014 07:48:21 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 01/30/2014 07:48:22 PM : [ 28 AD BD 1] ST 0 Thu 01/30/2014 07:48:22 PM : [iNST-TX-I1 ] 02 62 28 AD BD 0F 49 00 Thu 01/30/2014 07:48:22 PM : [iNST-ACK ] 02 62 28.AD.BD 0F 49 00 06 RINPUT (00) Thu 01/30/2014 07:48:22 PM : [iNST-SRX ] 02 50 28.AD.BD 24.1B.FE 2B 49 30 RINPUT (30) Thu 01/30/2014 07:48:22 PM : [std-Direct Ack] 28.AD.BD-->ISY/PLM Group=0, Max Hops=3, Hops Left=2
-
Am intermittently seeing EZIO8SA devices being ON (or at least reporting ON) when they should be OFF. I first emailed Smartenit support and, in a fit of laziness, simply copied most of it and their reply here as the body of my post. (I left the comment he made to me about the EZX10RF as an FYI.) Note that I happen to know he has only just upgraded ISY to the current 4.1.2 version today - and replied to him my concern that he hadn't really had much of a chance to test this...
-
I just got an EZIO8SA to replace some IOLincs I use to control HVAC stuff. So far, it looks like this will be a good move but with a drawback being that I don't have a visual indicator that a relay is on at the EZIO (which is not anywhere near my ISY admin console). There also isn't a button to physically turn them on/off manually but that's less of an issue. Does anyone know if I would be able to connect a small LED between NO and C (the terminals I use) of each relay to give me a visual of the state the relay is in? I'm using some of the relays to run 24VAC to duct dampers and some to "jumper" a setting in my furnace (fan on, fan high speed), also 24VAC. Of course I would look for LEDs that can handle 24V and think they would flicker because of the AC but that wouldn't bother me. Just as long as it would a) work and not fry something. Any info or suggestions would be appreciated.
-
Thanks so much for the insight, LeeG. This will be so much more efficient than querying 8 IOLincs individually or as part of a scene given that each query of an IOLinc returns an individual response for both the relay and the sensor in the IO Linc (16 response messages instead of one). I wish I would have known about this product sooner and am so glad it's working out of the box.
-
I was querying nodes 2 and 3 for my testing. Querying node 1 DOES send a command out but I only got a response back for node 1. For the record I do have input 5 & 6 connected to Gnd and I double checked the packaging - the only cable was a blue network cable that plugs the PLM into the EZIO8SA.
-
I just bought an EZIO8SA and PLM combo to replace some IOLincs. I was able to link it to ISY and am able to turn relays on and off no problem but a query does not work. With the event viewer at level 3 there is NOTHING sent out when I do a query. I did find/read the post related to the ISY status not being updated at viewtopic.php?f=27&t=12405 but the query worked in that case. My problem is the opposite of that: the status works fine but the query doesn't. I downloaded the smartenit utility but there are no instructions in the download or online on how to connect the PLM so the utility can communicate with it. It means that for the moment I can't find anything out about the PLM around firmware version, etc. to do some of the troubleshooting steps suggested in the other post. FWIW, a smarthome forum post on this subject indicates I'm not the only one who's come across this and seems to indicate that I will need a special cable that did not come with the kit and that I don't have. I contacted support@smartenit.com about this but thought I would mention it here in case someone can help on this front. Any suggestions would be appreciated.
-
Would like to tentatively close on this. The problem has not re-occurred at this point and I suspect it won't because I reduced the workload demands I've been placing on ISY. It may yet re-occur but given the additional test programs I've been running to try to cause/observe another instance of the problem and the fact that no one else seems to have encountered the problem I'm thinking it won't happen again with this firmware generation. Briefly, I've been running 4.0.11 (an alpha release with more debug info being captured as I understand it) for well over a month. I also created 24 programs like the following one to run each hour: If Time is 1:00:00AM Then Send Notification to 'me' content 'Generic Main Log' Else - No Actions - (To add one, press 'Action') The notification sends an email and writes to a log using this feature viewtopic.php?f=25&t=10905. Writing to a log file resolved / worked around the issue of an email not making it out, which happened at least half a dozen times. (Thank you UDI for the log feature; it's been a helpful troubleshooting tool) For more info on my workload issues see viewtopic.php?f=27&t=11999#p92535. And the workaround that I suspect fixed the problem is in this post viewtopic.php?f=27&t=11999#p92637 I'll report back if something changes.