C# breaks after use for unknown reason

[bkenobi]

I posted my Advanced Smart Lights code several months back.  I've noticed recently that after a variable amount of time (between a few hours and a few days) modules disappear from being listed as a smart light module (having the property "AdvSmartLights.Enabled" set as true).  I've been working to try to isolate the issue for several weeks without much success.  I believe that this was working in previous versions and has become broken over time.

Yesterday I decided to create a new set of HG modules not connected to any actual hardware so I could test things better without excessively triggering and damaging actual hardware (or annoying my wife).  I disabled all existing hardware from the code so I can truly see what's going on.  What I've found is that toggling a switch or sensor quickly will break the code.  I don't understand why this would happen, so I'm hoping I can get some help understanding this better.

This is the log that shows the issue:

Code: [Select]

20141209 21:14:48.8585840 ; sensor_mod ; test light ; test motion ; 1
20141209 21:14:48.8648480 ; sensor_mod ; test chime ; test motion ; 1
20141209 21:14:48.8685410 ; 14.5-test motion ; Status.Level ; 1
20141209 21:14:48.8814120 ; 15-test light ; Last event time ; 20141209 21:10:48.2921420
20141209 21:14:49.9019710 ; 16-test light ; ON
20141209 21:14:49.9089160 ; 15-test chime ; Last event time ; 20141208 20:51:09.6774880
20141209 21:14:49.9193030 ; 16.5-test chime ; Siren Type ; OFF
20141209 21:14:51.4337270 ; sensor_mod ; test light ; test motion ; 0
20141209 21:14:51.4398850 ; sensor_mod ; test chime ; test motion ; 0
20141209 21:14:51.4627960 ; 18.5-Start delay after OFF received
20141209 21:14:51.8663540 ; 17-test chime ; ON ; Delay time start ; 10
20141209 21:14:52.5365720 ; timer_mod ; test light ; timeout 10
20141209 21:14:52.5408570 ; timer_mod ; test chime ; timeout 10
20141209 21:14:52.5446920 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:14:52.5582430 ; timer_mod ; test light ; timeout 10
20141209 21:14:52.5621400 ; timer_mod ; test chime ; timeout 10
20141209 21:14:52.5659380 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:14:53.5885150 ; timer_mod ; test light ; timeout 10
20141209 21:14:53.5947750 ; timer_mod ; test chime ; timeout 10
20141209 21:14:53.5988620 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:14:53.6121990 ; timer_mod ; test light ; timeout 10
20141209 21:14:53.6164030 ; timer_mod ; test chime ; timeout 10
20141209 21:14:53.6203060 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:14:54.6435100 ; timer_mod ; test light ; timeout 10
20141209 21:14:54.6500000 ; timer_mod ; test chime ; timeout 10
20141209 21:14:54.6606660 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:14:54.7320290 ; timer_mod ; test light ; timeout 10
20141209 21:14:54.7364160 ; timer_mod ; test chime ; timeout 10
20141209 21:14:54.7404690 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:14:55.7622820 ; timer_mod ; test light ; timeout 10
20141209 21:14:55.7685290 ; timer_mod ; test chime ; timeout 10
20141209 21:14:55.7724160 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:14:55.7894960 ; timer_mod ; test light ; timeout 10
20141209 21:14:55.7933720 ; timer_mod ; test chime ; timeout 10
20141209 21:14:55.7974650 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:14:56.8366200 ; timer_mod ; test light ; timeout 10
20141209 21:14:56.8430390 ; timer_mod ; test chime ; timeout 10
20141209 21:14:56.8470040 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:14:56.8600520 ; timer_mod ; test light ; timeout 10
20141209 21:14:56.8641050 ; timer_mod ; test chime ; timeout 10
20141209 21:14:56.8680450 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:14:57.8897550 ; timer_mod ; test light ; timeout 10
20141209 21:14:57.8958750 ; timer_mod ; test chime ; timeout 10
20141209 21:14:57.8999000 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:14:57.9129240 ; timer_mod ; test light ; timeout 10
20141209 21:14:57.9168120 ; timer_mod ; test chime ; timeout 10
20141209 21:14:57.9207820 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:14:58.9429350 ; timer_mod ; test light ; timeout 10
20141209 21:14:58.9491690 ; timer_mod ; test chime ; timeout 10
20141209 21:14:58.9531470 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:14:58.9660790 ; timer_mod ; test light ; timeout 10
20141209 21:14:58.9700970 ; timer_mod ; test chime ; timeout 10
20141209 21:14:58.9741460 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:14:59.9959040 ; timer_mod ; test light ; timeout 10
20141209 21:15:00.0022340 ; timer_mod ; test chime ; timeout 10
20141209 21:15:00.0063570 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:15:00.0194530 ; timer_mod ; test light ; timeout 10
20141209 21:15:00.0235310 ; timer_mod ; test chime ; timeout 10
20141209 21:15:00.0285180 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:15:01.0513480 ; timer_mod ; test light ; timeout 10
20141209 21:15:01.0574690 ; timer_mod ; test chime ; timeout 10
20141209 21:15:01.0614360 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:15:01.0748940 ; timer_mod ; test light ; timeout 10
20141209 21:15:01.0789590 ; timer_mod ; test chime ; timeout 10
20141209 21:15:01.0830040 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:15:02.1053970 ; timer_mod ; test light ; timeout 10
20141209 21:15:02.1115360 ; timer_mod ; test chime ; timeout 10
20141209 21:15:02.1155030 ; 20-test light ; lasteventtime = 20141209 21:14:51.4627860
20141209 21:15:03.1363610 ; 21-test light ; timeout = 10 ; elapsed = 10.656531 ; timeout reached, turning OFF
20141209 21:15:03.1629000 ; timer_mod ; test light ; timeout 10
20141209 21:15:03.1671490 ; timer_mod ; test chime ; timeout 10
20141209 21:15:03.1711870 ; 20-test chime ; lasteventtime = 20141209 21:14:51.8660940
20141209 21:15:04.1780640 ; 21-test chime ; timeout = 10 ; elapsed = 11.308858 ; timeout reached, turning OFF
20141209 21:16:45.5873590 ; sensor_mod ; test light ; test motion ; 1
20141209 21:16:45.5943980 ; sensor_mod ; test chime ; test motion ; 1
20141209 21:16:45.5981870 ; 14.5-test motion ; Status.Level ; 1
20141209 21:16:45.6110870 ; 15-test light ; Last event time ; 20141209 21:15:03.1299710
20141209 21:16:46.6298420 ; 16-test light ; ON
20141209 21:16:46.6425290 ; 15-test chime ; Last event time ; 20141209 21:15:04.1766440
20141209 21:16:46.6471310 ; 16.5-test chime ; Siren Type ; OFF
20141209 21:16:48.5782120 ; 17-test chime ; ON ; Delay time start ; 10
20141209 21:16:48.9309890 ; timer_mod ; test light ; timeout 10
20141209 21:16:48.9353420 ; timer_mod ; test chime ; timeout 10
20141209 21:16:48.9394520 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:49.3956600 ; sensor_mod ; test light ; test motion ; 0
20141209 21:16:49.4100290 ; sensor_mod ; test chime ; test motion ; 0
20141209 21:16:49.4332340 ; 18.5-Start delay after OFF received
20141209 21:16:49.9927840 ; timer_mod ; test light ; timeout 10
20141209 21:16:49.9969680 ; timer_mod ; test chime ; timeout 10
20141209 21:16:50.0008280 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:16:50.0145450 ; timer_mod ; test light ; timeout 10
20141209 21:16:50.0185590 ; timer_mod ; test chime ; timeout 10
20141209 21:16:50.0224380 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:51.0447070 ; timer_mod ; test light ; timeout 10
20141209 21:16:51.0510080 ; timer_mod ; test chime ; timeout 10
20141209 21:16:51.0550750 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:16:51.0684860 ; timer_mod ; test light ; timeout 10
20141209 21:16:51.0723890 ; timer_mod ; test chime ; timeout 10
20141209 21:16:51.0764640 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:52.1352540 ; timer_mod ; test light ; timeout 10
20141209 21:16:52.1414250 ; timer_mod ; test chime ; timeout 10
20141209 21:16:52.1453150 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:16:52.1587600 ; timer_mod ; test light ; timeout 10
20141209 21:16:52.1626320 ; timer_mod ; test chime ; timeout 10
20141209 21:16:52.1666870 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:53.1885620 ; timer_mod ; test light ; timeout 10
20141209 21:16:53.1945400 ; timer_mod ; test chime ; timeout 10
20141209 21:16:53.1985560 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:16:53.2115520 ; timer_mod ; test light ; timeout 10
20141209 21:16:53.2154960 ; timer_mod ; test chime ; timeout 10
20141209 21:16:53.2195690 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:54.2413010 ; timer_mod ; test light ; timeout 10
20141209 21:16:54.2472730 ; timer_mod ; test chime ; timeout 10
20141209 21:16:54.2512900 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:16:54.2643080 ; timer_mod ; test light ; timeout 10
20141209 21:16:54.2692540 ; timer_mod ; test chime ; timeout 10
20141209 21:16:54.2731810 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:55.2953740 ; timer_mod ; test light ; timeout 10
20141209 21:16:55.3015040 ; timer_mod ; test chime ; timeout 10
20141209 21:16:55.3054280 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:16:55.3185700 ; timer_mod ; test light ; timeout 10
20141209 21:16:55.5923340 ; timer_mod ; test chime ; timeout 10
20141209 21:16:55.5964540 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:56.6206520 ; timer_mod ; test light ; timeout 10
20141209 21:16:56.6267910 ; timer_mod ; test chime ; timeout 10
20141209 21:16:56.6310230 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:16:56.6442250 ; timer_mod ; test light ; timeout 10
20141209 21:16:56.6482740 ; timer_mod ; test chime ; timeout 10
20141209 21:16:56.6522510 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:57.6743370 ; timer_mod ; test light ; timeout 10
20141209 21:16:57.6805100 ; timer_mod ; test chime ; timeout 10
20141209 21:16:57.6844930 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:16:57.6982510 ; timer_mod ; test light ; timeout 10
20141209 21:16:57.7022550 ; timer_mod ; test chime ; timeout 10
20141209 21:16:57.7063710 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:58.7309180 ; timer_mod ; test light ; timeout 10
20141209 21:16:58.7373770 ; timer_mod ; test chime ; timeout 10
20141209 21:16:58.7416740 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:16:58.7548060 ; timer_mod ; test light ; timeout 10
20141209 21:16:58.7587420 ; timer_mod ; test chime ; timeout 10
20141209 21:16:58.7627580 ; 20-test chime ; lasteventtime = 20141209 21:16:48.5781720
20141209 21:16:59.7868570 ; 21-test chime ; timeout = 10 ; elapsed = 10.188316 ; timeout reached, turning OFF
20141209 21:17:00.8460970 ; timer_mod ; test light ; timeout 10
20141209 21:17:00.8539930 ; timer_mod ; test chime ; timeout 10
20141209 21:17:00.8579080 ; 20-test light ; lasteventtime = 20141209 21:16:49.4332240
20141209 21:17:02.3367430 ; 21-test light ; timeout = 10 ; elapsed = 11.428492 ; timeout reached, turning OFF
20141209 21:19:45.2069350 ; 2-test switch ; Status.Level ; 1
20141209 21:19:47.1968320 ; 3-test light ; ON
20141209 21:20:08.6169090 ; 2-test switch ; Status.Level ; 0
20141209 21:20:09.6464250 ; 3.1-test light ; OFF
20141209 21:22:29.8910470 ; 2-test switch ; Status.Level ; 1
20141209 21:22:30.8718040 ; 2-test switch ; Status.Level ; 0
20141209 21:22:31.4626570 ; 3-test light ; ON
20141209 21:22:31.4693030 ; 12-test switch ; Consecutine OFF detected
20141209 21:22:32.5164410 ; 3.1-test light ; OFF
20141209 21:22:32.5227240 ; 12-test switch ; Consecutine OFF detected
20141209 21:22:32.5266940 ; 13-Double switch OFF
20141209 21:22:33.5283050 ; 14-test light ; OFF
20141209 21:22:48.8871860 ; sensor_mod ; test light ; test motion ; 1
20141209 21:22:48.8946750 ; 14.5-test motion ; Status.Level ; 1
20141209 21:22:48.9098390 ; 15-test light ; Last event time ; 20141209 21:22:33.5270070
20141209 21:22:49.9371360 ; 16-test light ; ON
20141209 21:22:51.7079040 ; sensor_mod ; test light ; test motion ; 0
20141209 21:22:51.7359180 ; 18.5-Start delay after OFF received
20141209 21:22:52.4131880 ; timer_mod ; test light ; timeout 10
20141209 21:22:52.4174990 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:22:53.4441950 ; timer_mod ; test light ; timeout 10
20141209 21:22:53.4504750 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:22:54.4771180 ; timer_mod ; test light ; timeout 10
20141209 21:22:54.4834580 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:22:55.5101960 ; timer_mod ; test light ; timeout 10
20141209 21:22:55.5163410 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:22:56.5428340 ; timer_mod ; test light ; timeout 10
20141209 21:22:56.5490510 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:22:57.6610300 ; timer_mod ; test light ; timeout 10
20141209 21:22:57.6713620 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:22:58.6984700 ; timer_mod ; test light ; timeout 10
20141209 21:22:58.7048620 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:22:59.7319430 ; timer_mod ; test light ; timeout 10
20141209 21:22:59.7382080 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:23:00.7651770 ; timer_mod ; test light ; timeout 10
20141209 21:23:00.7712780 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:23:01.7986140 ; timer_mod ; test light ; timeout 10
20141209 21:23:01.8047140 ; 20-test light ; lasteventtime = 20141209 21:22:51.7359070
20141209 21:23:03.7408210 ; 21-test light ; timeout = 10 ; elapsed = 10.072539 ; timeout reached, turning OFF
The thing to notice is that at the top of the code there are 2 modules listed when either "sensor_mod" or "timer_mod" fire.  At the end, there is only 1 module.  When the double switch is triggered at 20141209 21:22:32.5266940, the module "test chime" disappears.  I have scrubbed the code over and over but don't see what I've done wrong to cause this.

If anyone can see what's wrong, I would be extremely grateful!  Thanks!!!

[bkenobi]

I will try to break out the code so that I can recreate this error with the minimum/simplest code possible.  I'm hoping someone else can independantly verify that the code does or does not cause issues for someone else.  Testing requires no hardware, just 4 modules connected to no real hardware.  I am using X10, but the code is written such that it should work with any type of modules.

I understand if this sounds like a C# coding question, but it is really a question of whether something I'm doing in C# that should work is somehow not acceptable in HG for whatever reason.  This could be as simple as the Raspi isn't fast enough to run this code similar to nolio's issue with complex trigger code.

[bkenobi]

I've stripped the code down to it's bare bones where the code breaks.  It looks like there is an issue with the following line:

Code: [Select]

    smart_devices.WithParameter(SWITCH_NAME).Each((switch_mod)=>
I don't see anything wrong with the code.  But, when I include this line, I find that modules fall off my smart_devices list.  The following is the log I generated by triggering the motion sensor module on then off, turning the switch off, then the motion sensor on and off.

Code: [Select]

20141210 22:56:52.5521350 ; sensor_mod ; test light ; test motion ; 1
20141210 22:56:52.5585430 ; sensor_mod ; test chime ; test motion ; 1
20141210 22:56:55.1038890 ; sensor_mod ; test light ; test motion ; 0
20141210 22:56:55.1110030 ; sensor_mod ; test chime ; test motion ; 0

20141210 22:57:05.8383210 ; switch_mod ; test light ; test switch ; 0

20141210 22:57:14.5294100 ; sensor_mod ; test light ; test motion ; 1
20141210 22:57:17.1157490 ; sensor_mod ; test light ; test motion ; 0

As you can see, the second set of sensor_mod lines is missing the chime.

What is the difference between using "WithParameter" and "WithFeature"?  It seems like WithFeature must check the value in the parameter (checked true for example).  The documentation doesn't really help explain that.  Is WithFeature not compatible with WithParameter?

[bkenobi]

I have simplified the code even more and created a test script to test the test code.  I have found that when I use the following command, smart_devices gets redefined:

Code: [Select]

var SWITCH_NAME = "Adv_SmartLights.Switch";
var smart_devices = Modules.WithFeature(SMART_LIGHT_ENABLE);
    smart_devices.WithParameter(SWITCH_NAME).Each((switch_mod)=>
...
If I switch over to using an absolute reference instead of smart_devices things work:

Code: [Select]

var SWITCH_NAME = "Adv_SmartLights.Switch";
    Modules.WithFeature(SMART_LIGHT_ENABLE).WithParameter(SWITCH_NAME).Each((switch_mod)=>
I don't know why, but when I use the second set of code it appears to overwrite or simply corrupt smart_devices for some reason.  It would be much cleaner to use the second declaration, but unless this is a bug in HG, I'll switch over to the absolute reference approach.

At this point, this thread should be moved from HELP to BUG REPORTS.

[Gene]

Hi B,

I'm checking the code of ModulesHelper, but the two declarations should have the same effect unless you are then using some other selector in the Each code block that will so affect previous ModulesHelper selection.

Cheers,
g.

[bkenobi]

I was expecting the each statement to only affect what was inside that loop.  At least from my testing, it appears that somehow the smart_devices variable is being redefine somehow.  I don't know how to debug any deeper than at the HG C# level.  This would probably be easier to figure out from the HG executable/debugging level.  Unfortunately, I never had any success compiling the executable and I'm not sure where in the code this would be located (somewhere in the ModulesHelper code as you said).

What I can say is that after modifying my full Advance Smart Lights script with the absolute reference

Code: [Select]

Modules.WithFeature(SMART_LIGHT_ENABLE).WithParameter(SWITCH_NAME).Each((switch_mod)=>instead of

Code: [Select]

smart_devices.WithParameter(SWITCH_NAME).Each((switch_mod)=>the code doesn't lose modules any more.