Log not recording device activity

johnnyt · December 1, 2014

I was trying to troubleshoot what I'll call a localized "all on" event where all insteon devices in our master bedroom went ON when I noticed that turning the master bedroom ceiling light was not being recording in the log.

Further down are the log entries for one of 3 identical tests I did with identical results, followed by the event viewer at level 3 during the same test period. What's supposed to happen (and has been happening fine for a couple of years) is that when I fast off The "Master Bedroom Ceiling Light" with address 16.9C.3C a program either turns a floor lamp ON if it is off (program 1) or OFF if it is on (program 2).

The log records the scene calls made by the program but not the fast off event for Master Bedroom Ceiling Light that preceded it even though the latter is picked up in the event viewer.

The device is an ICON Dimmer v.39 (2876DB) in case that makes a difference.

Program 1 - When floor lamp if OFF and Ceiling light is turned Fast Off

If
        Control 'Bedrooms / Master Bedroom Ceiling Light' is switched Fast Off
    And Status  'Bedrooms / LaurenKPL.1-Floor Lamp(Xlink)' is Off
    And Status  'Bedrooms / Master WIC2 On-Off Module' is Off
    And Status  'Bedrooms / Master WIC 1' is Off
Then
        Set Scene 'Bedrooms / Floor Lamp Medium for Prgs' On
Else
   - No Actions - (To add one, press 'Action')

Program 2 - when floor lamp is ON if ceiling light is turn fast off
If
        Control 'Bedrooms / Master Bedroom Ceiling Light' is switched Fast Off
    And (
             Status  'Bedrooms / LaurenKPL.1-Floor Lamp(Xlink)' is not Off
          Or Status  'Bedrooms / Master WIC2 On-Off Module' is not Off
          Or Status  'Bedrooms / Master WIC 1' is not Off
        )
 Then
        Wait  1 second
        Set Scene 'Bedrooms / Dim Lighting for Prgs' Fast Off
 Else
   - No Actions - (To add one, press 'Action')

Unless I'm missing something, the Off for "Master Bedroom Ceiling Light" should have been recorded immediately above the Scene calls below.

Scene:1-MISC (Non Lighting) / Bathroom Fan - Main / Bathroom Fan (ON) for Prgs   On   255   Sun 2014/11/30 07:48:52 PM   Program   Log
1-MISC (Non Lighting) / Bathroom Fan - Main / MainBath.D - Fan   Status   100%   Sun 2014/11/30 07:48:52 PM   System   Log
1-MISC (Non Lighting) / Bathroom Fan - Main / Bathroom Fan Relay   Status   100%   Sun 2014/11/30 07:48:52 PM   System   Log
Scene:Bedrooms / Floor Lamp Medium for Prgs   On      Sun 2014/11/30 07:50:58 PM   Program   Log
Bedrooms / LaurenKPL.1-Floor Lamp(Xlink)   Status   40%   Sun 2014/11/30 07:50:58 PM   System   Log
Bedrooms / LaurenKPL.B-Floor Lamp(Xlink)   Status   100%   Sun 2014/11/30 07:50:58 PM   System   Log
Bedrooms / JeanKPL.1-FloorLamp(capped)   Status   100%   Sun 2014/11/30 07:50:58 PM   System   Log
Scene:Bedrooms / Dim Lighting for Prgs   Fast Off      Sun 2014/11/30 07:51:03 PM   Program   Log
Bedrooms / LaurenKPL.1-Floor Lamp(Xlink)   Status   0%   Sun 2014/11/30 07:51:03 PM   System   Log
Bedrooms / LaurenKPL.B-Floor Lamp(Xlink)   Status   0%   Sun 2014/11/30 07:51:03 PM   System   Log
Bedrooms / JeanKPL.1-FloorLamp(capped)   Status   0%   Sun 2014/11/30 07:51:03 PM   System   Log
Z-Dusk and Low Bat Sensors / Main Bath Dusk-Dawn   Status   100%   Sun 2014/11/30 07:51:52 PM   System   Log

Sun 11/30/2014 07:50:43 PM : [        Time] 19:50:54 11(0)
Sun 11/30/2014 07:50:47 PM : [iNST-SRX    ] 02 50 16.9C.3C 00.00.01 CF 14 00    LTOFF-F(00)
Sun 11/30/2014 07:50:47 PM : [std-Group   ] 16.9C.3C-->Group=1, Max Hops=3, Hops Left=3
Sun 11/30/2014 07:50:47 PM : [D2D EVENT   ] Event [16 9C 3C 1] [DFOF] [0] uom=0 prec=-1
Sun 11/30/2014 07:50:47 PM : [ 16 9C 3C 1]     DFOF   0
Sun 11/30/2014 07:50:47 PM : [iNST-SRX    ] 02 50 16.9C.3C 2F.B5.FB 45 14 01    LTOFF-F(01)
Sun 11/30/2014 07:50:47 PM : [std-Cleanup ] 16.9C.3C-->ISY/PLM Group=1, Max Hops=1, Hops Left=1
Sun 11/30/2014 07:50:47 PM : [iNST-DUP    ] Previous message ignored.
Sun 11/30/2014 07:50:47 PM : [D2D-CMP 00C5] CTL [16 9C 3C 1] DFOF op=1 Event(val=0 uom=0 prec=-1) is Condition(val=0 uom=0 prec=-) --> true
Sun 11/3/2014 07:50:47 PM : [D2D-CMP 00C4] CTL [16 9C 3C 1] DFOF op=1 Event(val=0 uom=0 prec=-1) is Condition(val=0 uom=0 prec=-1) --> true
Sun 11/3/2014 07:50:47 PM : [iNST-TX-I1 ] 02 62 00 00 48 CF 11 00
Sun 11/30/2014 07:50:48 PM : [iNST-ACK    ] 02 62 00.00.48 CF 11 00 06          LTONRR (00)
Sun 11/30/2014 07:50:48 PM : [D2D EVENT   ] Event [16 77 E5 1] [sT] [102] uom=0 prec=-1
Sun 11/30/2014 07:50:48 PM : [ 16 77 E5 1]       ST 102
Sun 11/30/2014 07:50:48 PM : [D2D-CMP 02A1] STS [16 77 E5 1] ST op=2 Event(val=102 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-) --> false
Sun 11/302014 07:50:48 PM : [D2D-CMP 0274] STS [16 77 E5 1] ST op=2 Event(val=102 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-1) --> false
Sun 11/302014 07:50:48 PM : [D2D-CMP 0275] STS [16 77 E5 1] ST op=2 Event(val=102 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-1) --> false
Sun 11/302014 07:50:48 PM : [D2D-CMP 0273] STS [16 77 E5 1] ST op=2 Event(val=102 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-1) --> false
Sun 11/302014 07:50:48 PM : [D2D-CMP 00C5] STS [16 77 E5 1] ST op=6 Event(val=102 uom=0 prec=-1) != Condition(val=0 uom=0 prec=-1) --> true
Sun 11/3/2014 07:50:48 PM : [D2D-CMP 00C4] STS [16 77 E5 1] ST op=1 Event(val=102 uom=0 prec=-1) is Condition(val=0 uom=0 prec=-1) --> false
Sun 11/30/2014 07:50:48 PM : [D2D-CMP 00B0] STS [16 77 E5 1] ST op=3 Event(val=102 uom=0 prec=-1) > Condition(val=249 uom=0 prec=-) --> false
Sun 11/30/2014 07:50:48 PM : [D2D-CMP 009D] STS [16 77 E5 1] ST op=6 Event(val=102 uom=0 prec=-1) != Condition(val=0 uom=0 prec=-) --> true
Sun 11/3/2014 07:50:48 PM : [D2D-CMP 009D] STS [16 77 E5 1] ST op=6 Event(val=102 uom=0 prec=-1) != Condition(val=255 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:48 PM : [D2D-CMP 008E] STS [16 77 E5 1] ST op=1 Event(val=102 uom=0 prec=-1) is Condition(val=0 uom=0 prec=-1) --> false
Sun 11/30/2014 07:50:48 PM : [D2D-CMP 00A1] STS [16 77 E5 1] ST op=2 Event(val=102 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-1) --> false
Sun 11/30/2014 07:50:48 PM : [D2D EVENT   ] Event [16 77 E5 2] [sT] [255] uom=0 prec=-1
Sun 11/30/2014 07:50:48 PM : [ 16 77 E5 2]       ST 255
Sun 11/30/2014 07:50:48 PM : [D2D EVENT   ] Event [16 74 DF 1] [sT] [255] uom=0 prec=-1
Sun 11/30/2014 07:50:48 PM : [ 16 74 DF 1]       ST 255
Sun 11/30/2014 07:50:51 PM : [iNST-SRX    ] 02 50 16.9C.3C 00.00.01 CF 14 00    LTOFF-F(00)
Sun 11/30/2014 07:50:51 PM : [std-Group   ] 16.9C.3C-->Group=1, Max Hops=3, Hops Left=3
Sun 11/30/2014 07:50:51 PM : [D2D EVENT   ] Event [16 9C 3C 1] [DFOF] [0] uom=0 prec=-1
Sun 11/30/2014 07:50:51 PM : [ 16 9C 3C 1]     DFOF   0
Sun 11/30/2014 07:50:51 PM : [iNST-SRX    ] 02 50 16.9C.3C 2F.B5.FB 45 14 01    LTOFF-F(01)
Sun 11/30/2014 07:50:51 PM : [std-Cleanup ] 16.9C.3C-->ISY/PLM Group=1, Max Hops=1, Hops Left=1
Sun 11/30/2014 07:50:51 PM : [iNST-DUP    ] Previous message ignored.
Sun 11/30/2014 07:50:51 PM : [D2D-CMP 00C5] CTL [16 9C 3C 1] DFOF op=1 Event(val=0 uom=0 prec=-1) is Condition(val=0 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:51 PM : [D2D-CMP 00C4] CTL [16 9C 3C 1] DFOF op=1 Event(val=0 uom=0 prec=-1) is Condition(val=0 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:53 PM : [iNST-TX-I1 ] 02 62 00 00 3D CF 14 00
Sun 11/30/2014 07:50:53 PM : [iNST-ACK    ] 02 62 00.00.3D CF 14 00 06          LTOFF-F(00)
Sun 11/30/2014 07:50:53 PM : [D2D EVENT   ] Event [16 77 E5 1] [sT] [0] uom=0 prec=-1
Sun 11/30/2014 07:50:53 PM : [ 16 77 E5 1]       ST   0
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 02A1] STS [16 77 E5 1] ST op=2 Event(val=0 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 0274] STS [16 77 E5 1] ST op=2 Event(val=0 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 0275] STS [16 77 E5 1] ST op=2 Event(val=0 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 0273] STS [16 77 E5 1] ST op=2 Event(val=0 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 00C5] STS [16 77 E5 1] ST op=6 Event(val=0 uom=0 prec=-1) != Condition(val=0 uom=0 prec=-1) --> false
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 00C4] STS [16 77 E5 1] ST op=1 Event(val=0 uom=0 prec=-1) is Condition(val=0 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 00B0] STS [16 77 E5 1] ST op=3 Event(val=0 uom=0 prec=-1) > Condition(val=249 uom=0 prec=-1) --> false
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 009D] STS [16 77 E5 1] ST op=6 Event(val=0 uom=0 prec=-1) != Condition(val=0 uom=0 prec=-1) --> false
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 009D] STS [16 77 E5 1] ST op=6 Event(val=0 uom=0 prec=-1) != Condition(val=255 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 008E] STS [16 77 E5 1] ST op=1 Event(val=0 uom=0 prec=-1) is Condition(val=0 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:53 PM : [D2D-CMP 00A1] STS [16 77 E5 1] ST op=2 Event(val=0 uom=0 prec=-1) < Condition(val=63 uom=0 prec=-1) --> true
Sun 11/30/2014 07:50:53 PM : [D2D EVENT   ] Event [16 77 E5 2] [sT] [0] uom=0 prec=-1
Sun 11/30/2014 07:50:53 PM : [ 16 77 E5 2]       ST   0
Sun 11/30/2014 07:50:53 PM : [D2D EVENT   ] Event [16 74 DF 1] [sT] [0] uom=0 prec=-1
Sun 11/30/2014 07:50:53 PM : [ 16 74 DF 1]       ST   0
Sun 11/30/2014 07:50:54 PM : [        Time] 19:51:05 11(0)

Michel Kohanim · December 2, 2014

Hi johnnyt,

I think the issue is that logs only capture changes in state and not physical activity. So, if the device was off before, it really does not matter how many times you physically turn it off as those won't be logged.

With kind regards,

Michel

johnnyt · December 3, 2014

Thanks, that explains it as well as maybe other situations that left me confused in the past.

Any chance the log could show what happens on the insteon network, not just what's changed? Would help with troubleshooting.

Thanks for considering it.

Michel Kohanim · December 3, 2014

Hi johnnyt,

We did consider but left it in the Event Viewer. This way you can see everything and not just what we think is important. Of course if the problem happens in a span of more than a few days, then Event Viewer will not be a good solution either.

With kind regards,
Michel

johnnyt · December 4, 2014

Yes, event viewer is fine for active troubleshooting when the problem is easy to reproduce and with guys like LeeG around to help read/understand the messages but it's not so good when you're on your own or faced with something that's hard to catch/reproduce or intermittent. Personally, I've had a lot in the latter group, many of which remain unsolved mysteries to this day - like the problem that prompted this thread - but if that's not enough people's experience, I understand.

Sent from my iPad using Tapatalk

Michel Kohanim · December 5, 2014

Hi johnnyt,

Understood. We definitely can't use the same log file. Perhaps we should have a debug only log with the name of programs and all other device activities.

With kind regards ,

Michel

Sign In

Log not recording device activity

Recommended Posts

johnnyt

Link to comment

Michel Kohanim

Link to comment

johnnyt

Link to comment

Michel Kohanim

Link to comment

johnnyt

Link to comment

Michel Kohanim

Link to comment

Archived

Recently Browsing

Who's Online (See full list)

Forum Statistics

Browse

Activity