MustangChris04 Posted April 4, 2015 Posted April 4, 2015 I have a program setup to turn a scene "on" if my fanlinc status is set to "off". The scene is designed to turn off a status led on a keypad so I know the fan is off when it is turned off. The program is working correctly. When I turn the fanlinc off, the program runs correctly and the "Fan Off" status light turns on. The issue is when the 3AM query hits, the scene is turned ON (even when the IF condition of this program is not met). I leave the fan on at night, and at 3AM the fan turns off. Here is the program below. The IF is set to my master bedroom fanlinc motor, and that condition is set to OFF. If that condition is met, then the "Master Fan Off" scene is run, which turns on the "Fan Off" led on the keypad. So if the fanlinc is ON, then it should not run the THEN portion because the condition was not met. Master Fan Off - [ID 0075][Parent 0001] If Status 'Master Bedroom / Master Bedroom Fanlinc - Ligh / Master Bedroom Fanlinc - Fan' is Off Then Set Scene 'Master Fan Off' On Else - No Actions - (To add one, press 'Action') When the fan is on, if I right click the program and click RUN IF, the fan does not turn off, which is correct because the status of the fan is not OFF, as defined in the IF. If I right click on the fanlinc and do a query while the fan is on, the program does not run, which is correct. If I do a query of the entire ISY then the program will run as soon as the query hits the fanlinc, which is not correct. The same with the 3AM query. As soon as it gets to the fanlinc, the program runs even though the fan was ON and the IF condition was NOT met. Im on v4.2.28 Any ideas?
LeeG Posted April 4, 2015 Posted April 4, 2015 Need to see an Event Trace at LEVEL 3 with the Fan On and the Program is invoked.
MustangChris04 Posted April 6, 2015 Author Posted April 6, 2015 Thanks LeeG. I tried to get the logs this morning but the fan didn't turn off at 3AM like it normally does! Quite strange, but I'll leave the logs running for next time it happens.
LeeG Posted April 6, 2015 Posted April 6, 2015 (edited) I suspect there is another variable in play. That is why the event trace is important. The event viewer is not meant to run 24/7. Would be a good idea to end trace and restart the Admin Console each evening. Edited April 6, 2015 by LeeG
MustangChris04 Posted May 28, 2015 Author Posted May 28, 2015 This morning at 3AM the fan randomly turned off again. It is not happening every night, only sometimes. Here is the log: http://screencast.com/t/uP6jOucWX The ID of the fan is the 23.10.66
MWareman Posted May 28, 2015 Posted May 28, 2015 What is state variable ID 8 used for in your programming?
MustangChris04 Posted May 28, 2015 Author Posted May 28, 2015 What is state variable ID 8 used for in your programming? That is for my alarm system heartbeat. Here is a screenshot of the heartbeat going back and forth: http://screencast.com/t/ojNlIAcK8
LeeG Posted May 28, 2015 Posted May 28, 2015 The Event Log running at LEVEL 1 is not very helpful (would be better at LEVEL 3 to show command that turned Fan Off). It shows the 3AM Query of FanLinc Light and Fan, the Fan was On at Med speed. Immediately after the Heartbeat variable was changed the Fan was turned Off. Look at the Heartbeat logic to see if the Fan can be turned Off or any other Program that can turn the Fan Off based on Heartbeat status.
LeeG Posted May 28, 2015 Posted May 28, 2015 I just realized that the Event Log has an entry showing Fan as being Off/turned Off before the 3AM Query of Light and Fan which shows the Fan as Med. Need to see LEVEL 3 trace to better understand what is actually happening. Post the LEVEL 3 event trace showing well before 3AM Query of FanLinc as well as after those query calls.
LeeG Posted May 28, 2015 Posted May 28, 2015 (edited) I've run my 3AM QueryAll Program several times without a problem but I keep my Insteon network running very well. I suspect you are seeing with the FanLinc what some users see with an I/O Linc which also has two nodes. The actual Query command response does not indicate which FanLinc node it applies to. Some users have seen a delay in the Query response of an I/O Linc node such that the next I/O Linc node is queried before the query response is received for the previous node. It allows the query response to the previous node to be applied to the next node (because node number is not contained in the response). This is speculation at this point since the LEVEL 1 trace does not show actual commands and response. I set the Light node to 100% On (FF) and Fan node to Med (BF). Below is what the trace of a FanLinc at LEVEL 3 should be. Thu 05/28/2015 02:49:19 PM : [iNST-TX-I1 ] 02 62 14 9E F5 0F 19 00 Thu 05/28/2015 02:49:19 PM : [iNST-ACK ] 02 62 14.9E.F5 0F 19 00 06 LTSREQ (LIGHT) Thu 05/28/2015 02:49:19 PM : [iNST-SRX ] 02 50 14.9E.F5 22.80.0B 2B 00 FF (FF) Thu 05/28/2015 02:49:19 PM : [std-Direct Ack] 14.9E.F5-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 05/28/2015 02:49:19 PM : [iNST-TX-I1 ] 02 62 14 9E F5 0F 19 03 Thu 05/28/2015 02:49:20 PM : [iNST-ACK ] 02 62 14.9E.F5 0F 19 03 06 LTSREQ (03) Thu 05/28/2015 02:49:20 PM : [iNST-SRX ] 02 50 14.9E.F5 22.80.0B 2B 19 BF LTSREQ (BF) Thu 05/28/2015 02:49:20 PM : [std-Direct Ack] 14.9E.F5-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 05/28/2015 02:49:20 PM : [iNST-TX-I1 ] 02 62 14 9E F5 0F 19 00 Thu 05/28/2015 02:49:20 PM : [iNST-ACK ] 02 62 14.9E.F5 0F 19 00 06 LTSREQ (LIGHT) Thu 05/28/2015 02:49:20 PM : [iNST-SRX ] 02 50 14.9E.F5 22.80.0B 2B 00 FF (FF) Thu 05/28/2015 02:49:20 PM : [std-Direct Ack] 14.9E.F5-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Thu 05/28/2015 02:49:20 PM : [iNST-TX-I1 ] 02 62 14 9E F5 0F 19 03 Thu 05/28/2015 02:49:21 PM : [iNST-ACK ] 02 62 14.9E.F5 0F 19 03 06 LTSREQ (03) Thu 05/28/2015 02:49:21 PM : [iNST-SRX ] 02 50 14.9E.F5 22.80.0B 2B 19 BF LTSREQ (BF) Thu 05/28/2015 02:49:21 PM : [std-Direct Ack] 14.9E.F5-->ISY/PLM Group=0, Max Hops=3, Hops Left=2 Edited May 28, 2015 by LeeG
LeeG Posted May 29, 2015 Posted May 29, 2015 I also noted that the Heartbeat is tripping every 9 seconds. That means the 3AM Query will be handling multiple variable updates during that Query sequence. Is it necessary to track the operation of the security system that frequently?
MustangChris04 Posted May 30, 2015 Author Posted May 30, 2015 Hi LeeG, Thank you for the thorough posts. I've set my logs to LEVEL 3. Hopefully within the next few days it occurs again. I checked each program and there is nothing for the heartbeat. You are correct about the heartbeat, it is not necessary to check so often, and I have no idea why I left it at the default 10 seconds. I just increased that time by 10 fold. Once this happens again I will post back with the Level 3 logs. Thanks!
MustangChris04 Posted June 6, 2015 Author Posted June 6, 2015 At around 3AM today the fan went off during the query. I was able to capture the log in verbose mode. I've attached the log as a text file. My fanlinc address is 23.10.66 I have 3 keypad Links that have the capability of controlling the fan, here are their addresses: Keypadlinc 1 address is 25.0D.F2 Keypadlinc 2 address is 1C.DE.35 Keypadlinc 3 address is 2F.BB.B6 In the logs, you will see at around 3:30 AM the fan was turned on. This is when I was starting to get hot and realized the fan was off, so I turned it back on. The ID of the program that turns ON the "fan off" scene is 0075. (The Fan Off scene will detect if the fan motor is off from the fanlinc. If the motor is off, then it turns the "Fan Off" scene to on, which will make sure the high/medium/low buttons on the keypad are off, and the the "off" button on the keypad is light up ( this is the 4 button fan keypad set). Thanks again for the help! Log.txt
stusviews Posted June 6, 2015 Posted June 6, 2015 I don't see the log. Does it show a state for each of the KPLs?
LeeG Posted June 6, 2015 Posted June 6, 2015 (edited) The Insteon network is generating extra Query response messages. The Query of the Light (which is Off) is generating an extra message that looks like the response to the following Fan Query. The Fan is set for Med speed but the duplicate Light Off response from Light makes it look like Fan is Off. Fri 06/05/2015 03:00:48 AM : [iNST-TX-I1 ] 02 62 23 10 66 0F 19 00 - Query of Light Fri 06/05/2015 03:00:48 AM : [iNST-ACK ] 02 62 23.10.66 0F 19 00 06 LTSREQ (LIGHT) Fri 06/05/2015 03:00:48 AM : [iNST-SRX ] 02 50 23.10.66 2B.95.60 27 00 00 (00) - Light Off response Fri 06/05/2015 03:00:48 AM : [std-Direct Ack] 23.10.66-->ISY/PLM Group=0, Max Hops=3, Hops Left=1 Fri 06/05/2015 03:00:48 AM : [iNST-TX-I1 ] 02 62 23 10 66 0F 19 03 - Query of Fan Fri 06/05/2015 03:00:48 AM : [iNST-ACK ] 02 62 23.10.66 0F 19 03 06 LTSREQ (03) Fri 06/05/2015 03:00:48 AM : [iNST-SRX ] 02 50 23.10.66 2B.95.60 23 00 00 (00) - duplicate Light Off response applied to Fan Query Fri 06/05/2015 03:00:48 AM : [std-Direct Ack] 23.10.66-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 Fri 06/05/2015 03:00:48 AM : [iNST-TX-I1 ] 02 62 23 10 66 0F 19 00 Fri 06/05/2015 03:00:49 AM : [iNST-SRX ] 02 50 23.10.66 2B.95.60 27 19 BF LTSREQ (BF) - actual Fan Med response Fri 06/05/2015 03:00:49 AM : [std-Direct Ack] 23.10.66-->ISY/PLM Group=0, Max Hops=3, Hops Left=1 Fri 06/05/2015 03:00:49 AM : [iNST-ACK ] 02 62 23.10.66 0F 19 00 06 LTSREQ (LIGHT) Fri 06/05/2015 03:00:49 AM : [iNST-SRX ] 02 50 23.10.66 2B.95.60 27 00 00 (00) Fri 06/05/2015 03:00:49 AM : [std-Direct Ack] 23.10.66-->ISY/PLM Group=0, Max Hops=3, Hops Left=1 This Fan Query worked as expected, showing Med speed Fri 06/05/2015 03:00:49 AM : [iNST-TX-I1 ] 02 62 23 10 66 0F 19 03 Fri 06/05/2015 03:00:49 AM : [iNST-ACK ] 02 62 23.10.66 0F 19 03 06 LTSREQ (03) Fri 06/05/2015 03:00:50 AM : [iNST-SRX ] 02 50 23.10.66 2B.95.60 27 19 BF LTSREQ (BF) Fri 06/05/2015 03:00:50 AM : [std-Direct Ack] 23.10.66-->ISY/PLM Group=0, Max Hops=3, Hops Left=1 Fri 06/05/2015 03:00:50 AM : [iNST-TX-I1 ] 02 62 26 4B 2D 0F 19 00 Fri 06/05/2015 03:00:50 AM : [iNST-ACK ] 02 62 26.4B.2D 0F 19 00 06 LTSREQ (LIGHT) This is duplicate Fan Query response Fri 06/05/2015 03:00:50 AM : [iNST-SRX ] 02 50 23.10.66 2B.95.60 23 19 BF LTSREQ (BF) Fri 06/05/2015 03:00:50 AM : [std-Direct Ack] 23.10.66-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 You can try an addition Range Extender near FanLinc and/or deal with the duplicate response messages in the Programming. Edited June 6, 2015 by LeeG
Jimbo.Automates Posted June 6, 2015 Posted June 6, 2015 Lee, if the ISY waited a little longer before querying the next node wouldn't that help reduce the chance of this issue? Sent from my Nexus 7 using Tapatalk
MustangChris04 Posted June 6, 2015 Author Posted June 6, 2015 Thanks Lee, I've got probably over 100 Insteon devices in the house, and all are dual band. There are about 8 dual band switches within 10 feet of the fanlinc in the same room. Do you still think a range extender would do anything? As far as programming to avoid this, do you mean creating a program that says if the fan is turned off between 3am and 3:01am, then turn it back on? I understand there is a duplicate response for the light, but shouldn't the ISY understand that this is for the light, and not the fan motor? As Jimbo mentioned, I think if the ISY slowed down the query rate, this would reduce the amount of overlapping traffic on the network and most likely avoid this issue. But even so, I still don't believe this issue should be occurring.
LeeG Posted June 6, 2015 Posted June 6, 2015 (edited) MustangChris04 The Range Extender was not much more than a guess. Unfortunately a Query response does not carry the node Group number so there is nothing in the Query response that allows knowing which node (Light or Fan) the response applies to. I know from experience that the 0xBF On Level applies to the Fan, along with not expecting to see the Light on at that level at 3AM. Evaluating two Query response messages separated by outbound messages is not the type of analysis the ISY could do to any given Query response by itself. This has to do with the PLM receiving multiple copies of the same message through different paths (with different Hops Left counts) and presenting both to the ISY as unique messages rather than understanding they are same message coming at different times. Fri 06/05/2015 03:00:48 AM : [iNST-SRX ] 02 50 23.10.66 2B.95.60 27 00 00 (00) - Light Off response Fri 06/05/2015 03:00:48 AM : [std-Direct Ack] 23.10.66-->ISY/PLM Group=0, Max Hops=3, Hops Left=1 Fri 06/05/2015 03:00:48 AM : [iNST-TX-I1 ] 02 62 23 10 66 0F 19 03 - Query of Fan Fri 06/05/2015 03:00:48 AM : [iNST-ACK ] 02 62 23.10.66 0F 19 03 06 LTSREQ (03) Fri 06/05/2015 03:00:48 AM : [iNST-SRX ] 02 50 23.10.66 2B.95.60 23 00 00 (00) - duplicate Light Off response applied to Fan Query Fri 06/05/2015 03:00:48 AM : [std-Direct Ack] 23.10.66-->ISY/PLM Group=0, Max Hops=3, Hops Left=0 It may be possible to avoid this network failure by slowing down Insteon traffic. I don't know and I'm very uncomfortable with the ISY getting into a practice of trying to compensate for every network problem that exists. Also note that these duplicate Query messages did NOT turn Off the Fan. Some Program logic decided to turn off Fan. Edited June 6, 2015 by LeeG
Recommended Posts