apostolakisl Posted September 29, 2011 Author Share Posted September 29, 2011 Below is a log of the status of a light that behaved wrong this morning. I don't know what the third line means where it says "on 63". Other than that, you can see that at 6:30 the light was turned on by the wakeup program. The next action on the light was to turn it off by me manually at 6:52:35. Then there is a program log with the 63 which I don't know what means, then the light turns on to 25% which it should not have done. Then I turned it off again and it stayed off. Alexis Room / Alexis BR/Overhead L Status 100% Thu 2011/09/29 06:30:00 AM System Log Alexis Room / Alexis BR/Overhead L Status 0% Thu 2011/09/29 06:52:35 AM System Log Alexis Room / Alexis BR/Overhead L On 63 Thu 2011/09/29 06:52:36 AM Program Log Alexis Room / Alexis BR/Overhead L Status 25% Thu 2011/09/29 06:52:37 AM System Log Alexis Room / Alexis BR/Overhead L Status 0% Thu 2011/09/29 06:52:42 AM System Log Link to comment
TJF1960 Posted September 29, 2011 Share Posted September 29, 2011 I am not sure what that means either but I hope someone can chime in to tell us. To test IndyMikes theory can you open the event viewer and run your tests to see if the ISY is detecting a 2nd off, when you get the time. Link to comment
Illusion Posted September 29, 2011 Share Posted September 29, 2011 I also have dozens of these programs running. Have for years. I have so little problems with them I have never given it a second thought. I have no recall of any failures. Link to comment
apostolakisl Posted September 29, 2011 Author Share Posted September 29, 2011 Here is the event viewer. Curiously, the times don't line up with the log. 1643bc is the light in question and the timing of events is not the same as in the log. Thu 9/29/2011 6:51:51 AM : [ 1 5 8 5 2 8 1 ] DON 0 Thu 9/29/2011 6:51:51 AM : [ 1 5 8 5 2 8 1 ] ST 255 Thu 9/29/2011 6:51:57 AM : [ 1 6 4 3 B C 1 ] BMAN 1 Thu 9/29/2011 6:51:59 AM : [ 1 6 4 3 B C 1 ] SMAN 0 Thu 9/29/2011 6:51:59 AM : [ 1 6 4 3 B C 1 ] ST 83 Thu 9/29/2011 6:52:27 AM : [MOD 2 2 1 5] 1000 Weather - Temperature Rate = 0.1 ï½° F/h Thu 9/29/2011 6:52:27 AM : [MOD 2 2 1 12] 20000 Weather - Wind Average Speed = 2 mph Thu 9/29/2011 6:52:27 AM : [MOD 2 2 1 22] 2235 Weather - Evapotranspiration = 0.2 235 inches/day Thu 9/29/2011 6:52:35 AM : [ 1 6 4 6 5 F 1 ] DOF 0 Thu 9/29/2011 6:52:40 AM : [ 1 6 4 6 5 F 1 ] DON 0 Thu 9/29/2011 6:52:40 AM : [ 1 6 4 6 5 F 1 ] ST 255 Thu 9/29/2011 6:52:48 AM : [ 1 6 4 6 5 F 1 ] DOF 0 Thu 9/29/2011 6:52:48 AM : [ 1 6 4 6 5 F 1 ] ST 0 Thu 9/29/2011 6:53:26 AM : [MOD 2 2 1 5] 2000 Weather - Temperature Rate = 0.2 ï½° F/h Thu 9/29/2011 6:53:26 AM : [MOD 2 2 1 13] 130000 Weather - Wind Direction = W Thu 9/29/2011 6:53:30 AM : [ 1 6 4 3 B C 1 ] DON 0 Thu 9/29/2011 6:53:30 AM : [ 1 6 4 3 B C 1 ] ST 137 Thu 9/29/2011 6:53:31 AM : [ 1 6 4 3 B C 1 ] DOF 0 Thu 9/29/2011 6:53:31 AM : [ 1 6 4 3 B C 1 ] ST 0 Link to comment
LeeG Posted September 29, 2011 Share Posted September 29, 2011 The following sequence is a press and hold of On paddle for manual ramp up. Device was ramped up to a level of 83 out of 255. Thu 9/29/2011 6:51:57 AM : [ 1 6 4 3 B C 1 ] BMAN 1 Thu 9/29/2011 6:51:59 AM : [ 1 6 4 3 B C 1 ] SMAN 0 Thu 9/29/2011 6:51:59 AM : [ 1 6 4 3 B C 1 ] ST 83 This looks like an On paddle tap with the result On level of 137 out of 256 Thu 9/29/2011 6:53:30 AM : [ 1 6 4 3 B C 1 ] DON 0 Thu 9/29/2011 6:53:30 AM : [ 1 6 4 3 B C 1 ] ST 137 This looks like an Off paddle tap with a result of 0 On Level Thu 9/29/2011 6:53:31 AM : [ 1 6 4 3 B C 1 ] DOF 0 Thu 9/29/2011 6:53:31 AM : [ 1 6 4 3 B C 1 ] ST 0 Without Device communications events being set in the Event Viewer it is impossible to know for certain the Insteon message flow. Link to comment
apostolakisl Posted September 29, 2011 Author Share Posted September 29, 2011 I don't think that is what actually happened. I know I did not do that, but my 6 year old daughter might have acted on the switch. I do know that when I got up to her room the light was on brightly as is exptected from the 6:30 program that turns it on as an alarm. I do know that around 6:50'ish I tapped the off and the light went from brightly on to off, then bounced up to 25% ish, then I immediately tapped off again and it shut off and stayed off. As far as event viewer. I need to start a session of the admin console, set the event viewer to level "device communication events" and then let it start collecting data. As I understand, it is not possible to change the viewer level after the fact and get that info, correct? Link to comment
LeeG Posted September 29, 2011 Share Posted September 29, 2011 Correct. Unlike HouseLinc2 that traces everything in the log file but only displays the specified level, the ISY traces only the level selected. There is no way to obtain the commands after the fact. Link to comment
apostolakisl Posted September 29, 2011 Author Share Posted September 29, 2011 Thanks Lee. I will start running sessions for logging. In the mean time. Thu 9/29/2011 6:29:36 AM : [ 1 6 4 3 B C 1 ] ST 255 Thu 9/29/2011 6:46:31 AM : [ 16 43 C 1 ] ST 255 Thu 9/29/2011 6:51:26 AM : [ 16 43 C 1 ] ST 0 Thu 9/29/2011 6:51:42 AM : [ 16 43 C 1 ] ST 255 Thu 9/29/2011 6:51:44 AM : [ 1 6 4 3 B C 1 ] DOF 0 Thu 9/29/2011 6:51:44 AM : [ 1 6 4 3 B C 1 ] ST 0 Thu 9/29/2011 6:51:44 AM : [ 1 6 4 3 B C 1 ] DOF 1 Thu 9/29/2011 6:51:45 AM : [ 1 6 4 3 B C 1 ] ST 63 Thu 9/29/2011 6:51:49 AM : [ 1 6 4 3 B C 1 ] DOF 0 Thu 9/29/2011 6:51:49 AM : [ 1 6 4 3 B C 1 ] ST 0 Thu 9/29/2011 6:51:57 AM : [ 1 6 4 3 B C 1 ] BMAN 1 Thu 9/29/2011 6:51:59 AM : [ 1 6 4 3 B C 1 ] SMAN 0 Thu 9/29/2011 6:51:59 AM : [ 1 6 4 3 B C 1 ] ST 83 Thu 9/29/2011 6:53:30 AM : [ 1 6 4 3 B C 1 ] DON 0 Thu 9/29/2011 6:53:30 AM : [ 1 6 4 3 B C 1 ] ST 137 Thu 9/29/2011 6:53:31 AM : [ 1 6 4 3 B C 1 ] DOF 0 Thu 9/29/2011 6:53:31 AM : [ 1 6 4 3 B C 1 ] ST 0 Thu 9/29/2011 6:56:37 AM : [ 16 43 C 1 ] ST 0 Thu 9/29/2011 7:11:33 AM : [ 16 43 C 1 ] ST 255 Thu 9/29/2011 7:22:05 AM : [ 16 43 C 1 ] ST 0 I sorted by the device and here is just this device's info for the entire morning. I am wondering if my daughter didn't actually push the button when I was in with my other daughter. But sometime in the 6:50'ish times I shut the light off, it bounced, and I shut it off again. But I am a bit confused. At 7:11 my daughters were both in the kitchen eating breakfast so how it is listed as 255 is a mystery to me. EDIT: Just noticed that perhaps that some of those are perhaps not the same device. I don't understand what device those codes are that are similar but different. I have no device 16:43:c1. For whatever reason ISY adds a 1 to the end of everything. The actual device in question is 16:43:bc MORE EDIT: It looks like 6:51:44 is when things went wrong. You can see that there is a device off, state 0, device off again (same time stamp), state 63, device off (third time), state 0. So it looks like there were device off commands received at 6:51:44 with the second one turning the light back on to 63 (25%). So, something caused a second signal. This might be what Indy Mike was talking about. Thu 9/29/2011 6:51:44 AM : [ 1 6 4 3 B C 1 ] DOF 0 (me pushing button) Thu 9/29/2011 6:51:44 AM : [ 1 6 4 3 B C 1 ] ST 0 (lihgt turned off) Thu 9/29/2011 6:51:44 AM : [ 1 6 4 3 B C 1 ] DOF 1 (bogus off command, ???what does the 1 mean after the dof, and for that matter what does the 0 mean the other times???) Thu 9/29/2011 6:51:45 AM : [ 1 6 4 3 B C 1 ] ST 63 (program ran and set to 25%) Thu 9/29/2011 6:51:49 AM : [ 1 6 4 3 B C 1 ] DOF 0 (me pushing button again) Thu 9/29/2011 6:51:49 AM : [ 1 6 4 3 B C 1 ] ST 0 Link to comment
apostolakisl Posted September 29, 2011 Author Share Posted September 29, 2011 Here is another example. This is my other daughter's bedroom and it looks like it did the same thing. I was not the one pushing the buttons. At 7:05:30 you see the second bogus dof (again with the 1 after it) which triggers the program and the light back onto 25%. Thu 9/29/2011 6:29:38 AM : [ 1 6 4 6 1 E 1 ] ST 255 Thu 9/29/2011 6:46:31 AM : [ 1 6 4 2 8 E 1 ] ST 255 Thu 9/29/2011 6:51:26 AM : [ 1 6 4 2 8 E 1 ] ST 0 Thu 9/29/2011 6:51:42 AM : [ 1 6 4 2 8 E 1 ] ST 255 Thu 9/29/2011 6:56:37 AM : [ 1 6 4 2 8 E 1 ] ST 0 Thu 9/29/2011 7:00:03 AM : [ 1 6 4 6 1 E 1 ] ST 0 Thu 9/29/2011 7:00:06 AM : [ 1 6 4 6 1 E 1 ] DON 0 Thu 9/29/2011 7:00:06 AM : [ 1 6 4 6 1 E 1 ] ST 155 Thu 9/29/2011 7:05:29 AM : [ 1 6 4 6 1 E 1 ] DOF 0 Thu 9/29/2011 7:05:29 AM : [ 1 6 4 6 1 E 1 ] ST 0 Thu 9/29/2011 7:05:30 AM : [ 1 6 4 6 1 E 1 ] DOF 1 Thu 9/29/2011 7:05:31 AM : [ 1 6 4 6 1 E 1 ] ST 63 Thu 9/29/2011 7:11:33 AM : [ 1 6 4 2 8 E 1 ] ST 255 Thu 9/29/2011 7:22:05 AM : [ 1 6 4 2 8 E 1 ] ST 0 Thu 9/29/2011 7:37:08 AM : [ 1 6 4 6 1 E 1 ] ST 0 Thu 9/29/2011 6:46:18 AM : [ 1 6 1 B D F 1 ] ST 255 Thu 9/29/2011 6:52:35 AM : [ 1 6 4 6 5 F 1 ] DOF 0 Thu 9/29/2011 6:52:40 AM : [ 1 6 4 6 5 F 1 ] DON 0 Thu 9/29/2011 6:52:40 AM : [ 1 6 4 6 5 F 1 ] ST 255 Thu 9/29/2011 6:52:48 AM : [ 1 6 4 6 5 F 1 ] DOF 0 Thu 9/29/2011 6:52:48 AM : [ 1 6 4 6 5 F 1 ] ST 0 Thu 9/29/2011 7:00:45 AM : [ 1 6 1 B D F 1 ] ST 0 Thu 9/29/2011 7:06:05 AM : [ 1 6 1 B D F 1 ] ST 255 Thu 9/29/2011 8:03:32 AM : [ 1 6 1 B D F 1 ] ST 0 Link to comment
LeeG Posted September 29, 2011 Share Posted September 29, 2011 When the paddle is pressed a Group Broadcast message is sent followed by a Group Cleanup Direct message. Without the actual detail I cannot be certain but I think the 0 in the first DOF 0 is the cmd2 field (red) from the Group Broadcast. The Group number in located in the To field (blue) of a Group Broadcast message. In my test shown below the Group Cleanup Direct message has the Group number 01 of the paddle in the cmd2 field (red). For devices such as KeypadLincs which can have up to 8 Group numbers, one for each button, the cmd2 field containing the Group number is the means of determining which KeypadLinc button was pressed. I think the ISY is logging a DOF 1 message when the Group Cleanup Direct message is received. The Group Cleanup Direct has Group 01 in the cmd2 field. An Event Trace containing the actual device messages will confirm. Thu 09/29/2011 03:09:44 PM : [iNST-SRX ] 02 50 16.3F.93 00.00.01 CB 13 00 LTOFFRR(00) Thu 09/29/2011 03:09:44 PM : [standard-Group][16.3F.93-->Group=1] Max Hops=3, Hops Left=2 Thu 09/29/2011 03:09:44 PM : [ 16 3F 93 1] DOF 0 Thu 09/29/2011 03:09:44 PM : [ 16 3F 93 1] ST 0 Thu 09/29/2011 03:09:44 PM : [iNST-SRX ] 02 50 16.3F.93 12.9F.E4 41 13 01 LTOFFRR(01) Thu 09/29/2011 03:09:44 PM : [standard-Cleanup][16.3F.93-->ISY/PLM Group=1] Max Hops=1, Hops Left=0 Note: the 1 after the device address reflects the node number. A SwitchLinc has one node. Link to comment
apostolakisl Posted September 29, 2011 Author Share Posted September 29, 2011 I will set the event viewer to pick up all the details and post them. But just looking at what I have right now there appears to be a dof signal being sent out that is boggus. The question is where did it come from and how to get rid of it. Link to comment
apostolakisl Posted September 29, 2011 Author Share Posted September 29, 2011 OK, here they are with all the extra detail. You can see the "DOF 1" in there a little over half way down which is the erroneous "off" signal that put the light to 25% unexpectedly. Thu 9/29/2011 4:51:29 PM : [ 16 43 BC 1] DON 0 Thu 9/29/2011 4:51:29 PM : [ 16 43 BC 1] ST 137 Thu 9/29/2011 4:51:30 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 42 11 01 LTONRR (01) Thu 9/29/2011 4:51:30 PM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hops=2, Hops Left=0 Thu 9/29/2011 4:51:31 PM : [iNST-SRX ] 02 50 16.43.BC 00.00.01 C7 13 00 LTOFFRR(00) Thu 9/29/2011 4:51:31 PM : [standard-Group][16.43.BC-->Group=1] Max Hops=3, Hops Left=1 Thu 9/29/2011 4:51:31 PM : [ 16 43 BC 1] DOF 0 Thu 9/29/2011 4:51:31 PM : [ 16 43 BC 1] ST 0 Thu 9/29/2011 4:51:31 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTOFFRR(01) Thu 9/29/2011 4:51:31 PM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hops=1, Hops Left=0 Thu 9/29/2011 4:51:31 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 47 13 01 LTOFFRR(01) Thu 9/29/2011 4:51:31 PM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hops=3, Hops Left=1 Thu 9/29/2011 4:51:31 PM : [ 16 43 BC 1] DOF 1 Thu 9/29/2011 4:51:32 PM : [iNST-ACK ] 02 62 16.43.BC 0F 11 3F 06 LTONRR (3F) Thu 9/29/2011 4:51:32 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 27 11 3F LTONRR (3F) Thu 9/29/2011 4:51:32 PM : [standard-Direct Ack][16.43.BC-->ISY/PLM Group=0] Max Hops=3, Hops Left=1 Thu 9/29/2011 4:51:32 PM : [ 16 43 BC 1] ST 63 Thu 9/29/2011 4:51:37 PM : [iNST-SRX ] 02 50 16.43.BC 00.00.01 C7 13 00 LTOFFRR(00) Thu 9/29/2011 4:51:37 PM : [standard-Group][16.43.BC-->Group=1] Max Hops=3, Hops Left=1 Thu 9/29/2011 4:51:37 PM : [ 16 43 BC 1] DOF 0 Thu 9/29/2011 4:51:37 PM : [ 16 43 BC 1] ST 0 Thu 9/29/2011 4:51:37 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTOFFRR(01) Thu 9/29/2011 4:51:37 PM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hops=1, Hops Left=0 Link to comment
LeeG Posted September 29, 2011 Share Posted September 29, 2011 There are two Group Cleanup Direct messages received from the SwitchLnc. They have different Max Hop counts indicating the SwitchLinc did not get an ACK to the first and retried. Since the PLM passed the first Group Cleanup Direct message to the ISY it indicates the PLM sent an ACK and the SwitchLinc failed to receive it. The SwitchLinc increased the Max Hop count and tried again. Thu 9/29/2011 4:51:31 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTOFFRR(01) Thu 9/29/2011 4:51:31 PM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hops=1, Hops Left=0 Thu 9/29/2011 4:51:31 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 47 13 01 LTOFFRR(01) Thu 9/29/2011 4:51:31 PM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hops=3, Hops Left=1 Thu 9/29/2011 4:51:31 PM : [ 16 43 BC 1] DOF 1 I think you said this is happening with multiple devices which indicates a powerline issue or perhaps a failing PLM. Are there some switches that work reliably with the two Off sequence? That would tend to eliminate the PLM as a candidate. Link to comment
apostolakisl Posted September 29, 2011 Author Share Posted September 29, 2011 Lee, thanks for the insight. I don't really know where to go from here. The ISY has a basically instant response to button presses of these devices as I watch the console or if I do querries. I don't know why the com would be so quick and error free from device to PLM to ISY but not from PLM to device. The problem barely existed prior to upgrading my firmware, so I don't know what to make of that. The PLM is 2 years old. The problem exists on every device that I have the program running on. I assume that means it actually exists on every device, it just doesn't cause a problem unless it has this program. And why does it list max hops as 1, 2, or 3 at different times? Does the max hop count mean that it quits repeating after 1, 2, or 3 hops? Why would it limit itself to 1 hop max ever? Link to comment
LeeG Posted September 30, 2011 Share Posted September 30, 2011 Devices start out with a Max Hop count of 1 as that provides the maximum powerline throughput. Has to do with the maximum time a Responder must wait before sending an ACK. If an ACK is not received the Group Cleanup Direct is reissued with a higher Max Hop count. The very old insteondetails document describes the Max Hop count being incremented by 1 as each retry is done. From this trace it looks like the Max Hop count went from 1 to 3. From the great work ELA is doing we know there are some differences between what the 2007 details document describes and the way things are working today with the latest devices. If powerline communication is otherwise solid it would appear to be a transient short duration situation. In a non automation world this sequence would not produce any adverse symptom. As ELA has found during his testing what appears to be a well working network can be working on the outer edge of reliability. When this is the case it does not take much to create a problem. Try running Scene Test against some of the Scenes. Look at the Max Hop count. If the Max Hop count is higher than 1 even if the test was successful indicates a retry was necessary. Link to comment
Hurting2Ride Posted September 30, 2011 Share Posted September 30, 2011 I went back and looked at your program. I believe that when I was attempting to do the same thing as you (pressing off while already off = a different action) that I ALSO was using the same logic in the IF commands as you, that being checking for both Status and Control. Status 'Master Bedroom / Master/Bath Cans L' is Off And Control 'Master Bedroom / Master/Bath Cans L' is switched Off Perhaps the ISY is looking at this and, depending on the timing of the communication and/or retries, sees this as 2 distinct OFF events which ends up triggering the program to turn back up to 25%? Link to comment
apostolakisl Posted September 30, 2011 Author Share Posted September 30, 2011 Lee, So we have established that the PLM/ISY has received the "off" signal, and sent an acknowledgement, but the switch didn't receive it so it sent a second "off" signal thinking the first didn't get through. So we know that at least some of the time, 1 hop isn't enough to get from PLM to Switch. How about the opposite, do we know how many hops it is taking from Switch to PLM? It obviously tries at least twice if it doesn't get an ack. Would it try more than twice? Would the "1" after "DOF" indicate that this is try number 2 and if there were a third try it would put a "2" there? I am trying to figure out if one hop is always enough to go from switch to PLM. If so, why isn't one hop enough to get back? This morning I had a heck of time with it. It took many tries to get it to stay off. Fri 9/30/2011 6:53:15 AM : [iNST-SRX ] 02 50 16.43.BC 00.00.01 C7 13 00 LTO FFRR(00) Fri 9/30/2011 6:53:15 AM : [standard-Group][16.43.BC-->Group=1] Max Hops=3, Hops Left=1 Fri 9/30/2011 6:53:15 AM : [ 16 43 BC 1] DOF 0 Fri 9/30/2011 6:53:15 AM : [ 16 43 BC 1] ST 0 Fri 9/30/2011 6:53:15 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:15 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=1, Hops Left=0 Fri 9/30/2011 6:53:16 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 42 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:16 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=2, Hops Left=0 Fri 9/30/2011 6:53:16 AM : [ 16 43 BC 1] DOF 1 Fri 9/30/2011 6:53:16 AM : [iNST-ACK ] 02 62 16.43.BC 0F 11 3F 06 LTO NRR (3F) Fri 9/30/2011 6:53:17 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 27 11 3F LTO NRR (3F) Fri 9/30/2011 6:53:17 AM : [standard-Direct Ack][16.43.BC-->ISY/PLM Group=0] Max Hops=3, Hops Left=1 Fri 9/30/2011 6:53:17 AM : [ 16 43 BC 1] ST 63 Fri 9/30/2011 6:53:20 AM : [iNST-SRX ] 02 50 16.43.BC 00.00.01 C7 13 00 LTO FFRR(00) Fri 9/30/2011 6:53:20 AM : [standard-Group][16.43.BC-->Group=1] Max Hops=3, Hops Left=1 Fri 9/30/2011 6:53:20 AM : [ 16 43 BC 1] DOF 0 Fri 9/30/2011 6:53:20 AM : [ 16 43 BC 1] ST 0 Fri 9/30/2011 6:53:21 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:21 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=1, Hops Left=0 Fri 9/30/2011 6:53:21 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 42 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:21 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=2, Hops Left=0 Fri 9/30/2011 6:53:21 AM : [ 16 43 BC 1] DOF 1 Fri 9/30/2011 6:53:21 AM : [iNST-ACK ] 02 62 16.43.BC 0F 11 3F 06 LTO NRR (3F) Fri 9/30/2011 6:53:22 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 27 11 3F LTO NRR (3F) Fri 9/30/2011 6:53:22 AM : [standard-Direct Ack][16.43.BC-->ISY/PLM Group=0] Max Hops=3, Hops Left=1 Fri 9/30/2011 6:53:22 AM : [ 16 43 BC 1] ST 63 Fri 9/30/2011 6:53:22 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 20 EE FE (FE) Fri 9/30/2011 6:53:22 AM : [standard-Direct Ack][16.43.BC-->ISY/PLM Group=0] Max Hops=0, Hops Left=0 Fri 9/30/2011 6:53:25 AM : [iNST-SRX ] 02 50 16.43.BC 00.00.01 C3 13 00 LTO FFRR(00) Fri 9/30/2011 6:53:25 AM : [standard-Group][16.43.BC-->Group=1] Max Hops=3, Hops Left=0 Fri 9/30/2011 6:53:25 AM : [ 16 43 BC 1] DOF 0 Fri 9/30/2011 6:53:25 AM : [ 16 43 BC 1] ST 0 Fri 9/30/2011 6:53:25 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:25 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=1, Hops Left=0 Fri 9/30/2011 6:53:25 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 42 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:25 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=2, Hops Left=0 Fri 9/30/2011 6:53:25 AM : [ 16 43 BC 1] DOF 1 Fri 9/30/2011 6:53:26 AM : [iNST-ACK ] 02 62 16.43.BC 0F 11 3F 06 LTO NRR (3F) Fri 9/30/2011 6:53:26 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 27 11 3F LTO NRR (3F) Fri 9/30/2011 6:53:26 AM : [standard-Direct Ack][16.43.BC-->ISY/PLM Group=0] Max Hops=3, Hops Left=1 Fri 9/30/2011 6:53:26 AM : [ 16 43 BC 1] ST 63 Fri 9/30/2011 6:53:30 AM : [iNST-SRX ] 02 50 16.43.BC 00.00.01 C3 13 00 LTO FFRR(00) Fri 9/30/2011 6:53:30 AM : [standard-Group][16.43.BC-->Group=1] Max Hops=3, Hops Left=0 Fri 9/30/2011 6:53:30 AM : [ 16 43 BC 1] DOF 0 Fri 9/30/2011 6:53:30 AM : [ 16 43 BC 1] ST 0 Fri 9/30/2011 6:53:30 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:30 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=1, Hops Left=0 Fri 9/30/2011 6:53:30 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 42 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:30 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=2, Hops Left=0 Fri 9/30/2011 6:53:30 AM : [ 16 43 BC 1] DOF 1 Fri 9/30/2011 6:53:30 AM : [iNST-ACK ] 02 62 16.43.BC 0F 11 3F 06 LTO NRR (3F) Fri 9/30/2011 6:53:31 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 27 11 3F LTO NRR (3F) Fri 9/30/2011 6:53:31 AM : [standard-Direct Ack][16.43.BC-->ISY/PLM Group=0] Max Hops=3, Hops Left=1 Fri 9/30/2011 6:53:31 AM : [ 16 43 BC 1] ST 63 Fri 9/30/2011 6:53:35 AM : [iNST-SRX ] 02 50 16.43.BC 00.00.01 C7 13 00 LTO FFRR(00) Fri 9/30/2011 6:53:35 AM : [standard-Group][16.43.BC-->Group=1] Max Hops=3, Hops Left=1 Fri 9/30/2011 6:53:35 AM : [ 16 43 BC 1] DOF 0 Fri 9/30/2011 6:53:35 AM : [ 16 43 BC 1] ST 0 Fri 9/30/2011 6:53:35 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:35 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=1, Hops Left=0 Link to comment
LeeG Posted September 30, 2011 Share Posted September 30, 2011 apostolakisl The cmd2 field of the Group Cleanup Direct message is the Group number of the particular Controller. For a SwitchLinc it is always 01. For devices such as an 8 button KeypadLinc the cmd2 field contains a value from 01-08 reflecting the Group number of the button pressed. Note the 01 in both the Group Cleanup Direct messages. The cmd2 field is the Group number, having nothing to do with Hop counts. The ISY does not normally display a DOF x message for the Group Cleanup Direct message as the initial Group Broadcast message is what the ISY reacted to and it is the message that generates DOF 0 message. Again the Group number in a Group Broadcast is located in the To address field. The second Group Cleanup Direct is reacted to by the ISY and generates the DOF 1 message because the message sequence appears to be another paddle press where the expected initial Group Broadcast message was not received. We know that is not the actual case in this scenario. Not receiving a Group Broadcast message happens which is why the Group protocol has a Group Cleanup Direct follow up message to insure each Responder reacts to the Group sequence. Thu 9/29/2011 4:51:31 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTOFFRR(01) Thu 9/29/2011 4:51:31 PM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hops=1, Hops Left=0 Thu 9/29/2011 4:51:31 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 47 13 01 LTOFFRR(01) Thu 9/29/2011 4:51:31 PM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hops=3, Hops Left=1 Thu 9/29/2011 4:51:31 PM : [ 16 43 BC 1] DOF 1 The Flag byte field containing the Max Hop count in the low order two bits contains the Hops Remaining in the next two bits. xxxx yy zz - xxxx describes the type of message, yy is Hops remaining and zz is Max Hops. Lee Link to comment
LeeG Posted September 30, 2011 Share Posted September 30, 2011 apostolakisl Looking over the Event Log in the last post the Max Hops is 2 which indicates the SwitchLinc is incrementing the Max Hop count by 1 for each retry. In the case below the 1st retry was successful. With the previous Event Log showing Max Hops 3 indicating additional retries the transient issue causing the problem is affecting more than a single message flow. Sometimes 1 retry works, other times multiple retries are necessary. Fri 9/30/2011 6:53:30 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 41 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:30 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=1, Hops Left=0 Fri 9/30/2011 6:53:30 AM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 42 13 01 LTO FFRR(01) Fri 9/30/2011 6:53:30 AM : [standard-Cleanup][16.43.BC-->ISY/PLM Group=1] Max Hop s=2, Hops Left=0 Fri 9/30/2011 6:53:30 AM : [ 16 43 BC 1] DOF 1 Lee Link to comment
apostolakisl Posted September 30, 2011 Author Share Posted September 30, 2011 Is there a single organized write-up on all the jargon contained in these event logs? I would really prefer to be able to interpret this stuff myself and all I can ever find are tidbits of info about how to interpret the language, never a comprehensive write-up. Link to comment
LeeG Posted September 30, 2011 Share Posted September 30, 2011 The insteondetails.pdf (from smartlabs web site) document covers the Insteon message format and content. It is an old document but the Insteon message structure has not changed from 2005. I don't think there is an ISY document that describes the ISY annotation. They are descriptors of the Insteon message itself so once the message is understood the annotation usually makes sense. Link to comment
Brian H Posted September 30, 2011 Share Posted September 30, 2011 http://www.insteon.net/pdf/insteondetails.pdf I will look and see if I can find any others that are not in the developers restricted area. Link to comment
IndyMike Posted September 30, 2011 Share Posted September 30, 2011 Hi Lou, As Lee indicated, the InsteonDetails guide gives you the formatting and bit structure of the messages transmitted over the powerline. The information displayed in the Event Viewer is actually Modem responses back to the ISY. The ISY tries to add descriptors of the information being received. The transmitted/received messages are preceded with codes like: "02 62": modem acknowledging a standard message from the ISY. ISY tags with the [iNST-ACK] "02 50": standard message received from a device. ISY tags with the [iNST-SRX] Thu 09/29/2011 08:24:14 PM : [iNST-ACK ] 02 62 0A.DB.0B 0F 2B 05 06 PEEK (05) Thu 09/29/2011 08:24:14 PM : [iNST-SRX ] 02 50 0A.DB.0B 13.22.F9 2B 2B 00 PEEK (00) Some of these codes are included in the modem developers guide: http://www.smarthome.com/manuals/2412sdevguide.pdf The Insteondetails paper defines the formatting of the remainder of the message. It does not give the actual command1 and command2 codes. Some of these are included in the Insteon command tables document: http://www.insteon.net/pdf/INSTEON_Command_Tables_20070925a.pdf From the example presented above, command1 is 0x2B which indicates that this is a peek operation - reading a device link table (tagged that way by the ISY). Command2 is 0x05 which is address that location that is being requested (again indicated by the ISY. Clear as mud, right? Unfortunately there is no single guide for this. You need to understand the protocol, modem commands, and device commands/responses as one package. Sorry but that's about the best I can do. I'm not proficient at reading this stuff either. Lee is - when he speaks, I listen and try to learn. I have learned from this thread. If Lee convened a course on the topic, I'd attend. IM Link to comment
apostolakisl Posted October 1, 2011 Author Share Posted October 1, 2011 Thanks IM, LeeG, etal, I did take a look at the tables in the Insteon pdf listed and gathered that ISY was substituting descriptions for some of the code. I am going to have to print everything out and start doodling on it if I have any chance of figuring it out. Obviously I am not looking at actual insteon traffic here but rather the ISY's interpretation of the stuff the PLM sends and receives. I am not sure how many hours I want to spend on it. It sure would be nice if the guys at UD who know this like the back of their hand created a nice cliff's notes version. Of course I don't want them to stop working on the Elk module to do it. Link to comment
LeeG Posted October 1, 2011 Share Posted October 1, 2011 Apostolakisl The knowledge I have has been acquired over many years of working with Insteon. Because SmartLabs considers the really “good†information confidential and proprietary it is a difficult subject to get ones arms around. Device features come and go with little warning or explanation. There is a Developer Subscription that can be purchased that gives access to some of the really “good†information but one has to sign an NDA to access that information. The data highlighted in blue are actual Insteon messages. The data in red are PLM commands. PLM messages in the 026x range are outbound messages, in the 025x range are inbound messages. The 06 on the end of the outbound message is the way the PLM ACKs a command/message sent from the ISY to the PLM over the serial interface. The data in blue is covered in the insteondetails.pdf document. There is much more information in that document than is needed to understand Insteon messages. Focus just on the Insteon message structures. Understand the last three bytes first (not counting the 06 ACK on outbound messages). They are Flags, cmd1 (Insteon command code) and cmd2 which varies by command and message type (first 4 bits of Flag).. Cmd2 can be tough because the “good†information is confidential. The basic Insteon message structure has not changed since day 1. Devices that were installed in 05/06 use the same basic messages being used today. Otherwise old and new devices could not interact with each other. It will be impossible for UDI to publish what you are looking for. They have access to confidential information which the NDA prevents them from sharing with the general public. Thu 9/29/2011 4:51:32 PM : [iNST-ACK ] 02 62 16.43.BC 0F 11 3F 06 LTONRR (3F) Thu 9/29/2011 4:51:32 PM : [iNST-SRX ] 02 50 16.43.BC 0F.D5.71 27 11 3F LTONRR (3F) Lee Link to comment
Recommended Posts
Archived
This topic is now archived and is closed to further replies.