"query all" questions about hops left, program time & status reports

[WayneW]

When running a "query all" with the event viewer at level 3, I see the "hops left" reported.  Is analyzing the "hops left" a good simple way to get a communication health check?

 

 

I trimmed the log down and pasted it below, to make it easier to scan the "hops left".  If there is any validity or usefulness to this technique, it would be nice to get this summary automatically, but with the addition of device names to make it more human readable.

 

I thought my house was working fairly well, but I am concerned by the "Hops Left=1" and "Hops Left=0" lines.

 

 

Item #2:

I also noticed that the "query all" program claims that it started and ended at 3:00:00.  When I run the "then" part of the program manually during the day, I can see that the "query all" actually takes 60-90 seconds, even though program summary indicates the end time equals the start time.  Is the "query all" program special in some way?  My other programs (especially those with a wait command) have an end time much later than the start time, as I expected.

 

Item #3:

I noticed that sometimes (specifically after the mystery "all on" event) the log (udreport.txt) shows that the "query all" shows a lot more "status=100%" than the daily 3 AM "query all".  Does UDreport only log when it finds a device state that is different than the ISY expects?

 

Query all

Sun 01/11/2015 03:00:00 AM : [        Time] 03:00:00 3(0)

Sun 01/11/2015 03:00:00 AM : [std-Direct Ack] 0D.85.E3-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:01 AM : [std-Direct Ack] 0C.02.8B-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:01 AM : [std-Direct Ack] 04.EC.98-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:02 AM : [std-Direct Ack] 04.EC.98-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:02 AM : [std-Direct Ack] 0D.82.36-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:03 AM : [std-Direct Ack] 22.AC.D7-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:00:03 AM : [std-Direct Ack] 0A.B4.CF-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:04 AM : [std-Direct Ack] 0A.B4.CF-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:04 AM : [std-Direct Ack] 00.C9.CD-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:05 AM : [std-Direct Ack] 00.C9.CD-->ISY/PLM Group=0, Max Hops=3, Hops Left=0

Sun 01/11/2015 03:00:14 AM : [std-Direct Ack] 04.4B.FB-->ISY/PLM Group=0, Max Hops=3, Hops Left=0

Sun 01/11/2015 03:00:14 AM : [std-Direct Ack] 23.C6.D9-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:15 AM : [std-Direct Ack] 23.BF.05-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:16 AM : [std-Direct Ack] 05.7A.DF-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:16 AM : [std-Direct Ack] 05.7A.DF-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:17 AM : [std-Direct Ack] 05.7B.10-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:17 AM : [std-Direct Ack] 05.7B.10-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:17 AM : [std-Direct Ack] 05.7B.10-->ISY/PLM Group=0, Max Hops=3, Hops Left=0

Sun 01/11/2015 03:00:18 AM : [std-Direct Ack] 06.1E.83-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:19 AM : [std-Direct Ack] 06.1E.83-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:19 AM : [std-Direct Ack] 00.1A.BF-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:20 AM : [std-Direct Ack] 22.A5.64-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:20 AM : [std-Direct Ack] 07.97.F3-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:21 AM : [std-Direct Ack] 07.97.F3-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:21 AM : [std-Direct Ack] 05.D7.23-->ISY/PLM Group=0, Max Hops=3, Hops Left=0

Sun 01/11/2015 03:00:22 AM : [std-Direct Ack] 05.D6.FA-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:00:22 AM : [std-Direct Ack] 00.5C.C0-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:23 AM : [std-Direct Ack] 23.B0.38-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:00:23 AM : [std-Direct Ack] 1D.CB.F2-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:00:24 AM : [std-Direct Ack] 0C.01.6A-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:24 AM : [std-Direct Ack] 06.1E.78-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:25 AM : [std-Direct Ack] 06.1E.78-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:25 AM : [std-Direct Ack] 07.31.18-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:48 AM : [std-Direct Ack] 0C.C9.7A-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:57 AM : [std-Direct Ack] 01.86.6A-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:00:58 AM : [std-Direct Ack] 01.86.81-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:00:58 AM : [std-Direct Ack] 01.86.F2-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:00:59 AM : [std-Direct Ack] 07.97.42-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:00:59 AM : [std-Direct Ack] 05.D7.F1-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:01:00 AM : [std-Direct Ack] 22.A9.B2-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:00 AM : [std-Direct Ack] 1F.B8.B7-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:01 AM : [std-Direct Ack] 22.A7.11-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:01 AM : [std-Direct Ack] 04.E8.B6-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:01 AM : [std-Direct Ack] 04.E8.B6-->ISY/PLM Group=0, Max Hops=3, Hops Left=0

Sun 01/11/2015 03:01:02 AM : [std-Direct Ack] 04.E8.B6-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:02 AM : [std-Direct Ack] 04.E8.B6-->ISY/PLM Group=0, Max Hops=3, Hops Left=0

Sun 01/11/2015 03:01:02 AM : [std-Direct Ack] 00.FC.D0-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:01:03 AM : [std-Direct Ack] 23.B0.6D-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:03 AM : [std-Direct Ack] 1D.C1.4F-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:04 AM : [std-Direct Ack] 0D.8D.80-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:05 AM : [std-Direct Ack] 0D.80.64-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:01:05 AM : [std-Direct Ack] 06.83.0A-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:01:05 AM : [std-Direct Ack] 0D.80.CD-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:01:06 AM : [std-Direct Ack] 17.81.4B-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:01:06 AM : [std-Direct Ack] 1A.FA.75-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:07 AM : [std-Direct Ack] 0E.9F.73-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:08 AM : [std-Direct Ack] 1A.FA.95-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:08 AM : [std-Direct Ack] 1A.FA.79-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

Sun 01/11/2015 03:01:09 AM : [std-Direct Ack] 1A.FA.72-->ISY/PLM Group=0, Max Hops=3, Hops Left=1

Sun 01/11/2015 03:01:09 AM : [std-Direct Ack] 1A.FA.FC-->ISY/PLM Group=0, Max Hops=3, Hops Left=2

 

 

 

Manually invoking the "query all" program, after a mystery "all on" event

 

 

Scene:My Lighting Status Query Tue 2015/01/06 07:21:15 PM Program Log   

LR Chandelier Status 100% Tue 2015/01/06 07:21:15 PM System Log   

KPLs / KPL Office Desk / KPL Office Desk (NL) Status 100% Tue 2015/01/06 07:21:16 PM System Log   

LR Table Lamp Status 100% Tue 2015/01/06 07:21:17 PM System Log   

OFC fan Status 100% Tue 2015/01/06 07:21:18 PM System Log   

KPLs / KPL Patio / KPL Patio (NL) Fans Status 100% Tue 2015/01/06 07:21:18 PM System Log   

new trees NL ATM Status 100% Tue 2015/01/06 07:21:19 PM System Log   

Patio / Patio Plants Trees Status 100% Tue 2015/01/06 07:21:20 PM System Log   

Patio / Patio Spa Lite Status 100% Tue 2015/01/06 07:21:20 PM System Log   

Patio / Patio Pool Lite Status 100% Tue 2015/01/06 07:21:21 PM System Log   

KPLs / KPL FR Patio / KPL FR Patio (NL) Patio Reces Status 100% Tue 2015/01/06 07:21:22 PM System Log   

KPLs / KPL FR Patio / KPL FR Patio A Pool Status 100% Tue 2015/01/06 07:21:23 PM System Log

 

etc, etc...

[LeeG]

The Hops Left count compared to the Max Hops count is one of the tools to evaluate the Insteon network.  The Hops Left count as a static number does not mean much unless Hops Left=0 (with Max Hops=3) which indicates all hops were used.  No room for addition hops.   

 

Hops Left is better examined when looking at a sequence of commands to the same device.  A Hops Left count that jumps from 2 to 1 to 0 across multiple commands indicates Insteon network problems.

 

All Programs including QueryAll do not wait for command to complete to end a clause.  The Query All process takes time but the Program that issued the command is done once the command is issued.

 

The ISY Log shows a change in device state.   Since the ISY is not aware of the All On the devices that were turned On by the All On are logged by the Query result..