HG 1.1 update broke Advanced Smart Lights

[bkenobi]

I've been doing some debugging and found that when HG was updated to version 1.1, something changed to the code that broke the Advanced Smart Lights APP.  The code technically works, but there are massive delays that cause the code to be basically unusable.  In version 493 everything works correctly.  Updating to 1.1 causes a delay of almost exactly 10 seconds between motion detection and lights to be turned on.  I see no reason for this delay, so I'm hoping there might be some kind of change that's known such that I can modify the ASL code to work with the current version of HG.

[bkenobi]

I reverted back to r483 and allowed for the web update.  The ASL code runs at normal speed.  There is definitely something different in the main HG code that my ASL code is struggling with.  I am fairly confident that there is some kind of a timer issue though I'm not setting one nor is it set for the delay as the delay is exactly 10 seconds every time for the switch.

Switch on -> lights on (10 second delay):

Code: [Select]

20151026 06:41:00.6343100 ; 2-Entry switch ; Status.Level ; 1
20151026 06:41:11.7554350 ; 3-Entry Lights ; ON
20151026 06:41:11.7622040 ; 14.2-Entry switch ; 1 0 ; No consecutive detected
Switch off -> lights off (10 second delay):

Code: [Select]

20151026 06:41:13.3714960 ; 2-Entry switch ; Status.Level ; 0
20151026 06:41:23.9309780 ; 3.1-Entry Lights ; OFF (TIMER_ON false)
20151026 06:41:23.9365400 ; 14.2-Entry switch ; 0 1 ; No consecutive detected
Looking at a different light, this motion sensor takes exactly 10 seconds to turn the light on too.

Motion sensor on -> light on (10 second delay):

Code: [Select]

20150928 19:36:00.1530500 ; 15-South lights ; Event time ; 20150928 19:35:49.5740760
20150928 19:36:10.1689050 ; 16-South lights ; ON
20150928 19:36:10.1750350 ; 16.1-Delay time start ; 300
The other thing I notice is that the GPIO based motion sensor is not recognized the same way as it used to be.

GPIO on -> light on (r493?, no delay):

Code: [Select]

20150928 19:05:29.6425080 ; 14.5-Garage motion GPIO ; Status.Level ; 1
20150928 19:05:29.6953570 ; 15-Entry Lights ; Event time ; 20150928 19:05:29.1158940
20150928 19:05:30.5561740 ; 16-Entry Lights ; ON
20150928 19:05:30.5616990 ; 16.2-Waiting for sensor OFF to set timer ; 300
GPIO on -> light on (r498, 10 second delay):

Code: [Select]

20150928 20:05:35.5504020 ; 15-Entry Lights ; Event time ; 20150928 20:05:35.0302780
20150928 20:05:46.6324280 ; 16-Entry Lights ; ON
Clearly something is wrong here.  Either I'm doing something with the ASL code that is implemented incorrectly for HG or something in the HG core code is updated/changed so that it functions differently than it used to.  I'll continue to scour the ASL code, but if there is anything known related to timer implementation, background functionality, X10 commands, etc that might be relevant for me to review a heads up would be much appreciated!

[Gene]

Hi bkenobi,

there could be a difference in the way HG sends commands now. Before these where asynchronous. Now HG wait for the command to complete.

A quick test is to try to issue from the web a command like:

Code: [Select]

http://192.168.0.235/api/HomeAutomation.X10/M7/Control.On
and see how much time the browser takes to load the response page (which is blank for X10 anyway).
Try it with old and new version.

Anyway with my CM15 it just takes 1 second to execute. One time I experienced a delay too, but the problem was solved replacing the internal CM15 battery (dunno why, but it worked).

g.

[Gene]

this is M7 Off timings with new HG:

Code: [Select]

2015-10-27 17:08:15.9334 Debug 04-05      <--- START
2015-10-27 17:08:16.4377 Debug 55
2015-10-27 17:08:16.4381 Debug Command succesfull
2015-10-27 17:08:16.4381 Debug 06-03
2015-10-27 17:08:16.9417 Debug 55
2015-10-27 17:08:16.9421 Debug Command succesfull
2015-10-27 17:08:16.9437 Info HomeAutomation.X10        M7      -       Status.Level    0  <--- END
2015-10-27 17:08:16.9470 Info WebServiceGateway 192.168.0.6     HTTP    GET     200 /api/HomeAutomation.X10/M7/Control.Off

g.

[bkenobi]

I'll Give it a try locally tonight. I just tried with A1 remotely with an older HG and the response was very quick.

[bkenobi]

r493:

Code: [Select]

2015-10-27T20:36:46.9717600-07:00 MIG.Gateways.WebServiceGateway 192.168.0.5 api/HomeAutomation.X10/A1/Control.On HTTP GET
2015-10-27T20:36:46.9770490-07:00 HomeGenie.System Console StdOut/StdErr redirect Console.Output X10 < 04 66
2015-10-27T20:36:47.3948510-07:00 HomeGenie.System Console StdOut/StdErr redirect Console.Output X10 > 55
2015-10-27T20:36:47.3984420-07:00 HomeGenie.System Console StdOut/StdErr redirect Console.Output X10 > COMMAND SUCCESSFUL
2015-10-27T20:36:47.4024650-07:00 HomeGenie.System Console StdOut/StdErr redirect Console.Output X10 < 06 62
2015-10-27T20:36:47.8348510-07:00 HomeGenie.System Console StdOut/StdErr redirect Console.Output X10 > 55
2015-10-27T20:36:47.8382620-07:00 HomeGenie.System Console StdOut/StdErr redirect Console.Output X10 > COMMAND SUCCESSFUL
r499:

Code: [Select]

2015-10-27 21:03:17.5206 Debug 04-66
2015-10-27 21:03:17.5267 Warn Interface I/O error
2015-10-27 21:03:17.5291 Debug 06-62
2015-10-27 21:03:17.5315 Warn Interface I/O error
2015-10-27 21:03:17.5475 Info HomeAutomation.X10 A1 - Status.Level 1
2015-10-27 21:03:17.5631 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.X10/A1/Control.On

[bkenobi]

And this is 499 with the ASL code.

switch on -> light on (10 second delay):

Code: [Select]

2015-10-27 21:11:56.6183 Debug 5A-02-00-E9
2015-10-27 21:11:56.6214 Debug PLCRX: 5A-02-00-E9
2015-10-27 21:11:56.6393 Debug FNMAP: 00
2015-10-27 21:11:56.6421 Debug DATA : E9
2015-10-27 21:11:56.6666 Debug       0) Address = B6
2015-10-27 21:11:57.0501 Debug 5A-02-01-E2
2015-10-27 21:11:57.0530 Debug PLCRX: 5A-02-01-E2
2015-10-27 21:11:57.0595 Debug FNMAP: 01
2015-10-27 21:11:57.0620 Debug DATA : E2
2015-10-27 21:11:57.0864 Debug       0) House code = B
2015-10-27 21:11:57.0924 Debug       0)    Command = On
2015-10-27 21:11:57.1002 Info HomeAutomation.X10 B6 - Status.Level 1
2015-10-27 21:11:57.7828 Debug 04-69
2015-10-27 21:12:00.1969 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Statistics/Global.TimeRange//
2015-10-27 21:12:00.4821 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Statistics/Parameter.StatsHour/Meter.Watts//1445929200000/1446015599000
2015-10-27 21:12:02.9769 Warn Previous command timed out, resending (1)
2015-10-27 21:12:02.9819 Debug 06-62
2015-10-27 21:12:03.1613 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-27 21:12:07.9870 Warn Previous command timed out, resending (1)
2015-10-27 21:12:07.9922 Info HomeAutomation.X10 A6 - Status.Level 1
Looks like the issue is that there are 2 timeouts that take 5 seconds each.  I'm not clear what's timing out though since the command eventually sends.  I assume this is due to the refactoring of the X10 code?

[Gene]

Bkenobi your CM15 is not sending ACK (0x55) after each command.
See my log for example:

2015-10-27 17:08:15.9334 Debug 04-05      <--- START
2015-10-27 17:08:16.4377 Debug 55
2015-10-27 17:08:16.4381 Debug Command succesfull
2015-10-27 17:08:16.4381 Debug 06-03
2015-10-27 17:08:16.9417 Debug 55
2015-10-27 17:08:16.9421 Debug Command succesfull
2015-10-27 17:08:16.9437 Info HomeAutomation.X10        M7      -       Status.Level    0  <--- END

if 0x55 is not received, the XTenLib will attempt resending the command 2 more times.

g.

[bkenobi]

I can try resetting the CM15A.  I'm not sure why it would have an issue with one version but not another.  Did you change how HG works such that it didn't used to require the ACK command?  I can't think of anything I did on my end to change how the hardware is configured.  I'm trying to understand what I need to do to maintain a reliable HA setup.

[Gene]

Hi ben,

please see the log of a command issued with the old version. the ACK might be missing there too, the only difference is that the old HG do not wait for a command to complete.

g.

[bkenobi]

I know the 55 was in the log a long time ago when you did the last X10 rewrite, but the current mono output (e.g., r493) does not output the raw X10 commands.  I know they are in 498/499.  I'll reset the CM15A since you suggested that replacing the battery helped (which would reset the unit).

[bkenobi]

I reset my CM15A and the lights still took 10 seconds to turn on/off and the log indicated timeouts.  I replaced the primary CM15A with my backup unit and had the same issue.  I reinstalled the primary CM15A and I still see the delay.  If I trigger the switch from HG rather than at the switch, the lights seem to work quicker.  I'm not sure what's going on with that though.

CM15A switch on  -> light on: 11.7 seconds

Code: [Select]

2015-10-28 19:05:47.6398 Debug 5A-02-00-E9
2015-10-28 19:05:47.6425 Debug PLCRX: 5A-02-00-E9
2015-10-28 19:05:47.6448 Debug FNMAP: 00
2015-10-28 19:05:47.6473 Debug DATA : E9
2015-10-28 19:05:47.6502 Debug       0) Address = B6
2015-10-28 19:05:48.0719 Debug 5A-02-01-E2
2015-10-28 19:05:48.0747 Debug PLCRX: 5A-02-01-E2
2015-10-28 19:05:48.0775 Debug FNMAP: 01
2015-10-28 19:05:48.0801 Debug DATA : E2
2015-10-28 19:05:48.0829 Debug       0) House code = B
2015-10-28 19:05:48.0855 Debug       0)    Command = On
2015-10-28 19:05:48.0888 Info HomeAutomation.X10 B6 - Status.Level 1
2015-10-28 19:05:48.7004 Debug 04-69
2015-10-28 19:05:53.7062 Warn Previous command timed out, resending (1)
2015-10-28 19:05:53.7105 Debug 06-62
2015-10-28 19:05:56.9480 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-28 19:05:58.7154 Warn Previous command timed out, resending (1)
2015-10-28 19:05:58.7205 Info HomeAutomation.X10 A6 - Status.Level 1
2015-10-28 19:05:59.2900 Debug 55
2015-10-28 19:05:59.2926 Debug Command succesfull
2015-10-28 19:05:59.7134 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /hg/html/pages/control/widgets/homegenie/generic/light.js
2015-10-28 19:05:59.7893 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /hg/html/pages/control/widgets/homegenie/generic/light.html

HG command switch on -> light on: 3.9 seconds

Code: [Select]

2015-10-28 19:09:08.5608 Debug 04-E9
2015-10-28 19:09:09.6242 Debug 55
2015-10-28 19:09:09.6274 Debug Command succesfull
2015-10-28 19:09:09.6312 Debug 06-E3
2015-10-28 19:09:10.0563 Debug 55
2015-10-28 19:09:10.0590 Debug Command succesfull
2015-10-28 19:09:10.0636 Info HomeAutomation.X10 B6 - Status.Level 0
2015-10-28 19:09:10.6491 Debug 04-69
2015-10-28 19:09:11.2116 Info HomeAutomation.EnergyMonitor 1 Virtual Module EnergyMonitor.KwLoad 0.000
2015-10-28 19:09:11.7951 Info HomeAutomation.EnergyMonitor 1 Virtual Module EnergyMonitor.WattLoad 0.000
2015-10-28 19:09:12.0985 Debug 55
2015-10-28 19:09:12.1013 Debug Command succesfull
2015-10-28 19:09:12.1052 Debug 06-63
2015-10-28 19:09:12.5286 Debug 55
2015-10-28 19:09:12.5315 Debug Command succesfull
2015-10-28 19:09:12.5365 Info HomeAutomation.X10 A6 - Status.Level 0

[bkenobi]

Is it possible that the CM15A does not send a ACK when a different transmitter sends a command? It appears that things work correctly when the CM15A sends the command but not when it receives.

[Gene]

I made some tests and I could see the I/O error too. It seems like the initialization message is sent too early at startup. What I did to make it disappear is going to the maintenance page and change the port from USB to something else and then switching it back to USB... and the I/O error message disappeared.
Can you make this test and see if the ACK returns to normal? If so I'll try to change the startup sequence in order to fix this.

g.

[bkenobi]

This log shows turning switch on which turns light on, changing CM15A to CM11A, changing back to CM15A, turning switch off which turns light off.  There is a delay for the light to turn on and one for turning off after changing ports still.

Code: [Select]

2015-10-29 05:50:03.4567 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-29 05:50:07.6766 Debug 5A-02-00-E9
2015-10-29 05:50:07.6794 Debug PLCRX: 5A-02-00-E9
2015-10-29 05:50:07.6820 Debug FNMAP: 00
2015-10-29 05:50:07.6847 Debug DATA : E9
2015-10-29 05:50:07.6877 Debug       0) Address = B6
2015-10-29 05:50:08.1098 Debug 5A-02-01-E2
2015-10-29 05:50:08.1127 Debug PLCRX: 5A-02-01-E2
2015-10-29 05:50:08.1153 Debug FNMAP: 01
2015-10-29 05:50:08.1185 Debug DATA : E2
2015-10-29 05:50:08.1213 Debug       0) House code = B
2015-10-29 05:50:08.1239 Debug       0)    Command = On
2015-10-29 05:50:08.1277 Info HomeAutomation.X10 B6 - Status.Level 1
2015-10-29 05:50:08.7449 Debug 04-69
2015-10-29 05:50:13.4834 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-29 05:50:14.3272 Warn Previous command timed out, resending (1)
2015-10-29 05:50:14.3316 Debug 06-62
2015-10-29 05:50:19.3360 Warn Previous command timed out, resending (1)
2015-10-29 05:50:19.3412 Info HomeAutomation.X10 A6 - Status.Level 1
2015-10-29 05:50:20.4070 Debug 55
2015-10-29 05:50:20.4095 Debug Command succesfull
2015-10-29 05:50:20.4268 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /hg/html/pages/control/widgets/homegenie/generic/light.js
2015-10-29 05:50:20.5055 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /hg/html/pages/control/widgets/homegenie/generic/switch.js
2015-10-29 05:50:20.5191 Info WebServiceGateway 192.168.0.5 HTTP GET 304 /hg/html/images/indicators/plug.png
2015-10-29 05:50:20.5550 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /hg/html/pages/control/widgets/homegenie/generic/light.html
2015-10-29 05:50:20.7949 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /hg/html/pages/control/widgets/homegenie/generic/switch.html
2015-10-29 05:50:23.4921 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/

2015-10-29 05:50:25.8827 Trace HomeAutomation.X10: Port=/dev/ttyAMA0
2015-10-29 05:50:26.4444 Info HomeAutomation.X10

2015-10-29 05:50:30.6675 Info MIGService.Interfaces HomeAutomation.X10 MIG Interface Options.Port /dev/ttyAMA0
2015-10-29 05:50:31.1187 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-29 05:50:31.6124 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/MIGService.Interfaces/HomeAutomation.X10/Options.Set/Port/%2Fdev%2FttyAMA0/
2015-10-29 05:50:32.0716 Trace HomeAutomation.X10: Port=USB
2015-10-29 05:50:32.2185 Info HomeAutomation.X10
2015-10-29 05:50:32.7714 Debug 9B-20-6E-02-2D-90-09-02
2015-10-29 05:50:32.7793 Debug BB-54-40-05-00-14-20-28-24-29
2015-10-29 05:50:32.7953 Debug 8B
2015-10-29 05:50:32.8207 Info MIGService.Interfaces HomeAutomation.X10 MIG Interface Options.Port USB
2015-10-29 05:50:32.8228 Debug 55
2015-10-29 05:50:32.8269 Debug 00
2015-10-29 05:50:32.8329 Debug 00-00-00-00-00-00-00-00
2015-10-29 05:50:32.8463 Debug 00
2015-10-29 05:50:33.2927 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-29 05:50:33.4446 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-29 05:50:33.7501 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/MIGService.Interfaces/HomeAutomation.X10/Options.Set/Port/USB/

2015-10-29 05:50:39.3892 Debug 5A-02-00-E9
2015-10-29 05:50:39.3921 Debug PLCRX: 5A-02-00-E9
2015-10-29 05:50:39.3947 Debug FNMAP: 00
2015-10-29 05:50:39.3975 Debug DATA : E9
2015-10-29 05:50:39.4004 Debug       0) Address = B6
2015-10-29 05:50:39.8222 Debug 5A-02-01-E3
2015-10-29 05:50:39.8250 Debug PLCRX: 5A-02-01-E3
2015-10-29 05:50:39.8275 Debug FNMAP: 01
2015-10-29 05:50:39.8303 Debug DATA : E3
2015-10-29 05:50:39.8329 Debug       0) House code = B
2015-10-29 05:50:39.8357 Debug       0)    Command = Off
2015-10-29 05:50:39.8390 Info HomeAutomation.X10 B6 - Status.Level 0
2015-10-29 05:50:40.4170 Debug 04-69
2015-10-29 05:50:43.4414 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-29 05:50:46.0444 Warn Previous command timed out, resending (1)
2015-10-29 05:50:46.0493 Debug 06-63
2015-10-29 05:50:51.0545 Warn Previous command timed out, resending (1)
2015-10-29 05:50:51.0597 Info HomeAutomation.X10 A6 - Status.Level 0
2015-10-29 05:50:52.1196 Debug 55
2015-10-29 05:50:52.1221 Debug Command succesfull
2015-10-29 05:50:53.4442 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-29 05:51:03.5067 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/
2015-10-29 05:51:13.4598 Info WebServiceGateway 192.168.0.5 HTTP GET 200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/

I removed everything that cluttered the log up so it would be easier to read (e.g., MQTT stuff).  Hopefully I didn't remove a critical message.  I don't see anything that suggests it did anything different than during boot up.

I looked back in the log and I do see some errors from the boot sequence of 499 with default settings.  I doubt this helps though.