Author |
|
judetf Senior Member
Joined: January 23 2008
Online Status: Offline Posts: 234
|
Posted: October 10 2008 at 06:15 | IP Logged
|
|
|
I have a timed event to run a macro every morning. The 3 line macro uses 3 ph_insteon commands to turn on 3 different lights.
95% of the time everything works perfectly. Earlier this week, however, only 1 light turned on and then this morning none of the lights turned on.
The event log shows the macro executing, but no insteon Out events.
As soon as I manually ran the macro the events the lights all turned on (and the Event log showed things).
Since I _can't_ reproduce the problem at will and it only happens sporadically, I'm trying to figure out how to track/record what happens. Do I need to capture the insteon log all night long and wait for it not to work then scan through the log? Are there better ways to troubleshoot?
Thanks
jtf
|
Back to Top |
|
|
TonyNo Moderator Group
Joined: December 05 2001 Location: United States
Online Status: Offline Posts: 2889
|
Posted: October 10 2008 at 07:17 | IP Logged
|
|
|
This is something that I have been seeing and monitoring.
Capturing the Insteon log is what it will take. I see a few megs of log each day, so I have been deleting it when no issues have occurred.
|
Back to Top |
|
|
BeachBum Super User
Joined: April 11 2007 Location: United States
Online Status: Offline Posts: 1880
|
Posted: October 10 2008 at 09:02 | IP Logged
|
|
|
You might also try sending a User Message in the middle of the macro to insure the macro is actually running. I personally have not experienced this problem and I run many timed events.
__________________ Pete - X10 Oldie
|
Back to Top |
|
|
judetf Senior Member
Joined: January 23 2008
Online Status: Offline Posts: 234
|
Posted: October 10 2008 at 09:37 | IP Logged
|
|
|
Pete, given that the other morning one light out of three turned on, I would surmise that the macro did actually run (but that's just my interpretation of events).
TonyNo, given that you seem to have noticed the same thing, is there any chance that I can rest easy knowing that you are monitoring it and that someday Dave will "fix" something? Or should I start doing my own monitoring? I'm happy to do so, if extra data would be helpful, but I'd be hard pressed to actually look at the logs and understand anything relevant in there...
|
Back to Top |
|
|
BeachBum Super User
Joined: April 11 2007 Location: United States
Online Status: Offline Posts: 1880
|
Posted: October 10 2008 at 09:54 | IP Logged
|
|
|
That is true but did the macro complete. One would think so. Just trying to divide and conquer to isolate the problem. Tony may capture it for you as I haven’t seen it yet. The question is did the macro issue the Insteon command and PH failed to execute it or did the macro stop executing for some reason. And also why Timed Events only? The problem I have is if it fails I do error recovery that fixes it but only if the macro completed so therefore I might not catch it. Just my 2 cents worth….
__________________ Pete - X10 Oldie
|
Back to Top |
|
|
TonyNo Moderator Group
Joined: December 05 2001 Location: United States
Online Status: Offline Posts: 2889
|
Posted: October 10 2008 at 13:28 | IP Logged
|
|
|
Yes, as you describe the same exact symptoms, my catching it means you can just go about your business. ;)
|
Back to Top |
|
|
judetf Senior Member
Joined: January 23 2008
Online Status: Offline Posts: 234
|
Posted: October 11 2008 at 07:37 | IP Logged
|
|
|
Sweet, TonyNo is on the case! :)
I'm happy to be a testbed, if you need a second set of data.
Pete, I get it now. So can we talk about "error recovery?" Is that discussed in some other thread somewhere? I've thought a few times about building in something that, uh, checks to make sure what I wanted to have happen actually happened, whether on a timed event, macro or (more often an issue) a trigger. Are there straight-forward ways of doing error recovery globally, or is it just a matter of working out the logic for each event you want to check and checking it?
|
Back to Top |
|
|
BeachBum Super User
Joined: April 11 2007 Location: United States
Online Status: Offline Posts: 1880
|
Posted: October 11 2008 at 09:39 | IP Logged
|
|
|
It may need its own thread someday but for now probably not. My problem is I have a very noisy environment due to many track lighting transformers. Also I have a mix of X10 with Insteon. When I was pure X10 I developed a recovery system to handle it. With Insteon I set a global with the intended level and after a Trigger Insteon Device Change I go thought the global level settings with each Insteon device and check their status real time. This works for me and is transparent. If you want more detail I’d be glad to supply it.
Jeff runs a similar command with a different approach.
http://www.myx10.com/forum/forum_posts.asp?TID=1557&KW=inste on%5Fevent+jeffw
(Beware of blanks the forum inserts)
He doesn’t use globals and makes sure an Insteon device was set correctly at that instance. My problem with that approach is the timing. This can interrupt an execution sequence of a long macro. Other than that it seems to accomplish the same results and is much simpler to setup.
__________________ Pete - X10 Oldie
|
Back to Top |
|
|
TonyNo Moderator Group
Joined: December 05 2001 Location: United States
Online Status: Offline Posts: 2889
|
Posted: November 03 2008 at 17:30 | IP Logged
|
|
|
Whoo hoo! I finally have one in the logs!
Here is the PH log...
Code:
Nov 03 2008 06:15:40 Insteon In Incoming Insteon received on Insteon DM controller INSTEON-PLM. From Address:[01.86.1A] To Address:[0D.FB.AA] Flags:[39] Cmd1:[19] Cmd2:[0]. Decode: Direct ACK. From: WALK LIGHTS To: PLMCTLR1, Off
Nov 03 2008 06:15:40 Insteon Out Insteon DM Controller INSTEON-PLM transmission of Address:[01.86.1A] Flags:[15] Cmd1:[19] Cmd2:[0]. Decode: Direct. ID: WALK LIGHTS, Off
Nov 03 2008 06:15:38 Macro Macro PORCH LIGHT OFF executed.
Nov 03 2008 06:15:38 Execute Timed Event Timed Event PORCH OFF processed. |
|
|
That macro handles both the porch light and my walk lights. As you can see, there is nothing for the porch light. I'll post the corresponding Insteon log section tonight.
|
Back to Top |
|
|
BeachBum Super User
Joined: April 11 2007 Location: United States
Online Status: Offline Posts: 1880
|
Posted: November 03 2008 at 17:44 | IP Logged
|
|
|
My guess is the Insteon log is the same. Looks like the macro went south or prematurely terminated. Whatever sounds like Dave’s got work to do.
__________________ Pete - X10 Oldie
|
Back to Top |
|
|
TonyNo Moderator Group
Joined: December 05 2001 Location: United States
Online Status: Offline Posts: 2889
|
Posted: November 03 2008 at 19:32 | IP Logged
|
|
|
My macro is...
Code:
10 Insteon PORCH LIGHT OFF
20 Device Control INSTEON+WALK LIGHTS+OFF |
|
|
Porch Light: 03.82.08
Walk Lights: 01.86.1A
Here is the hunk after 06:15:38 until one of the addresses it sent...
Code:
2008-11-03 06:15:38.000 TX 02 62 03 82 08 05 2B 32
2008-11-03 06:15:38.015 RX SENTINSTEON=0D FB AA 03 82 08 05 2B 32 06
2008-11-03 06:15:38.281 RX RECEIVEINSTEONRAW=03 82 08 0D FB AA 21 2B FE
2008-11-03 06:15:38.343 TX 02 62 03 82 08 05 2B 21
2008-11-03 06:15:38.375 RX SENTINSTEON=0D FB AA 03 82 08 05 2B 21 06
2008-11-03 06:15:38.625 RX RECEIVEINSTEONRAW=03 82 08 0D FB AA 21 2B 1F
2008-11-03 06:15:38.671 TX 02 62 03 82 08 05 2B 30
2008-11-03 06:15:38.703 RX SENTINSTEON=0D FB AA 03 82 08 05 2B 30 06
2008-11-03 06:15:39.000 RX RECEIVEINSTEONRAW=03 82 08 0D FB AA 21 2B 20
2008-11-03 06:15:39.125 TX 02 62 03 82 08 0F 13 00
2008-11-03 06:15:39.140 TX 02 62 03 82 08 05 2B 31
2008-11-03 06:15:39.171 RX CTLR NAK=02 62 03 82 08 05 2B 31
2008-11-03 06:15:40.171 TX 02 62 03 82 08 05 2B 31
2008-11-03 06:15:40.203 RX SENTINSTEON=0D FB AA 03 82 08 05 2B 31 06
2008-11-03 06:15:40.453 RX RECEIVEINSTEONRAW=03 82 08 0D FB AA 21 2B 00
2008-11-03 06:15:40.500 TX 02 62 01 86 1A 0F 13 00
2008-11-03 06:15:40.562 RX SENTINSTEON=0D FB AA 01 86 1A 0F 13 00 06
2008-11-03 06:15:40.875 RX RECEIVEINSTEONRAW=01 86 1A 0D FB AA 27 13 00 |
|
|
|
Back to Top |
|
|
grif091 Super User
Joined: March 26 2008 Location: United States
Online Status: Offline Posts: 1357
|
Posted: November 03 2008 at 21:39 | IP Logged
|
|
|
PH is doing a series of Peek commands (0x2B) to the PORCH LIGHT device to read a portion of its memory. Unfortunately only the low order byte of the memory address is supplied with the Peek command. Prior to the earliest trace entry in your post should be a Set MSB (0x28) which sets the high order byte of the memory address to be read by subsequent Peeks. The Peek data coming back looks somewhat like link record data (0xFF, 0x1F) but the Peek addresses are not sequential so PH may well be reading configuration data from PORCH LIGHT. I can’t tell without knowing the value in the earlier 0x28 command cmd2 value. In the middle of the Peeks being sent to the device, the OFF command for PORCH LIGHT is sent to the PLM. Before the expected RX SENTINSTEON message that the OFF command had been sent on the powerline, another Peek command is issued by PH which is rejected by the PLM with a NAK and retried by PH. The coincidence of the OFF command to PORCH LIGHT followed close behind by another Peek seems to have confused the PLM and it never sent the OFF command to PORCH LIGHT on the powerline. Looks like PH did what was expected and the PLM did not. There have been issues with PLMs when hit with multiple commands close together. Dave will have to determine if this is a PLM failure. Other products have tried with only partial success to space the commands to the PLM as a work around to closely issued commands not being handled correctly by the PLM. I have seen a post that a later version of the PLM has fixed this issue but I have not seen any feed back to confirm this.
__________________ Lee G
|
Back to Top |
|
|
BeachBum Super User
Joined: April 11 2007 Location: United States
Online Status: Offline Posts: 1880
|
Posted: November 04 2008 at 09:39 | IP Logged
|
|
|
Lee, can I assume that Dave is sending the Peeks because of the Direct Command? And that the failure is intermit because of this. I’m not seeing the Peeks/Pokes in my logs but I don’t sent Direct Commands hence being the reason some of us are not experiencing the failure
__________________ Pete - X10 Oldie
|
Back to Top |
|
|
grif091 Super User
Joined: March 26 2008 Location: United States
Online Status: Offline Posts: 1357
|
Posted: November 04 2008 at 10:46 | IP Logged
|
|
|
The reading of PORCH LIGHT device memory using Peeks is not related to Direct commands. Peeks are used to read the link data base and configuration data. I was hoping to get a response as to why PH chose that moment in time to hit PORCH LIGHT with all those Peeks at the same time the Macro was triggered to turn off those two lights.
Just turned on Status Scan and got a similar sequence of Peeks as PH checked the status of each of my devices. Not use to seeing that sequence as I don't run with Status Scan on. I will have to look closer at the exact sequence of addresses used by those Peeks but I think PORCH LIGHT was being Status Scanned at the same time the Macro was triggered. From what I know about the PLM issue it would not have to be the PORCH LIGHT being Status Scanned, any device scan could do it. It is the coincidence of traffic to the PLM. The Status Scan is issuing messages in a controlled sequence. Now the Macro starts issuing messages essentially asynchronously to the message activity related to the Status Scan. There was only 15 milliseconds between the PORCH LIGHT OFF command and the next Peek that I think caused the problem. I could be all wet about this but it tracks with other problems I have seen with the PLM when hit with messages very close together.
__________________ Lee G
|
Back to Top |
|
|
BeachBum Super User
Joined: April 11 2007 Location: United States
Online Status: Offline Posts: 1880
|
Posted: November 04 2008 at 10:58 | IP Logged
|
|
|
This is very similar to a situation a saw with the PLM and X10 commands coming from the ControLinc. The timing got pretty close as I can remember in the low millisecond range and the PLM then started to lockup and sent back CTRL NAKs. This was supposed to be fixed but I captured it falling at firmware 63. I fixed it by removing the X10 addresses from the ControLinc.
__________________ Pete - X10 Oldie
|
Back to Top |
|
|
dhoward Admin Group
Joined: June 29 2001 Location: United States
Online Status: Offline Posts: 4447
|
Posted: November 04 2008 at 11:04 | IP Logged
|
|
|
Lee has the analysis spot on. The peeks are PH performing a Database scan. Of course this only happens if "Link Scan" is checked. Also, PowerHome would only attempt to scan a devices links if it were new or if it detected that the link database had changed (via "Status Scan" and the DB delta byte coming back different). If manual links arent being made and no additional link changes are made via PowerHome, then once scanned, PH would not usually scan again. It just happened to be coincidence that the PORCH LIGHT was being scanned when the macro attempted to turn on the very same device it was scanning. However as Lee points out, the problem would most likely still have occurred since the communication to the PLM was not in a controlled manner.
Which brings us to the real problem is that PowerHome attempted a direct control command in the middle of a background operation. PowerHome should have waited until that portion of the background operation completed before injecting a direct command into the mix. This caused the direct command to be lost and the peek operation to fail which PowerHome recovered from. Since the direct command was lost, it doesnt show up in the log.
I have been in the process of rewriting this particular part of the Insteon code to try and prevent this from happening. I just finished this portion last night and will begin extensive testing tonight. Hopefully all will go well and this error will be eliminated.
I'll let everyone know how the testing goes.
Dave.
|
Back to Top |
|
|
TonyNo Moderator Group
Joined: December 05 2001 Location: United States
Online Status: Offline Posts: 2889
|
Posted: November 04 2008 at 12:14 | IP Logged
|
|
|
Thanks Dave!
|
Back to Top |
|
|