Scheduled Polling Events - auto closing garage door [SOLUTION]

[n2ppp]

I've been trying to write an event/action intended to automatically close the garage door late in the evening if it's been open for an extended period of time.  Unfortunately, I haven't been able to get it to function.  My approach was to schedule an event when the garage door is opened so that if it's still open after a certain time of day (let's say between 8pm and 6am) and it's been open more than 30 minutes (for instance), it will send a command to close the door.  As I wasn't able to get it working, I've peppered the code with console log messages to help diagnose the problem.  I was successful in scheduling periodic polling for garage door status.  One thing I notice is that whenever the scheduled event is triggered, the node values seem to be those as they were when the gateway code was first executed.  For instance, the updated time is the time when the gateway was first executed, though there have been several updates since.  As I was unable to get the conditions to trigger the behavior to work, I've commented the close command and added a bunch of tracing.  It's far from pretty at this point, but here's my crack at the code...

Code Select Expand

exports.garageOpenDate = null;

exports.events = {
  garageClose : {
    label:'Garage : Night auto close',
    icon:'clock',
    descr:'Automatically close garage door after being open for 30 mins',
    nextSchedule:function(node) {
      return 30000; // 30sec
    },
    scheduledExecute:function(node) {
      console.log('The Node: '+JSON.stringify(node));
      sendMessageToNode({nodeId:node._id, action:'STS'});
      console.log('***> Garage is '+node.metrics['Status'].value);
      console.log('***> Garage status last updated: '+new Date(node.metrics['Status'].updated).toString());
      if ( node.metrics['Status'] && node.metrics['Status'].value == 'OPEN' ) {

        if ( exports.garageOpenDate == null ) {
          exports.garageOpenDate = new Date(Date.now());
        };

        var nowDate = new Date(Date.now());

        if (nowDate.getHours() > 20 || nowDate.getHours() < 6) {
          console.log('***> It is late. Garage is '+node.metrics['Status'].value);
          console.log('***> Garage has been open since '+(new Date(exports.garageOpenDate)).toString());
          //if (openDuration > 60) {
          //   sendSMS('Garage event', 'Garage open before 6:00 am');
          //   sendMessageToNode({nodeId:node._id, action:'CLS'});
          //};
        };
      };
      if ( node.metrics['Status'] && node.metrics['Status'].value == 'CLOSED' ) {
        exports.garageOpenDate = null;
      };
    }
  },

I also added some tracing to gateway.js, confirming that the node data is actually being updated (of course), so I suspect that in the event/action code, I'm looking at a stale copy of the node.

The log excerpts look like...
:

Code Select Expand

: Initial state: Garage Door is closed
:
[08-04-16_00:39:25.285] [LOG]   **** RUNNING SCHEDULED EVENT - nodeId:99 event:garageClose...
[08-04-16_00:39:25.289] [LOG]   The Node: {"_id":99,"updated":1470277741055,"type":"GarageMote","label":"Garage Opener","rssi":50,"metrics":{"Status":{"label":"Status","value":"CLOSED","updated":1470277741055,"pin":1,"graph":1}},"events":{"garageClose":1}}
[08-04-16_00:39:25.295] [LOG]   NODEACTION: {"nodeId":99,"action":"STS"}
[08-04-16_00:39:25.299] [LOG]   ***> Garage is CLOSED
[08-04-16_00:39:25.303] [LOG]   ***> Garage status last updated: Wed Aug 03 2016 22:29:01 GMT-0400 (EDT)
[08-04-16_00:39:25.306] [LOG]   **** SCHEDULING EVENT - nodeId:99 event:garageClose to run in ~0.01hrs
[08-04-16_00:39:25.315] [LOG]   >: ACK:OK
[08-04-16_00:39:26.332] [LOG]   >: [99] CLOSED   [RSSI:-51][ACK-sent]
[08-04-16_00:39:26.339] [LOG]   ***> Metric name: Status, was: CLOSED, now: CLOSED
[08-04-16_00:39:26.342] [LOG]   post: /home/pi/gateway/data/db/0099_Status.bin[1470285566,0]
:
: Status poll fires... garage indicates it's still closed.  Good.
:
[08-04-16_00:40:55.370] [LOG]   **** RUNNING SCHEDULED EVENT - nodeId:99 event:garageClose...
[08-04-16_00:40:55.373] [LOG]   The Node: {"_id":99,"updated":1470277741055,"type":"GarageMote","label":"Garage Opener","rssi":50,"metrics":{"Status":{"label":"Status","value":"CLOSED","updated":1470277741055,"pin":1,"graph":1}},"events":{"garageClose":1}}
[08-04-16_00:40:55.379] [LOG]   NODEACTION: {"nodeId":99,"action":"STS"}
[08-04-16_00:40:55.382] [LOG]   ***> Garage is CLOSED
[08-04-16_00:40:55.385] [LOG]   ***> Garage status last updated: Wed Aug 03 2016 22:29:01 GMT-0400 (EDT)
[08-04-16_00:40:55.388] [LOG]   **** SCHEDULING EVENT - nodeId:99 event:garageClose to run in ~0.01hrs
[08-04-16_00:40:55.399] [LOG]   >: ACK:OK
[08-04-16_00:40:56.416] [LOG]   >: [99] CLOSED   [RSSI:-49][ACK-sent]
[08-04-16_00:40:56.423] [LOG]   ***> Metric name: Status, was: CLOSED, now: CLOSED
:
:  ---- So far, so good... OPEN the door...
:
[08-04-16_00:41:17.587] [LOG]   NODEACTION: {"nodeId":99,"action":"OPN"}
[08-04-16_00:41:17.607] [LOG]   >: ACK:OK
[08-04-16_00:41:18.626] [LOG]   >: [99] OPENING   [RSSI:-50][ACK-sent]
[08-04-16_00:41:18.641] [LOG]   ***> Metric name: Status, was: CLOSED, now: OPENING..
:
: ---- Indicates OPENING... good.
:
[08-04-16_00:43:25.509] [LOG]   **** RUNNING SCHEDULED EVENT - nodeId:99 event:garageClose...
[08-04-16_00:43:25.512] [LOG]   The Node: {"_id":99,"updated":1470277741055,"type":"GarageMote","label":"Garage Opener","rssi":50,"metrics":{"Status":{"label":"Status","value":"CLOSED","updated":1470277741055,"pin":1,"graph":1}},"events":{"garageClose":1}}
[08-04-16_00:43:25.517] [LOG]   NODEACTION: {"nodeId":99,"action":"STS"}
[08-04-16_00:43:25.520] [LOG]   ***> Garage is CLOSED
[08-04-16_00:43:25.523] [LOG]   ***> Garage status last updated: Wed Aug 03 2016 22:29:01 GMT-0400 (EDT)
[08-04-16_00:43:25.526] [LOG]   **** SCHEDULING EVENT - nodeId:99 event:garageClose to run in ~0.01hrs
[08-04-16_00:43:25.537] [LOG]   >: ACK:OK
[08-04-16_00:43:26.553] [LOG]   >: [99] OPEN   [RSSI:-50][ACK-sent]
[08-04-16_00:43:26.560] [LOG]   ***> Metric name: Status, was: OPEN, now: OPEN
:
: Huh?  Event still indicates that the door is closed and update was last night.  How can that be?
:
[08-04-16_00:44:25.566] [LOG]   **** RUNNING SCHEDULED EVENT - nodeId:99 event:garageClose...
[08-04-16_00:44:25.570] [LOG]   The Node: {"_id":99,"updated":1470277741055,"type":"GarageMote","label":"Garage Opener","rssi":50,"metrics":{"Status":{"label":"Status","value":"CLOSED","updated":1470277741055,"pin":1,"graph":1}},"events":{"garageClose":1}}
[08-04-16_00:44:25.574] [LOG]   NODEACTION: {"nodeId":99,"action":"STS"}
[08-04-16_00:44:25.578] [LOG]   ***> Garage is CLOSED
[08-04-16_00:44:25.581] [LOG]   ***> Garage status last updated: Wed Aug 03 2016 22:29:01 GMT-0400 (EDT)
[08-04-16_00:44:25.584] [LOG]   **** SCHEDULING EVENT - nodeId:99 event:garageClose to run in ~0.01hrs
[08-04-16_00:44:25.595] [LOG]   >: ACK:OK
[08-04-16_00:44:26.610] [LOG]   >: [99] OPEN   [RSSI:-50][ACK-sent]
[08-04-16_00:44:26.617] [LOG]   ***> Metric name: Status, was: OPEN, now: OPEN
:
: Again... Node properties are out-of-date.  Looks like it's always an old copy of node.
:

Any suggestions?

Thanks,
Alex

[Felix]

One thing I notice is that whenever the scheduled event is triggered, the node values seem to be those as they were when the gateway code was first executed.

Basically it sounds like a javascript clojure, when you register the function you are capturing the context of the variables which get encapsulated and carried into the future, javascript is fun
Let me find some time to examine this a little more and see if I can fix it for you. Sorry for the tardiness...

[n2ppp]

I appreciate that you're taking a look at it Felix.  While I've been a programmer for decades, I'm pretty new to Javascript.  I figured it was something like you suggested.

-Al

[n2ppp]

My first thought after I saw the traces was... I wonder how I can fetch the "real" object at execution time rather than pushing it at schedule time.
-Al

[Felix]

Yes that's what needs to happen, you need to get the node at the time of execution. The passed in "node" is what it was at the time of scheduling, since that time metrics might have changed - in your case the door STATUS metric.
So to fix this, in the scheduled function you need to "get latest", you can do that with something like this:

Code Select Expand

scheduledExecute:function(nodeAtScheduleTime) {
  db.findOne({ _id : nodeAtScheduleTime._id }, function (err, nodeRightNow) {
    if (nodeRightNow)
    {
      //your scheduled/polling logic goes here....
    }
  });
}

Let me know if this works for you...

[n2ppp]

Hi Felix,
  Thanks!  That sounds promising.  What's the best approach to gaining access to 'db' in metrics.js?  Do I need to make another connection to the database, or can I use the same 'db' reference instantiated within gateway.js?  If another Database connection is required within metrics.js, when/where would you suggest that I do that?  Would I be in the same closure situation if it's not done within the scheduled event?  I'm guessing that I would not want to establish the Database connection on the fly for performance reasons, if possible.

- Al

[Felix]

You shouldn't need to since that function is executed from the gateway.js global context.
So all gateway.js variables within these scheduled functions should be available when they execute.
But FWIW I haven't checked this example so let me know if there's any trouble.

[n2ppp]

There won't be an opportunity to work on this until late tonight, the earliest.  I'll definitely let you know how it goes.

Thanks,
Al

[n2ppp]

Hi Felix,
  I tried your suggestion, but unfortunately it seems that db is out of scope...

Code Select Expand

[08-06-16_09:09:28.882] [LOG]   **** RUNNING SCHEDULED EVENT - nodeId:99 event:garageClose...

/home/pi/gateway/metrics.js:146
      db.findOne({ _id : nodeAtScheduleTime._id }, function (err, nodeRightNow
      ^
ReferenceError: db is not defined
    at exports.events.garageClose.scheduledExecute (/home/pi/gateway/metrics.js:146:7)
    at runAndReschedule (/home/pi/gateway/gateway.js:491:3)
    at timer._onTimeout (timers.js:216:16)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)

[Felix]

Hmmmm. OK i need to try this and see how to resolve the db.
A thought I had was that to be 100% sure of what's the status when running the check, is to actually run a message and wait for the door to tell you if it's OPEN.
I'll see what works best. Let me get back to you here ok?
Thanks

[n2ppp]

In the code snippet I sent, I do send a STS request, however I was still stuck with looking at the old node values after.  Not only do I need to know the door position, but I also need to know how long it's been there so that I can delay closure for legitimate opening of the door late at night.  I think it all comes down to getting access to the real node object, or indirectly through a db query.

Your assistance is much appreciated.

Thanks,
Alex

[Felix]

Ok the problem was the db was not global. See the latest changes for this.  You'll need to update gateway.js. This should fix the db error from my earlier code.

Also I added a garagePoll sample event which just retrieves the status and logs it to the clients (same changeset).
Let me know if this works.

[n2ppp]

Felix,
  That's great!  I'll implement your changes when I have some time tonight.  You just gave me an opportunity to learn something about JavaScript.  Many years ago (30+ perhaps), I was taught to avoid global variables, so I generally do unless it's absolutely necessary.  I didn't realize that the syntax for defining a global variable in JavaScript was to simply use the name w/o declaring it with var.  I would have expected that I'd need to declare it with a special directive like 'global' or 'extern', etc.

  I'm curious... why did you introduce a try/catch around the functionToExecute?  Did you experience a problem or did you just recognize the potential for one?

Thanks,
Al

[Felix]

I added the try so that if the scheduled event has some error, it wouldn't crash the whole app, instead it would log it in the console window in the UI, and make it easier to debug that way rather than dig the logs on disk.

[n2ppp]

I agree.  Very nice.  Especially when you consider that "end users" will be writing their own event handlers.  I frequently found that when I introduced a syntactical error into metrics.js, the gateway threw an exception and died.  I usually had to reboot as I didn't know what services I needed to recycle after applying the fix.  It's fairly inconvenient during development :-)

Take care,
Al