TESTING RELEASE

[Gene]

All right, so I'm modifying XTenLib so that every time a new address is sent it will reset the previously stored values.
I'll update the attacched dll when done.
In the meantime if you are available right now, you can already test the currently attacched dll.

g.

[bkenobi]

I can do a very quick test now and more thorough tonight.

[bkenobi]

I was able to run my test script against the old and new dll configurations.  Both versions seem to work equally reliable, so that's good.  I didn't have the time to use output from HG in order to report accurate times so I went with my trust stop watch.  I ran my test code against both and there was a difference in response time.  The old dll ran my test in 2.1-2.2 seconds (same as before).  The new dll appeared much faster and seemed to be able to toggle the lights in closer to 1.6 seconds.  I only tried this 5-10 times with each config, but it seemed pretty consistently faster.

If there is a way for you to add a time stamp for the X10 debug block that shows the start and end time of the block (or a timestamp on each output line) I could give much more accurate results including the time to process X10.  I have something similar for the older dll, so this could be useful info.

So far, this looks really good.  Nice work!   

[Gene]

Hi Ben,

thanks for your test and time =)
I'm attacching the latest XTenLib with timestamps.

I have to say few things about X10 when sending a sequence of commands from two different controllers:

1) often commands won't reach the destination and there's no way to aknowledge about it
2) the two interfaces will get desync and current addressed units could be different each other

Also using RF as primary source for triggering is not reliable. An example follow.

HG with CM15Pro
1) received RF signal "5D 20 70 8F 58 A7" from MS13E that is set as a trigger for HG "Smart Light"
2) HG "Smart Light" turn B7 ON
3) HG "X10 100% Brighten When turned On" set B7 light to 100%
4) HG "Energy Saving Mode" dim B7 light to 40%
5) somewhere in between these the RF signal is sent over PLC by CM15 as B8 ON (that is the unit associated with the motion sensor)

The other HG box receiption with CM11 over PLC of all the above is not consistent and receives either one of the following:
1) B7 ON BRIGHT DIM B8 ON (that is correct)
2) B7 ON BRIGHT B8 ON DIM (that is bad)
3) B7 ON BRIGHT B8 ON (that is lossy)

Everything works as it should if I set the source of the Smart Light trigger to be B8 ON instead of the RF signal itself.

So, about X10 RF my conclusion is that if the RF signal is also being sent over PLC, it's better to relay on the unit associated to it.

Cheers,
g.

[bkenobi]

I think this would be the same issue with X10 that anyone would see if they were using more than one controller at the same time.  I have multiple motion sensors that use RF and one that is PLC.  If it is a very windy day, I have seen where I have hundreds or thousands of motion triggers by these devices.  If I were to run a macro in AHP during a time that these motion sensors were to send, things could go bad as you describe.  The one advantage you have with HG is that it is a smart controller.  Since you know this *could* happen, you have the ability to potentially try to minimize the impact.  People using a RR501 or TM751 (for example) would just have to deal with it by repeating commands manually.

In some cases these controllers actually can ten quite rude (TM751 is a big offender).  If an RF command is sent to this transceiver it simply dumps the command to PLC immediately.  If another command is in progress, they collide and neither work.  The RR501 is polite and will check for PLC activity before sending a command.  But, if a command is actually a sequence (like smart light control), it won't know to wait for the end of the sequence.

I guess it would be nice if there was a way in the CM15 to lock RF from tranceiving until the sequence was complete, but I doubt that can be done.

[bkenobi]

I've done some testing with the new X10 dll.  So far, things look bad unfortunately.  What I've found so far:

• Commands take a long time to execute
• My test code doesn't execute at all
• The wrong commands may be sent

1) The following is an example of turning on a light in the web interface by selecting toggle or ON buttons:

Code: [Select]

2014-04-23T20:51:23.5422280-07:00 HomeAutomation.X10 A6 - Status.Level 0
2014-04-23T20:51:27.0535810-07:00 MIG.Gateways.WebServiceGateway 192.168.0.100 api/HomeAutomation.HomeGenie/Logging/RealTime.EventStream/ HTTP GET
2014-04-23T20:51:28.3538690-07:00 MIG.Gateways.WebServiceGateway 192.168.0.5 api/HomeAutomation.HomeGenie/Config/Interfaces.List/1398311522266 HTTP GET
2014-04-23T20:51:28.4992150-07:00 MIG.Gateways.WebServiceGateway 192.168.0.100 api/HomeAutomation.HomeGenie/Config/Interfaces.List/1398311535575 HTTP GET
[20:51:28.627269] X10 < 06 63
[20:51:29.906193] X10 > 55
This shows that the command A6 ON is sent after nearly 5 seconds.  Some times I found it respond very quickly, but many times it was very slow.


2) I ran my test code in 2 ways.  Attempt 1 was using the light switch to send an X10 command "B6 ON" which should trigger HG to send "A6 ON".  I found that sometimes it works, but other times it doesn't send the "A6 ON" command.  The following was a success:

Code: [Select]

[21:02:05.336049] X10 > 5A 02 00 E9
[21:02:05.339821] X10 > PLCRX: 5A 02 00 E9
[21:02:05.342002] X10 > FNMAP: 00
[21:02:05.344239] X10 >  DATA: E9
[21:02:05.346606] X10 >       0) House code = B
[21:02:05.348882] X10 >       0)  Unit code = 6
[21:02:05.518999] X10 > 5C 00 1D
[21:02:05.712840] X10 > 5A 02 01 E2
[21:02:05.715674] X10 > PLCRX: 5A 02 01 E2
[21:02:05.717753] X10 > FNMAP: 01
[21:02:05.719999] X10 >  DATA: E2
[21:02:05.722258] X10 >       0) House code = B
[21:02:05.724444] X10 >       0)    Command = ON
2014-04-23T21:02:05.7315590-07:00 HomeAutomation.X10 B6 - Status.Level 1
2014-04-23T21:02:05.7411470-07:00 HomeAutomation.X10 A6 - Status.Level 1
[21:02:05.838967] X10 < 04 69
[21:02:06.913538] X10 > 55
[21:02:06.920679] X10 < 06 62
[21:02:07.347125] X10 > 5C 00 1D
In this case, the total time for execution was 2.011 seconds plus whatever transmission takes (minimal in this case).  A second case where it was super slow:

Code: [Select]

[21:07:49.816736] X10 > 5A 02 00 E9
[21:07:49.820036] X10 > PLCRX: 5A 02 00 E9
[21:07:49.823022] X10 > FNMAP: 00
[21:07:49.825751] X10 >  DATA: E9
[21:07:49.828297] X10 >       0) House code = B
[21:07:49.830415] X10 >       0)  Unit code = 6
[21:07:50.055838] X10 > 5C 00 1D
[21:07:50.249933] X10 > 5A 02 01 E3
[21:07:50.252976] X10 > PLCRX: 5A 02 01 E3
[21:07:50.255945] X10 > FNMAP: 01
[21:07:50.258716] X10 >  DATA: E3
[21:07:50.261167] X10 >       0) House code = B
[21:07:50.263242] X10 >       0)    Command = OFF
2014-04-23T21:07:50.2660500-07:00 HomeAutomation.X10 B6 - Status.Level 0
2014-04-23T21:07:50.2751540-07:00 HomeAutomation.X10 A6 - Status.Level 0
2014-04-23T21:07:51.4034150-07:00 MIG.Gateways.WebServiceGateway 192.168.0.100 api/HomeAutomation.HomeGenie/Config/Interfaces.List/1398312518351 HTTP GET
2014-04-23T21:07:52.4117290-07:00 MIG.Gateways.WebServiceGateway 192.168.0.100 api/HomeAutomation.HomeGenie/Logging/RealTime.EventStream/ HTTP GET
[21:07:55.331273] X10 < 06 63
[21:07:55.746802] X10 > 55
2014-04-23T21:07:58.4575890-07:00 MIG.Gateways.WebServiceGateway 192.168.0.100 api/HomeAutomation.HomeGenie/Config/Interfaces.List/1398312525575 HTTP GET
2014-04-23T21:07:58.7834590-07:00 HomeAutomation.HomeGenie.Automation 35 Automation Program Program.Status Running
2014-04-23T21:07:58.7997080-07:00 HomeAutomation.HomeGenie.Automation 35 Automation Program Program.Status Idle
2014-04-23T21:07:59.6727100-07:00 MIG.Gateways.WebServiceGateway 192.168.0.100 api/HomeAutomation.HomeGenie/Config/Modules.Get/HomeAutomation.HomeGenie.Automation/35/1398312526775 HTTP POST
2014-04-23T21:07:59.6828790-07:00 MIG.Gateways.WebServiceGateway 192.168.0.100 api/HomeAutomation.HomeGenie/Config/Modules.Get/HomeAutomation.HomeGenie.Automation/35/1398312526782 HTTP POST
[21:07:59.703400] X10 > 5C 00 18

Total transmission time from B6 OFF to A6 OFF was 9.886 seconds.  I had a couple times where nothing happened at all. 

3) I have a signal monitor that tells me what's going on with PLC, noise, signal strength, etc.  In the cases where the lights don't work as expected, I'm seeing:

B6 ON
Axx ON

When I viewed commands with the older X10 dll, I would see:

B6 ON
A6 ON

I think what must be going on is that I confused the issue when I told you about multiple house/unit codes.  This only works when it's the same house code.  So, you can turn all lights with house code A and unit codes 2-5 on at the same time by giving the following:

A2
A3
A4
A5
A ON

If you want to control more than one unit but they are different house codes, you cannot combine this way.  A6 and B6 would have to be:

A6
A ON
B6
B ON

There is a way to set things up using scenes with extended codes, but I'm not familiar with this approach and could not provide any input.

I'm not positive this is the issue with the implementation, but I can say that something has significantly regressed as far as speed goes.

[Gene]

Hi Ben,

I've been running all sort of test for almost one day obtaining very faaast response from XTenLib. Faster than the previous release.

My configuration is:

1) HG1 with CM11
2) HG2 with CM15Pro

Here some tests. Timings are relative to the time the action is performed on the source.

TEST 1

HG1 send B4 ON (830ms)

Code: [Select]


Control.On//1398328626757        HTTP    GET
2014-04-24T08:37:02.7768960+00:00       HomeAutomation.X10      B4      -       Status.Level    1
[08:37:02.830053] X10 < 04 EA
[08:37:02.854065] X10 > EE 00
[08:37:02.861990] X10 > CKSUM: Expected [EE] Checksum ==> EE 00
[08:37:02.869079] X10 < 00
[08:37:03.477697] X10 > 55 00
[08:37:03.491462] X10 < 06 E2
[08:37:03.598742] X10 > E8 00
[08:37:03.606362] X10 > CKSUM: Expected [E8] Checksum ==> E8 00



HG2 receive (start 633ms, end 1451ms)

Code: [Select]


/Logging/RealTime.EventStream/  HTTP    GET
[10:37:03.409065] X10 > 5A 02 00 EA
[10:37:03.416941] X10 > PLCRX: 5A 02 00 EA
[10:37:03.466086] X10 > FNMAP: 00
[10:37:03.473770] X10 >  DATA: EA
[10:37:03.498727] X10 >       0) House code = B
[10:37:03.506655] X10 >       0)  Unit code = 4
[10:37:04.156554] X10 > 5A 02 01 E2
[10:37:04.163939] X10 > PLCRX: 5A 02 01 E2
[10:37:04.177119] X10 > FNMAP: 01
[10:37:04.184902] X10 >  DATA: E2
[10:37:04.195521] X10 >       0) House code = B
[10:37:04.202990] X10 >       0)    Command = ON
2014-04-24T10:37:04.2274570+02:00       HomeAutomation.X10      B4      -       Status.Level    1



TEST 2

HG1 send B4 OFF (716ms)

Code: [Select]

2014-04-24T08:39:53.9298560+00:00       HomeAutomation.X10      B4      -       Status.Level    0
[08:39:54.006153] X10 < 06 E3
[08:39:54.022008] X10 > E9 00
[08:39:54.031675] X10 > CKSUM: Expected [E9] Checksum ==> E9 00
[08:39:54.038305] X10 < 00
[08:39:54.645699] X10 > 55 00


HG2 receive (start 637ms, end 676ms)

Code: [Select]


[10:39:54.566365] X10 > 5A 02 01 E3
[10:39:54.574639] X10 > PLCRX: 5A 02 01 E3
[10:39:54.582370] X10 > FNMAP: 01
[10:39:54.589757] X10 >  DATA: E3
[10:39:54.595955] X10 >       0) House code = B
[10:39:54.601317] X10 >       0)    Command = OFF
2014-04-24T10:39:54.6059110+02:00       HomeAutomation.X10      B4      -       Status.Level    0


Then I built a little script for triggering B7 on/off and linking it to the B4 light:

Code: [Select]

var bedroomlight = Modules.WithAddress("B4");
When.ModuleParameterChange((module, parameter)=>{
 
  if (module.Is("Luce Secondaria") && parameter.Is("Status.Level"))
  {
    if (parameter.Value != "0") bedroomlight.On();
    else bedroomlight.Off();
  }
 
  return true;
});

TEST 3

HG2 send B7 ON and triggers B4 ON (2516ms)

Code: [Select]


2014-04-24T10:50:53.2367960+02:00       HomeAutomation.X10      B7      -       Status.Level    1
2014-04-24T10:50:53.2739360+02:00       HomeAutomation.X10      B4      -       Status.Level    1
[10:50:53.283518] X10 < 04 E5
[10:50:54.190070] X10 > 55
[10:50:54.198647] X10 < 06 E2
[10:50:54.712041] X10 > 55
[10:50:54.719952] X10 < 04 EA
[10:50:55.231987] X10 > 55
[10:50:55.240187] X10 < 06 E2
[10:50:55.752727] X10 > 55


HG 1 receive (start 925ms, end 3149ms)

Code: [Select]


[08:50:54.161101] X10 > 5A 00
[08:50:54.260062] X10 < C3
[08:50:56.162860] X10 > 5A 00
[08:50:56.269089] X10 < C3
[08:50:56.305030] X10 > 5A 05 0A E5 E2 EA E2
[08:50:56.312858] X10 > PLCRX: 5A 05 0A E5 E2 EA E2
[08:50:56.320079] X10 > FNMAP: 00 01 00 01
[08:50:56.324693] X10 >  DATA: E5 E2 EA E2
[08:50:56.330664] X10 >       0) House code = B
[08:50:56.336786] X10 >       0)  Unit code = 7
[08:50:56.342497] X10 >       1) House code = B
[08:50:56.347953] X10 >       1)    Command = ON
2014-04-24T08:50:56.3521180+00:00       HomeAutomation.X10      B7      -       Status.Level    1
[08:50:56.366095] X10 >       2) House code = B
[08:50:56.373316] X10 >       2)  Unit code = 4
[08:50:56.379581] X10 >       3) House code = B
[08:50:56.385334] X10 >       3)    Command = ON
2014-04-24T08:50:56.3895230+00:00       HomeAutomation.X10      B4      -       Status.Level    1
20


TEST 4

HG1 send B7 OFF and receive also B4 ON from the HG2 trigger (4567ms)

Code: [Select]


2014-04-24T08:55:38.7350400+00:00       HomeAutomation.X10      B7      -       Status.Level    0
[08:55:38.811446] X10 < 04 E5
[08:55:38.865267] X10 > E9 00
[08:55:38.874739] X10 > CKSUM: Expected [E9] Checksum ==> E9 00
[08:55:38.881278] X10 < 00
[08:55:39.488727] X10 > 55 00
[08:55:39.497035] X10 < 06 E3
[08:55:39.604811] X10 > E9 00
[08:55:39.612512] X10 > CKSUM: Expected [E9] Checksum ==> E9 00
[08:55:39.619039] X10 < 00
[08:55:40.224652] X10 > 55 00
[08:55:41.142127] X10 > 5A 00
[08:55:41.209264] X10 < C3
[08:55:43.151140] X10 > 5A 00
[08:55:43.218377] X10 < C3
[08:55:43.258904] X10 > 5A 03 02 EA E3
[08:55:43.266605] X10 > PLCRX: 5A 03 02 EA E3
[08:55:43.272907] X10 > FNMAP: 00 01
[08:55:43.278164] X10 >  DATA: EA E3
[08:55:43.285259] X10 >       0) House code = B
[08:55:43.290805] X10 >       0)  Unit code = 4
[08:55:43.296805] X10 >       1) House code = B
[08:55:43.302151] X10 >       1)    Command = OFF
2014-04-24T08:55:43.3061340+00:00       HomeAutomation.X10      B4      -       Status.Level    0


HG2 receive B7 OFF and triggers B4 OFF (start 680ms, end 1471ms)

Code: [Select]


[10:55:39.415667] X10 > 5A 02 00 E5
[10:55:39.423106] X10 > PLCRX: 5A 02 00 E5
[10:55:39.430977] X10 > FNMAP: 00
[10:55:39.437877] X10 >  DATA: E5
[10:55:39.442557] X10 >       0) House code = B
[10:55:39.447582] X10 >       0)  Unit code = 7
[10:55:40.134068] X10 > 5A 02 01 E3
[10:55:40.141500] X10 > PLCRX: 5A 02 01 E3
[10:55:40.149519] X10 > FNMAP: 01
[10:55:40.155491] X10 >  DATA: E3
[10:55:40.162022] X10 >       0) House code = B
[10:55:40.168075] X10 >       0)    Command = OFF
2014-04-24T10:55:40.1731150+02:00       HomeAutomation.X10      B7      -       Status.Level    0
2014-04-24T10:55:40.2068560+02:00       HomeAutomation.X10      B4      -       Status.Level    0
[10:55:40.290066] X10 < 04 EA


About:

I think what must be going on is that I confused the issue when I told you about multiple house/unit codes.  This only works when it's the same house code.  So, you can turn all lights with house code A and unit codes 2-5 on at the same time by giving the following:

I didn't do that. Currently it works that if I send A4 ON and then send DIM OFF and other sequence of commands on that unit, XTenLib simply won't resend the address but just the command unless a new address is received or sent from PLC.

I dunno what's different or wrong with your test, please double check your configuration and or give me some hint about how to replicate this.

Remarks:
The B4 light is a module (LM12) with soft start enabled so the ack to the "passive" HG is sent only when the soft start sequence is completed (at least, visibly looks like that).

Cheers,
g.

[bkenobi]

I don't think I have anything to exotic in my setup, but perhaps all the updates has corrupted something.  Since things are working well for you, it is probably time for me to format the card and start from scratch again.

My config is pretty simple I think. 

• Raspi B v2.0
• HG r360 debian image
• removed r360, installed r368
• disabled almost all builtin programs
• installed 3 custom programs (activity log, advanced smart lights (not running), light test)
• CM15A and wireless keyboard/mouse connected to USB

[Gene]

The only relevant change I can think of, regarding the CM15, is the following.

Everytime a command is sent to the CM15, XTenLib expects the ACK from the interface before sending the next command.
The ACK is for my CM15EU a simple 55 or 55 00 for the CM11:

Code: [Select]


[16:43:04.343366] X10 < 04 E5
[16:43:05.786054] X10 > 55
[16:43:05.794459] X10 < 06 E4 2E
[16:43:07.008771] X10 > 55

(this is an exmaple B7 DIM)

if this ACK is not received, XTenLib will wait on next command up to 5 seconds (it was 3 seconds before, and thruth to be said HG was ignoring it when using the CM15).

This ACK signal should tell that the command has been understood and actually sent over PLC.

Can you make some more tests with your current setup and see if the problem is this ACK wait?

Cheers,
g.

[bkenobi]

I already have that kind of data in a log file I saved yesterday.  I'll both check it out myself and package it up so you take a look at it.  I'll upload something after work.

[Gene]

Ok thanks.

I'm also attacching a version of XTenLib that shorten the max wait for the ACK to 500ms, but only for CM15.
I've tried to tight it up to 300ms and 400ms and wouldn't work. 500ms is the minumum I was able to set.

Cheers,
g.

[bkenobi]

I tried the same test with the same configuration this evening.  I found that it was working much better actually.  But, after more than a dozen attempts, it finally had an issue where it took way too long to toggle the light.  I've attached the whole log with that session of testing.  The last set of data is:

Code: [Select]

[20:54:38.904775] X10 < 06 62
[20:54:39.331669] X10 > 5C 00 1D
[20:54:40.596641] X10 > 5A 02 00 E9
[20:54:40.600057] X10 > PLCRX: 5A 02 00 E9
[20:54:40.603338] X10 > FNMAP: 00
[20:54:40.606782] X10 >  DATA: E9
[20:54:40.610593] X10 >       0) House code = B
[20:54:40.613973] X10 >       0)  Unit code = 6
[20:54:40.832644] X10 > 5C 00 1D
[20:54:41.026731] X10 > 5A 02 01 E3
[20:54:41.030138] X10 > PLCRX: 5A 02 01 E3
[20:54:41.033634] X10 > FNMAP: 01
[20:54:41.036839] X10 >  DATA: E3
[20:54:41.040613] X10 >       0) House code = B
[20:54:41.043878] X10 >       0)    Command = OFF
2014-04-24T20:54:41.0480820-07:00 HomeAutomation.X10 B6 - Status.Level 0
2014-04-24T20:54:41.0585510-07:00 HomeAutomation.X10 A6 - Status.Level 0
2014-04-24T20:54:46.0446650-07:00 HomeAutomation.HomeGenie.Automation 35 Automation Program Program.Status Running
2014-04-24T20:54:46.0636570-07:00 HomeAutomation.HomeGenie.Automation 35 Automation Program Program.Status Idle
[20:54:46.114246] X10 < 06 63
[20:54:47.519510] X10 > 55
[20:54:59.605913] X10 > 5C 00 18

[bkenobi]

After updating the XTenLib.dll to the one you posted today, I was not able to get an instance of a multi-second delay.  I did see a couple times where it seemed like the light took more like 3-4 seconds to toggle, but nothing like the 10 seconds from the last update.



I did notice some errors when I loaded HG after swapping XTenLib.dll with the latest update.  It looks like HG didn't like me performing tail on some log files when it was trying to access them.

[bkenobi]

Did you find anything out about this issue based on the log files I uploaded?  I can do more testing if that would help.  I currently am running r370 and have not performed much testing since uploading the logs.

[Jens]

Hi Gene,

I tried now R370/371 but moving the X10 shutters to a certain hight does still not work.

Did you have a chance to loook at the extended code sample I provided? I think the only
chance to get them working is by using extended commands.

Furthermore if I set the shutter to any value and press "open" afterwards I would expect
the widget to switch from that previous value to a hundred, which is not the case. This is
more the UI behaviour it would not help annyway to move to a certain hight.

Thanks
Regards
Jens