X10 activating too many modules

[bkenobi]

I have an issue with HG turning on multiple modules that are not supposed to be actuated. The following log is supposed to show HG receiving O3 ON and then the Advanced Smart Lights code turning A8 ON.

2015-12-27 19:17:46.2853 Debug 5D-20-20-DF-08-F7 2015-12-27 19:17:46.2853 Debug RFCOM: 5D-20-20-DF-08-F7 2015-12-27 19:17:46.2868 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData 5D 20 20 DF 08 F7 2015-12-27 19:17:46.2895 Debug Command On HouseCode O UnitCode 3 2015-12-27 19:17:46.2912 Info HomeAutomation.X10 O3 - Status.Level 1 2015-12-27 19:17:46.4063 Debug 5D-20-20-DF-08-F7 2015-12-27 19:17:46.4063 Warn Ignoring repeated message within 500ms 2015-12-27 19:17:46.7184 Debug 5A-02-00-42 2015-12-27 19:17:46.7184 Debug PLCRX: 5A-02-00-42 2015-12-27 19:17:46.7197 Debug FNMAP: 00 2015-12-27 19:17:46.7202 Debug DATA : 42 2015-12-27 19:17:46.7280 Debug 0) Address = O3 2015-12-27 19:17:47.1186 Debug 5A-02-01-42 2015-12-27 19:17:47.1193 Debug PLCRX: 5A-02-01-42 2015-12-27 19:17:47.1193 Debug FNMAP: 01 2015-12-27 19:17:47.1203 Debug DATA : 42 2015-12-27 19:17:47.1203 Debug 0) House code = O 2015-12-27 19:17:47.1215 Debug 0) Command = On 2015-12-27 19:17:47.1226 Info HomeAutomation.X10 O3 - Status.Level 1 2015-12-27 19:17:47.1400 Debug 55 2015-12-27 19:17:47.1407 Debug 00 2015-12-27 19:17:47.4019 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData
2015-12-27 19:17:47.6200 Debug 04-6D 2015-12-27 19:17:47.7720 Debug 5A-02-00-42 2015-12-27 19:17:47.7731 Debug PLCRX: 5A-02-00-42 2015-12-27 19:17:47.7739 Debug FNMAP: 00 2015-12-27 19:17:47.7747 Debug DATA : 42 2015-12-27 19:17:47.7789 Debug 0) Address = O3 2015-12-27 19:17:47.9824 Debug 5A-02-01-42 2015-12-27 19:17:48.0339 Debug PLCRX: 5A-02-01-42 2015-12-27 19:17:48.0350 Debug FNMAP: 01 2015-12-27 19:17:48.0359 Debug DATA : 42 2015-12-27 19:17:48.0370 Debug 0) House code = O 2015-12-27 19:17:48.0381 Debug 0) Command = On 2015-12-27 19:17:48.0395 Info HomeAutomation.X10 O3 - Status.Level 1 2015-12-27 19:17:48.0469 Debug 55 2015-12-27 19:17:48.0481 Debug Command succesfull 2015-12-27 19:17:48.5349 Debug 06-62 2015-12-27 19:17:49.0077 Debug 55 2015-12-27 19:17:49.0088 Debug Command succesfull 2015-12-27 19:17:49.0105 Info HomeAutomation.X10 A8 - Status.Level 1 2015-12-27 19:17:49.0242 Debug 04-6D 2015-12-27 19:17:49.4476 Debug 55 2015-12-27 19:17:49.4492 Debug Command succesfull 2015-12-27 19:17:49.4504 Debug 06-62 2015-12-27 19:17:49.8906 Debug 55 2015-12-27 19:17:49.8913 Debug Command succesfull 2015-12-27 19:17:49.8939 Debug 04-6D 2015-12-27 19:17:50.3118 Debug 55 2015-12-27 19:17:50.3124 Debug Command succesfull 2015-12-27 19:17:50.3137 Debug 06-62 2015-12-27 19:17:50.7437 Debug 55 2015-12-27 19:17:50.7444 Debug Command succesfull

However, the actual result in my home was A8 as well as A2, A3, and A4 turning ON. When ASL turns off the lights 5 minutes later, only A8 turned OFF.

2015-12-27 19:26:00.3436 Debug 04-6D 2015-12-27 19:26:00.7677 Debug 55 2015-12-27 19:26:00.7694 Debug Command succesfull 2015-12-27 19:26:00.7715 Debug 06-63 2015-12-27 19:26:01.1998 Debug 55 2015-12-27 19:26:01.2015 Debug Command succesfull 2015-12-27 19:26:01.2048 Info HomeAutomation.X10 A8 - Status.Level 0

Any thoughts? I'll add an issue on github as well.

[bkenobi]

The funny thing is that HG doesn't show these modules turned on in the web interface. I can't confirm at the moment, but I'm wondering if HG is or isn't sending the right signals. I don't know why, but the only other option is that HG is sending the right command and all the modules are ignoring the fact that a command was sent and the next command should result in resetting the set of H/U codes paying attention.

[bkenobi]

I performed a few tests today and found that if I send the command with X10 controllers, I don't have an issue. This means that the modules are working correctly. I then sent the command to trigger the ASL code and things worked as expected. This means to me that when simple commands are sent in a clean environment, the code works as expected.

I don't know why I see issues some times and not others, but I can say that this issue has only been seen in the last couple months. I believe the only thing that has changed that could cause this would be the change to HG that makes X10 commands run asynchronously. I wonder if the following is possible:

Motion sensor sends RF ON command several times (O3, O ON) HG receives the first command and ASL determines a module should be turned on ASL sends A8 While ASL is sending an A8 command, HG is still receiving O3 or O ON so it is not sent immediately ASL sends A ON This command beats the A8 command out the door so the real command is actually A ON, A8

I haven't confirmed this as I have no easy way to record such an operation outside HG. I think the best I can do is set up a second instance of HG with my backup CM15A and simply record incoming commands on PLC to see what the modules are actually seeing.

[bkenobi]

I have trapped the issue and it looks like HG is sending a rogue command. I have 2 instances of HG running in order to see the issue. My main install is running on RPi and is labeled HG1. The second is running on WinXP and is labeled HG2. Both utilize a CM15A but HG2 does not have RF enabled so it only sees what HG1 is putting out via PLC.

In this case a motion sensor O3 sent via RF an ON command. HG1 received this and the ASL code correctly decided to turn on light A8. Prior to A8 turning on, I saw A6 turn on followed by A8. A6 was the last module that was turned off on house code A.

The critical info is (HG1.txt): 2016-02-02 17:57:54.0914 Debug 06-62 2016-02-02 17:57:54.5446 Debug 55 2016-02-02 17:57:54.5452 Debug Command succesfull 2016-02-02 17:57:54.5471 Info HomeAutomation.X10 A8 - Status.Level 1 2016-02-02 17:57:54.5600 Debug 04-6D 2016-02-02 17:57:54.9805 Debug 55 2016-02-02 17:57:54.9811 Debug Command succesfull 2016-02-02 17:57:54.9824 Debug 06-62 2016-02-02 17:57:55.4125 Debug 55 2016-02-02 17:57:55.4132 Debug Command succesfull 2016-02-02 17:57:55.4159 Debug 04-6D 2016-02-02 17:57:55.8365 Debug 55 2016-02-02 17:57:55.8372 Debug Command succesfull 2016-02-02 17:57:55.8388 Debug 06-62 2016-02-02 17:57:56.2686 Debug 55 2016-02-02 17:57:56.2693 Debug Command succesfull

This sends: A ON A8 A ON A8 A ON

Since A6 was turned OFF last, that initial A ON command turned that module back on prior to sending the address.

HG1.txt HG2.txt

[bkenobi]

Reviewing the data from the first log file (HG1.txt), I'm wondering if perhaps rather than sending the command out of order, if somehow HG forgot to send the first half of the command. Looking at the problem command, I see a bit of an odd sequence:

2016-02-02 17:57:53.6115 Debug 55 2016-02-02 17:57:53.6121 Debug Command succesfull 2016-02-02 17:57:54.0914 Debug 06-62 2016-02-02 17:57:54.5446 Debug 55 2016-02-02 17:57:54.5452 Debug Command succesfull

Every other command has something prior to the ACK statement (debug 55). In the case of the incorrect command above, it only has the ACK. Is it possible that the command to address the module got lost prior to sending? This is how every other command looks and it's correct:

2016-02-02 17:57:54.5600 Debug 04-6D 2016-02-02 17:57:54.9805 Debug 55 2016-02-02 17:57:54.9811 Debug Command succesfull 2016-02-02 17:57:54.9824 Debug 06-62 2016-02-02 17:57:55.4125 Debug 55 2016-02-02 17:57:55.4132 Debug Command succesfull

So It appears that one line was lost (04-6D).

[bkenobi]

I have a new instance unwanted lights turning on this evening. It appears to be the same issue where 04-6D (A ON) fired prior to HG sending a set of module commands (A8 in this case).

2016-02-26 20:07:37.9739 Debug 5D-20-20-DF-08-F7 2016-02-26 20:07:37.9752 Debug RFCOM: 5D-20-20-DF-08-F7 2016-02-26 20:07:37.9763 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData 5D 20 20 DF 08 F7 2016-02-26 20:07:38.0160 Debug Command On HouseCode O UnitCode 3 2016-02-26 20:07:38.0180 Info HomeAutomation.X10 O3 - Status.Level 1 2016-02-26 20:07:38.0699 Debug 5D-20-20-DF-08-F7 2016-02-26 20:07:38.0699 Warn Ignoring repeated message within 500ms 2016-02-26 20:07:38.4061 Debug 5A-02-00-42 2016-02-26 20:07:38.4068 Debug PLCRX: 5A-02-00-42 2016-02-26 20:07:38.4068 Debug FNMAP: 00 2016-02-26 20:07:38.4079 Debug DATA : 42 2016-02-26 20:07:38.4087 Debug 0) Address = O3 2016-02-26 20:07:38.8060 Debug 5A-02-01-42 2016-02-26 20:07:38.8060 Debug PLCRX: 5A-02-01-42 2016-02-26 20:07:38.8072 Debug FNMAP: 01 2016-02-26 20:07:38.8072 Debug DATA : 42 2016-02-26 20:07:38.8083 Debug 0) House code = O 2016-02-26 20:07:38.8089 Debug 0) Command = On 2016-02-26 20:07:38.8099 Info HomeAutomation.X10 O3 - Status.Level 1 2016-02-26 20:07:38.8190 Debug 55 2016-02-26 20:07:38.8190 Debug 00 2016-02-26 20:07:39.2712 Debug 5A-02-00-42 2016-02-26 20:07:39.3069 Debug 04-6D 2016-02-26 20:07:39.3193 Debug PLCRX: 5A-02-00-42 2016-02-26 20:07:39.3208 Debug FNMAP: 00 2016-02-26 20:07:39.3208 Debug DATA : 42 2016-02-26 20:07:39.3226 Debug 0) Address = O3 2016-02-26 20:07:39.5018 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData
2016-02-26 20:07:39.6702 Debug 5A-02-01-42 2016-02-26 20:07:39.6709 Debug PLCRX: 5A-02-01-42 2016-02-26 20:07:39.6709 Debug FNMAP: 01 2016-02-26 20:07:39.6721 Debug DATA : 42 2016-02-26 20:07:39.6727 Debug 0) House code = O 2016-02-26 20:07:39.6727 Debug 0) Command = On 2016-02-26 20:07:39.6781 Info HomeAutomation.X10 O3 - Status.Level 1 2016-02-26 20:07:39.6868 Debug 55 2016-02-26 20:07:39.6868 Debug Command succesfull 2016-02-26 20:07:40.1717 Debug 06-62 2016-02-26 20:07:40.5912 Debug 55 2016-02-26 20:07:40.5919 Debug Command succesfull 2016-02-26 20:07:40.5935 Info HomeAutomation.X10 A8 - Status.Level 1 2016-02-26 20:07:40.6071 Debug 04-6D 2016-02-26 20:07:41.0233 Debug 55 2016-02-26 20:07:41.0239 Debug Command succesfull 2016-02-26 20:07:41.0259 Debug 06-62 2016-02-26 20:07:41.4553 Debug 55 2016-02-26 20:07:41.4560 Debug Command succesfull 2016-02-26 20:07:41.4590 Debug 04-6D 2016-02-26 20:07:41.8793 Debug 55 2016-02-26 20:07:41.8803 Debug Command succesfull 2016-02-26 20:07:41.8826 Debug 06-62 2016-02-26 20:07:42.3114 Debug 55 2016-02-26 20:07:42.3120 Debug Command succesfull 2016-02-26 20:07:45.1037 Debug 5D-20-20-DF-08-F7 2016-02-26 20:07:45.1045 Debug RFCOM: 5D-20-20-DF-08-F7 2016-02-26 20:07:45.1053 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData 5D 20 20 DF 08 F7 2016-02-26 20:07:45.1088 Debug Command On HouseCode O UnitCode 3 2016-02-26 20:07:45.1104 Info HomeAutomation.X10 O3 - Status.Level 1 2016-02-26 20:07:45.2237 Debug 5D-20-20-DF-08-F7 2016-02-26 20:07:45.2237 Warn Ignoring repeated message within 500ms 2016-02-26 20:07:45.5376 Debug 5A-02-00-42 2016-02-26 20:07:45.5382 Debug PLCRX: 5A-02-00-42 2016-02-26 20:07:45.5389 Debug FNMAP: 00 2016-02-26 20:07:45.5389 Debug DATA : 42 2016-02-26 20:07:45.5402 Debug 0) Address = O3 2016-02-26 20:07:45.9358 Debug 5A-02-01-42 2016-02-26 20:07:45.9358 Debug PLCRX: 5A-02-01-42 2016-02-26 20:07:45.9370 Debug FNMAP: 01 2016-02-26 20:07:45.9370 Debug DATA : 42 2016-02-26 20:07:45.9382 Debug 0) House code = O 2016-02-26 20:07:45.9389 Debug 0) Command = On 2016-02-26 20:07:45.9399 Info HomeAutomation.X10 O3 - Status.Level 1 2016-02-26 20:07:45.9520 Debug 55 2016-02-26 20:07:45.9520 Debug 00 2016-02-26 20:07:46.1708 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData
2016-02-26 20:07:46.4009 Debug 5A-02-00-42 2016-02-26 20:07:46.4009 Debug PLCRX: 5A-02-00-42 2016-02-26 20:07:46.4021 Debug FNMAP: 00 2016-02-26 20:07:46.4021 Debug DATA : 42 2016-02-26 20:07:46.4036 Debug 0) Address = O3 2016-02-26 20:07:46.8010 Debug 5A-02-01-42 2016-02-26 20:07:46.8010 Debug PLCRX: 5A-02-01-42 2016-02-26 20:07:46.8022 Debug FNMAP: 01 2016-02-26 20:07:46.8027 Debug DATA : 42 2016-02-26 20:07:46.8039 Debug 0) House code = O 2016-02-26 20:07:46.8060 Debug 0) Command = On 2016-02-26 20:07:46.8084 Info HomeAutomation.X10 O3 - Status.Level 1 2016-02-26 20:07:46.8171 Debug 55 2016-02-26 20:07:46.8179 Debug 00 2016-02-26 20:07:47.3021 Debug 04-6D 2016-02-26 20:07:47.7220 Debug 55 2016-02-26 20:07:47.7228 Debug Command succesfull 2016-02-26 20:07:47.7238 Debug 06-62 2016-02-26 20:07:48.1540 Debug 55 2016-02-26 20:07:48.1553 Debug Command succesfull 2016-02-26 20:07:48.1580 Debug 04-6D 2016-02-26 20:07:48.5781 Debug 55 2016-02-26 20:07:48.5787 Debug Command succesfull 2016-02-26 20:07:48.5802 Debug 06-62 2016-02-26 20:07:49.0101 Debug 55 2016-02-26 20:07:49.0109 Debug Command succesfull 2016-02-26 20:07:49.0176 Debug 04-6D 2016-02-26 20:07:49.4342 Debug 55 2016-02-26 20:07:49.4355 Debug Command succesfull 2016-02-26 20:07:49.4372 Debug 06-62 2016-02-26 20:07:49.8662 Debug 55 2016-02-26 20:07:49.8668 Debug Command succesfull 2016-02-26 20:07:50.8023 Debug 5D-20-20-DF-08-F7 2016-02-26 20:07:50.8031 Debug RFCOM: 5D-20-20-DF-08-F7 2016-02-26 20:07:50.8040 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData 5D 20 20 DF 08 F7 2016-02-26 20:07:50.8069 Debug Command On HouseCode O UnitCode 3 2016-02-26 20:07:50.8088 Info HomeAutomation.X10 O3 - Status.Level 1 2016-02-26 20:07:50.8983 Debug 5D-20-20-DF-08-F7 2016-02-26 20:07:50.8991 Warn Ignoring repeated message within 500ms 2016-02-26 20:07:51.1997 Info HomeAutomation.HomeGenie.Automation 1017 - Program.UiRefresh Data updated 2016-02-26 20:07:51.2478 Debug 5A-02-00-42 2016-02-26 20:07:51.2571 Debug PLCRX: 5A-02-00-42 2016-02-26 20:07:51.2571 Debug FNMAP: 00 2016-02-26 20:07:51.2582 Debug DATA : 42 2016-02-26 20:07:51.2592 Debug 0) Address = O3 2016-02-26 20:07:51.6355 Debug 5A-02-01-42 2016-02-26 20:07:51.6362 Debug PLCRX: 5A-02-01-42 2016-02-26 20:07:51.6369 Debug FNMAP: 01 2016-02-26 20:07:51.6369 Debug DATA : 42 2016-02-26 20:07:51.6381 Debug 0) House code = O 2016-02-26 20:07:51.6388 Debug 0) Command = On 2016-02-26 20:07:51.6398 Info HomeAutomation.X10 A8 - Status.Level 1 2016-02-26 20:07:51.6495 Debug 55 2016-02-26 20:07:51.6501 Debug 00 2016-02-26 20:07:51.8593 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData
2016-02-26 20:07:51.8943 Debug Event propagation halted - parameter manipulated by automation program 'Advanced Smart Lights' (1016) (Name=Receiver.RawData, OldValue=5D 20 20 DF 08 F7, NewValue=) 2016-02-26 20:07:52.0998 Debug 5A-02-00-42 2016-02-26 20:07:52.0998 Debug PLCRX: 5A-02-00-42 2016-02-26 20:07:52.1010 Debug FNMAP: 00 2016-02-26 20:07:52.1010 Debug DATA : 42 2016-02-26 20:07:52.1025 Debug 0) Address = O3 2016-02-26 20:07:52.4997 Debug 5A-02-01-42 2016-02-26 20:07:52.5009 Debug PLCRX: 5A-02-01-42 2016-02-26 20:07:52.5019 Debug FNMAP: 01 2016-02-26 20:07:52.5019 Debug DATA : 42 2016-02-26 20:07:52.5044 Debug 0) House code = O 2016-02-26 20:07:52.5067 Debug 0) Command = On 2016-02-26 20:07:52.5094 Info HomeAutomation.X10 O3 - Status.Level 1 2016-02-26 20:07:52.5186 Debug 55 2016-02-26 20:07:52.5195 Debug 00 2016-02-26 20:07:53.0016 Debug 04-6D 2016-02-26 20:07:53.4717 Debug 55 2016-02-26 20:07:53.4723 Debug Command succesfull 2016-02-26 20:07:53.4742 Debug 06-62 2016-02-26 20:07:53.9037 Debug 55 2016-02-26 20:07:53.9045 Debug Command succesfull 2016-02-26 20:07:53.9113 Debug 04-6D 2016-02-26 20:07:54.3357 Debug 55 2016-02-26 20:07:54.3364 Debug Command succesfull 2016-02-26 20:07:54.3382 Debug 06-62 2016-02-26 20:07:54.7677 Debug 55 2016-02-26 20:07:54.7677 Debug Command succesfull

[bkenobi]

Another instance.

2016-03-04 22:39:44.4627 Debug 5D-20-20-DF-08-F7 2016-03-04 22:39:44.4636 Debug RFCOM: 5D-20-20-DF-08-F7 2016-03-04 22:39:44.4648 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData 5D 20 20 DF 08 F7 2016-03-04 22:39:44.4679 Debug Command On HouseCode O UnitCode 3 2016-03-04 22:39:44.4696 Info HomeAutomation.X10 O3 - Status.Level 1 2016-03-04 22:39:44.5856 Debug 5D-20-20-DF-08-F7 2016-03-04 22:39:44.5863 Warn Ignoring repeated message within 500ms 2016-03-04 22:39:44.8977 Debug 5A-02-00-42 2016-03-04 22:39:44.8977 Debug PLCRX: 5A-02-00-42 2016-03-04 22:39:44.8995 Debug FNMAP: 00 2016-03-04 22:39:44.9002 Debug DATA : 42 2016-03-04 22:39:44.9078 Debug 0) Address = O3 2016-03-04 22:39:45.2977 Debug 5A-02-01-42 2016-03-04 22:39:45.2977 Debug PLCRX: 5A-02-01-42 2016-03-04 22:39:45.3002 Debug FNMAP: 01 2016-03-04 22:39:45.3011 Debug DATA : 42 2016-03-04 22:39:45.3077 Debug 0) House code = O 2016-03-04 22:39:45.3088 Debug 0) Command = On 2016-03-04 22:39:45.3100 Info HomeAutomation.X10 O3 - Status.Level 1 2016-03-04 22:39:45.3198 Debug 55 2016-03-04 22:39:45.3206 Debug 00 2016-03-04 22:39:45.4678 Info HomeAutomation.X10 RF X10 RF Receiver Receiver.RawData
2016-03-04 22:39:45.7988 Debug 04-6D 2016-03-04 22:39:46.1261 Debug 5A-02-00-42 2016-03-04 22:39:46.1269 Debug PLCRX: 5A-02-00-42 2016-03-04 22:39:46.1278 Debug FNMAP: 00 2016-03-04 22:39:46.1278 Debug DATA : 42 2016-03-04 22:39:46.1319 Debug 0) Address = O3 2016-03-04 22:39:46.1618 Debug 5A-02-01-42 2016-03-04 22:39:46.1618 Debug PLCRX: 5A-02-01-42 2016-03-04 22:39:46.1632 Debug FNMAP: 01 2016-03-04 22:39:46.1637 Debug DATA : 42 2016-03-04 22:39:46.1637 Debug 0) House code = O 2016-03-04 22:39:46.1651 Debug 0) Command = On 2016-03-04 22:39:46.1660 Info HomeAutomation.X10 O3 - Status.Level 1 2016-03-04 22:39:46.1835 Debug 55 2016-03-04 22:39:46.1841 Debug Command succesfull 2016-03-04 22:39:46.6633 Debug 06-62 2016-03-04 22:39:47.1429 Debug 55 2016-03-04 22:39:47.1429 Debug Command succesfull 2016-03-04 22:39:47.1452 Info HomeAutomation.X10 A8 - Status.Level 1 2016-03-04 22:39:47.1517 Debug 04-6D 2016-03-04 22:39:47.5829 Debug 55 2016-03-04 22:39:47.5829 Debug Command succesfull 2016-03-04 22:39:47.5847 Debug 06-62 2016-03-04 22:39:48.0149 Debug 55 2016-03-04 22:39:48.0157 Debug Command succesfull 2016-03-04 22:39:48.0193 Debug 04-6D 2016-03-04 22:39:48.4390 Debug 55 2016-03-04 22:39:48.4396 Debug Command succesfull 2016-03-04 22:39:48.4410 Debug 06-62 2016-03-04 22:39:48.8710 Debug 55 2016-03-04 22:39:48.8717 Debug Command succesfull @

[bkenobi]

sorry, hit the wrong submit button.

[bkenobi]

FWIW, I have still seen this happen within the last couple weeks. It's rare, but it definitely happens. I'd rather have some attention to this issue, but I guess if I'm the only one seeing it, then it could be isolated?