search

automategreen / home-controller

A node package to control Insteon home automation devices
MIT License
96 stars 29 forks source link

Light level response inconsistent #97

Closed THX723 closed 2 years ago

THX723 commented 4 years ago

When polling the status of a light, say ...

function lightStatus () {
  var level = this.level();
  console.log(light.id + ' is at level of ' + level);
}

Sometimes the returned level is wildly incorrect (seemingly random). Maybe a coincident, but this seems to occur more when there are lots of traffic or the polling is rapid and continuous.

Any thoughts?

siburny commented 4 years ago

Hmm, I've never seen this in my setup. Would it possible to record and send us a debug output?

THX723 commented 4 years ago

@siburny Here's the debug log. But first some preface ...

home-controller is being leveraged by homebridge-platform-insteonlocal which controls my Insteon devices.

insteonlocal listens for light switch events and make a simple status call to home-controller via 

self.light.level(function(err,level) { do stuff }

For debug purpose, I injected the following line in Light.js:

console.log('[home-controller] id=%s command1=%s command2=%s', id, status.response.standard.command1, status.response.standard.command2) ///THX723 Debug

Modified Light.js:

/**
 * Light Instant Change
 * Check for light level.
 *
 * 19 -- STATUS command
 *
 * 21 -- Instant Change command
 *
 * @param  {String}   id
 * @param  {Number}   level
 * @param  {Function} next
 */
Light.prototype.level = function (level, next) {
  if (typeof level === 'function') {
    next = level;
    level = null;
  }

  var id = this.id;

  if (level !== null && level !== undefined){
    return this.insteon.directCommand(id, '21', utils.levelToHexByte(level), next);
  } else {
    var deferred = Q.defer();
    deferred.resolve(
      this.insteon.directCommand(id, '19')
      .then(function (status) {

        if(!status || !status.response || !status.response.standard) {
          debug('No response for level request for device %s', id);
          return null;
        }

        console.log('[home-controller] id=%s command1=%s command2=%s', id, status.response.standard.command1, status.response.standard.command2) ///THX723 Debug

        var level = Math.ceil(parseInt(status.response.standard.command2, 16) * 100 / 255);
        return level;
      })
    );
    return deferred.promise.nodeify(next);
  }
};

Light switch was switched ON 20 times consecutively in a relatively short time. One would expect light status returned to be ON (command2=FF) 100% of the time. But as you can see, 40% of the time it reported values other than FF/100%.

[6/23/2020, 12:48:46 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=06 command2=00
[6/23/2020, 12:48:46 AM] [Insteon Local Platform] [Kitchen Light] is Off at (0%)
[6/23/2020, 12:49:25 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:49:26 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:49:28 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:49:28 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:49:31 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=11 command2=01
[6/23/2020, 12:49:31 AM] [Insteon Local Platform] [Kitchen Light] is On at (1%)
[6/23/2020, 12:49:33 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:49:33 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:49:34 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:49:35 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:49:36 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:49:36 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:49:37 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:49:38 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:49:38 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=11 command2=01
[6/23/2020, 12:49:40 AM] [Insteon Local Platform] [Kitchen Light] is On at (1%)
[6/23/2020, 12:49:43 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=11 command2=01
[6/23/2020, 12:49:43 AM] [Insteon Local Platform] [Kitchen Light] is On at (1%)
[6/23/2020, 12:49:45 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=06 command2=00
[6/23/2020, 12:49:45 AM] [Insteon Local Platform] [Kitchen Light] is Off at (0%)
[6/23/2020, 12:49:47 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:49:48 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:50:02 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:50:05 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:50:05 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=06 command2=00
[6/23/2020, 12:50:05 AM] [Insteon Local Platform] [Kitchen Light] is Off at (0%)
[6/23/2020, 12:50:06 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:50:06 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:50:08 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=11 command2=01
[6/23/2020, 12:50:08 AM] [Insteon Local Platform] [Kitchen Light] is On at (1%)
[6/23/2020, 12:50:09 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:50:10 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:50:11 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=02 command2=FF
[6/23/2020, 12:50:11 AM] [Insteon Local Platform] [Kitchen Light] is On at (100%)
[6/23/2020, 12:50:13 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=11 command2=01
[6/23/2020, 12:50:13 AM] [Insteon Local Platform] [Kitchen Light] is On at (1%)
[6/23/2020, 12:50:14 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
[home-controller] id=422C15 command1=11 command2=01
[6/23/2020, 12:50:14 AM] [Insteon Local Platform] [Kitchen Light] is On at (1%)
[6/23/2020, 12:50:15 AM] [Insteon Local Platform] Getting status for [422C15 Kitchen Light]...
siburny commented 4 years ago

It would be really helpful to see the underlining Insteon traffic. How do you run your application? Are you able to set an environment variable?

siburny commented 4 years ago

I had some time to play with it and couldn't replicate the issue. Every "level" request produced correct value. Also, "level" command is 19, but your log shows anything but that command.