Gateway v8.10.0 released!

[Felix]

You can now check the new features/fixes in the last release(s) here: https://github.com/LowPowerLab/RaspberryPi-Gateway/releases/tag/v8.10

As always:
- make sure to back up your data before you do an upgrade to ensure there is no loss in case something goes wrong
- if updating your Gateway, make sure to read the release notes so you don't miss important update actions you need to take
- report any issues here or submit a PR in github

[ssmall]

Felix,

I recently updated to v8.10.0 and everything is working great except for my implementation of garagePoll that I have defined in the userMetrics directory.  I am saving the state of the node in the scheduled event.  After the update to 8.1.0 I noticed the node state was no longer getting updated properly.  I think I narrowed it down to a change that was made to gateway.js.  It looks like the schedule function is also updating the state of the node on line 635.  This update is overwriting my changes to the node.  Is there anyway for me to make changes to a node without having them overwritten?

Thanks,

-Steve

[Felix]

Steve, thanks for tracking this down, can you please share the code snippets you mentioned?

[ssmall]

The db.update at the end is what is overwritten.  I tested this by commenting out the update starting at line 635 in gateway.js and my garage poll worked as expected.

Here is my code:

Code: [Select]

  garagePoll: { label:'Garage : POLL', icon:'comment', descr:'Poll Garage Status', nextSchedule:function(nodeAtScheduleTime) { return 300000; }, scheduledExecute:function(nodeAtScheduleTime) { db.findOne({ _id : nodeAtScheduleTime._id }, function (err, nodeRightNow) {

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

if (nodeRightNow)
{
  /*just emit a log the status to client(s) */
  console.log('GARAGE POLL STATUS Node Id: ' + nodeRightNow._id + " Status: " + nodeRightNow.metrics['Status'].value);

  if (nodeRightNow.metrics['Status'] &&
      nodeRightNow.metrics['Status'].value == 'OPEN') {

    /* Only automatically close between 9pm and 6am */
    if ((nowDate.getHours() >= 21 || nowDate.getHours() <= 6) && nodeRightNow.metrics['Status'].closeCount < 3) {

      if (nodeRightNow.metrics['Status'].openDate == null) {
        nodeRightNow.metrics['Status'].openDate = nowDate;
        nodeUpdated = true;
      };

      /* Elapsed time in minutes */
      var elapsedTimeMinutes = Math.round(((nowDate - nodeRightNow.metrics['Status'].openDate)) / (60*1000));
      console.log('GARAGE SHOULD BE CLOSED ' + elapsedTimeMinutes);
      console.log('nodeRightNow.metrics[Status].openDate ' + nodeRightNow.metrics['Status'].openDate);

      /* Close the door if open more than 10 minutes */
      if (elapsedTimeMinutes >= 10) {
        sendMessageToNode({nodeId:nodeRightNow._id, action:'CLS'});
        nodeRightNow.metrics['Status'].closeCount++;
        nodeRightNow.metrics['Status'].openDate = null;
        nodeUpdated = true;
      };

      console.log('Close Count: ' + nodeRightNow.metrics['Status'].closeCount);
    };
  };

  if (nowDate.getHours() < 21 && nowDate.getHours() > 6 && nodeRightNow.metrics['Status'].openDate) {
    nodeRightNow.metrics['Status'].openDate = null;
    nodeUpdated = true;
  };

  /* Reset the close count */
  if ((nowDate.getHours() < 21 && nowDate.getHours() > 6 && nodeRightNow.metrics['Status'].closeCount > 0) || nodeRightNow.metrics['Status'].closeCount == null) {
    nodeRightNow.metrics['Status'].closeCount = 0;
    nodeUpdated = true;
  };

  if (nodeUpdated) {
    db.update({ _id: nodeRightNow._id }, { $set : nodeRightNow}, {}, function (err, numReplaced) { console.log('   ['+nodeRightNow._id+'] DB-Updates:' + numReplaced);});
  };
};
});

[Felix]

What are these variables?

nodeRightNow.metrics['Status'].closeCount++;
nodeRightNow.metrics['Status'].openDate = null;

Are they the ones being overwritten? Or what part of the node/metrics is being overwritten/removed?
Do you have a log section that shows the sequence of your code writing what you want to the DB, then the new db.update at line 635 overwriting that?

That new db.update was added to keep track of the events and be able to display info on them in the UI front end.

[ssmall]

I modified the garagePoll event code to incorporate more logging to demonstrate what I am experiencing.  I also changed gateway.js and inserted a console.log right after the db.update on line 639

Code: [Select]

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

if (nodeRightNow)
{
  /*just emit a log the status to client(s) */
  console.log('GARAGE POLL STATUS Node Id: ' + nodeRightNow._id + " Status: " + nodeRightNow.metrics['Status'].value);

  if (nodeRightNow.metrics['Status'] &&
      nodeRightNow.metrics['Status'].value == 'OPEN') {

      console.log('Initial nodeRightNow.metrics[Status].openDate ' + nodeRightNow.metrics['Status'].openDate);

    /* Only automatically close between 9pm and 6am and closeCount < 5 */
    if ((nowDate.getHours() >= 9 || nowDate.getHours() <= 6) && nodeRightNow.metrics['Status'].closeCount < 10) {

      if (nodeRightNow.metrics['Status'].openDate == null) {
        nodeRightNow.metrics['Status'].openDate = nowDate;
        nodeUpdated = true;
      };

      console.log('After assignment nodeRightNow.metrics[Status].openDate ' + nodeRightNow.metrics['Status'].openDate);

      /* Elapsed time in minutes */
      var elapsedTimeMinutes = Math.round(((nowDate - nodeRightNow.metrics['Status'].openDate)) / (60*1000));
      console.log('GARAGE SHOULD BE CLOSED ' + elapsedTimeMinutes);
      console.log('nodeRightNow.metrics[Status].openDate ' + nodeRightNow.metrics['Status'].openDate);

      /* Close the door if open more than 10 minutes */
      if (elapsedTimeMinutes >= 10) {
        sendMessageToNode({nodeId:nodeRightNow._id, action:'CLS'});
        nodeRightNow.metrics['Status'].closeCount++;
        nodeRightNow.metrics['Status'].openDate = null;
        nodeUpdated = true;
      };

      console.log('Close Count: ' + nodeRightNow.metrics['Status'].closeCount);
    };
  };

  /* Reset the openDate to null when the hours are between 7am and 8pm
  if (nowDate.getHours() < 9 && nowDate.getHours() > 6 && nodeRightNow.metrics['Status'].openDate) {
    nodeRightNow.metrics['Status'].openDate = null;
    nodeUpdated = true;
  };

  /* Reset the close count */
  if ((nowDate.getHours() < 9 && nowDate.getHours() > 6 && nodeRightNow.metrics['Status'].closeCount > 0) || nodeRightNow.metrics['Status'].closeCount == null) {
    nodeRightNow.metrics['Status'].closeCount = 0;
    nodeUpdated = true;
  };

  if (nodeUpdated) {
    db.update({ _id: nodeRightNow._id }, { $set : nodeRightNow}, {}, function (err, numReplaced) { console.log('gp:   ['+nodeRightNow._id+'] DB-Updates:' + numReplaced);});
  };

  console.log('After save nodeRightNow.metrics[Status].openDate ' + nodeRightNow.metrics['Status'].openDate);

  db.findOne({ _id : nodeAtScheduleTime._id }, function (err, findNode) {
    console.log('After find findNode.metrics[Status].openDate ' + findNode.metrics['Status'].openDate);
  });
};
});
 } }
};

Here is the output from the garagePoll:

[2017-10-08T17:14:43.947Z] (sys) Starting
[10-08-17_12:14:51.307] [LOG]   **** SCHEDULING EVENT - nodeId:11 event:garagePoll to run in ~1m
[10-08-17_12:14:51.320] [LOG]   gateway dbNode.metrics[Status].openDate = null
[10-08-17_12:14:51.347] [LOG]   gw:   [11] DB-Updates:1
[10-08-17_12:14:54.409] [INFO]  AUTHORIZING CONNECTION FROM 127.0.0.1:33644
[10-08-17_12:14:54.424] [INFO]  NEW CONNECTION FROM 10.12.20.1
[10-08-17_12:15:51.311] [LOG]   **** RUNNING SCHEDULED EVENT - nodeId:11 event:garagePoll...
[10-08-17_12:15:51.315] [LOG]   **** SCHEDULING EVENT - nodeId:11 event:garagePoll to run in ~1m
[10-08-17_12:15:51.321] [LOG]   GARAGE POLL STATUS Node Id: 11 Status: OPEN
[10-08-17_12:15:51.323] [LOG]   Initial nodeRightNow.metrics[Status].openDate null
[10-08-17_12:15:51.324] [LOG]   After assignment nodeRightNow.metrics[Status].openDate Sun Oct 08 2017 12:15:51 GMT-0500 (CDT)
[10-08-17_12:15:51.325] [LOG]   GARAGE SHOULD BE CLOSED 0
[10-08-17_12:15:51.327] [LOG]   nodeRightNow.metrics[Status].openDate Sun Oct 08 2017 12:15:51 GMT-0500 (CDT)
[10-08-17_12:15:51.328] [LOG]   Close Count: 4
[10-08-17_12:15:51.330] [LOG]   After save nodeRightNow.metrics[Status].openDate Sun Oct 08 2017 12:15:51 GMT-0500 (CDT)
[10-08-17_12:15:51.333] [LOG]   gateway dbNode.metrics[Status].openDate = null
[10-08-17_12:15:51.344] [LOG]   gp:   [11] DB-Updates:1
[10-08-17_12:15:51.348] [LOG]   After find findNode.metrics[Status].openDate Sun Oct 08 2017 12:15:51 GMT-0500 (CDT)
[10-08-17_12:15:51.354] [LOG]   gw:   [11] DB-Updates:1

[10-08-17_12:16:51.317] [LOG]   **** RUNNING SCHEDULED EVENT - nodeId:11 event:garagePoll...
[10-08-17_12:16:51.319] [LOG]   **** SCHEDULING EVENT - nodeId:11 event:garagePoll to run in ~1m
[10-08-17_12:16:51.332] [LOG]   GARAGE POLL STATUS Node Id: 11 Status: OPEN
[10-08-17_12:16:51.334] [LOG]   Initial nodeRightNow.metrics[Status].openDate null
[10-08-17_12:16:51.335] [LOG]   After assignment nodeRightNow.metrics[Status].openDate Sun Oct 08 2017 12:16:51 GMT-0500 (CDT)
[10-08-17_12:16:51.338] [LOG]   GARAGE SHOULD BE CLOSED 0
[10-08-17_12:16:51.340] [LOG]   nodeRightNow.metrics[Status].openDate Sun Oct 08 2017 12:16:51 GMT-0500 (CDT)
[10-08-17_12:16:51.342] [LOG]   Close Count: 4
[10-08-17_12:16:51.343] [LOG]   After save nodeRightNow.metrics[Status].openDate Sun Oct 08 2017 12:16:51 GMT-0500 (CDT)
[10-08-17_12:16:51.346] [LOG]   gateway dbNode.metrics[Status].openDate = null
[10-08-17_12:16:51.357] [LOG]   gp:   [11] DB-Updates:1
[10-08-17_12:16:51.360] [LOG]   After find findNode.metrics[Status].openDate Sun Oct 08 2017 12:16:51 GMT-0500 (CDT)
[10-08-17_12:16:51.367] [LOG]   gw:   [11] DB-Updates:1

At the start of the garagePoll event the OpenDate is always null even though the openDate is successfully updated at the end of the code.  closeCount is also not updated as well, but I am not showing it for clarity.  gp: is the console.log from when garagePoll updates the node and gw: is  the console.log from when the gateway updates the node.

[sparky]

Felix,

Since changing to 8.10 I've been having an issue with some events turning off by themselves.  I'm still trying to figure it out but wondered if you had experienced this.

Before going to bed I look to see that all 3 events are on (green) and when I wake up 2 of them are off.  I check the log and don't see any "REMOVING SCHEDULED EVENT - nodeId:4" entries that one would normally see.

My userMetrics for the doorbell has not changed since changing from 8.9 to 8.10;

Code: [Select]

 //Door Bell Mote
  doorbellSound : { label:'Doorbell : Sound', icon:'audio', descr:'Play sound when doorbell rings', serverExecute:function(node) { if (node.metrics['RING'] && node.metrics['RING'].value == 'RING' && (Date.now() - new Date(node.metrics['RING'].updated).getTime() < 2000)) { io.sockets.emit('PLAYSOUND', 'sounds/doorbell.wav'); }; } },
  //doorbellSMS : { label:'Doorbell : SMS', icon:'comment', descr:'Send SMS when Doorbell button is pressed', serverExecute:function(node) { if (node.metrics['RING'] && node.metrics['RING'].value == 'RING' && (Date.now() - new Date(node.metrics['RING'].updated).getTime() < 2000)) { sendSMS('DOORBELL', 'DOORBELL WAS RINGED: [' + node._id + '] ' + node.label + ' @ ' + new Date().toLocaleTimeString()); }; } },
  doorbellEmail : { label:'Doorbell : Email', icon:'mail', descr:'Send Email when Doorbell button is pressed', serverExecute:function(node) { if (node.metrics['RING'] && node.metrics['RING'].value == 'RING' && (Date.now() - new Date(node.metrics['RING'].updated).getTime() < 2000)) { sendEmail('DOORBELL', 'DOORBELL WAS RINGED: [' + node._id + '] ' + node.label + ' @ ' + new Date().toLocaleTimeString()); }; } },
  doorbellON_AM : { label:'Doorbell ON at 6:30AM!', icon:'clock', descr:'Enable doorbell every morning', nextSchedule:function(node) { return exports.timeoutOffset(6,30); }, scheduledExecute:function(node) { sendMessageToNode({nodeId:node._id, action:'BELL:1'}); } },
  doorbellOFF_PM : { label:'Doorbell OFF at 8:00PM!', icon:'clock', descr:'Disable doorbell every evening', nextSchedule:function(node) { return exports.timeoutOffset(20,00); }, scheduledExecute:function(node) { sendMessageToNode({nodeId:node._id, action:'BELL:0'}); } },

  doorbellSMSLimiter : { label:'Doorbell : SMS Limited 4/seconds', icon:'comment', descr:'Send SMS when RING is detected, once per 4 seconds', 
    serverExecute:function(node) { 
      if (node.metrics['RING'] && node.metrics['RING'].value == 'RING' && (Date.now() - node.metrics['RING'].updated < 2000)) /*check if RING metric exists and value is RING, received less than 2s ago*/
      {
        var approveSMS = false;
        if (node.metrics['RING'].lastSMS) /*check if lastSMS value is not NULL ... */
        {
          if (Date.now() - node.metrics['RING'].lastSMS > 4000) /*check if lastSMS timestamp is more than 4 seconds ago*/
          {
            approveSMS = true;
          }
        }
        else
        {
          approveSMS = true;
        }
        
        if (approveSMS)
        {
          node.metrics['RING'].lastSMS = Date.now();
          sendSMS('DOORBELL', 'DOORBELL WAS RINGED: [' + node._id + ':' + node.label + '] @ ' + new Date().toLocaleTimeString());  // line below was un-commented due to getting double DB-Updates entries in log
          //db.update({ _id: node._id }, { $set : node}, {}, function (err, numReplaced) { console.log('   ['+node._id+'] DB-Updates:' + numReplaced);}); /*save lastSMS timestamp to DB*/
        }
        else console.log('   ['+node._id+'] RING SMS skipped.');
    

Thanks in advance!!

[Felix]

Thanks for the extra details, I will try to look into these issues as soon as I have some time.

[sparky]

additional info;

I created the bell on/off event in the metrics.js file but used your "send SMS" event to see what happens.  See the sequence of photos below.  Instead of the event just being turned off they are removed from the node.

[Felix]

I must say that is very unusual.
Are you sure your custom code is sound and the update is complete?
Any errors in the gateyway.sys.log or in the browser DevTools?

[sparky]

Well the custom code has been working flawlessly since 8.8 or before.

Not sure if the install is complete but all I can say is I haven't had any other issues except this one.

The update was installed using these steps;

•Copy the contents of this directory in  /home/pi/gateway
•run  npm install  in the  /home/pi/gateway  directory to install all node dependencies
•Adjust any email/password/SMS settings in  settings.json5

No errors in the gateway.sys.log in fact the log doesn't even show the event were removed as mentioned before.

Not sure what DevTools to use to check for errors.

Thanks

[Felix]

sparky,
F12 brings DevTools is the browser (DevTools in chrome, Firebug in Firefox).
It's where you can see the actual DOM of your page, see the traffic and requests the page does, all the scripts and any errors, you can add breakpoints in javascript to step through the code etc.

Anyway I will need to find some time to look into these problems.
Since it's not happening on my end, and nobody else is developing and fixing bugs, it may be a while. I will need to be able to reproduce the problem in my setup to come up with a fix.
Thanks for the details so far.

[sparky]

Well I guess I'm not surprised it's not happening at your end but I posted just in case it was something that was missed.

I don't expect you to waste any more time fixing something that I did wrong.  I know you have a lot on your plate and I appreciate the time you spent thus far.

Take care!

[sparky]

Although it doesn't make sense to me its appears that I fixed it.  Been running great for a couple days now!

[rd909]

I'm not sure what the problem is yet, but I am also experiencing event issues since 8.10.0. When I add an event, it disappears. If I remove the default "garage poll" event to the garagemote, it comes back on its own. Somehow I have been able to get an event added to my sonarmote, but the garagemote is giving me fits. Has anyone found the cause for this yet? The earlier posts don't seem definitive.