setTimeout big issue - Puck.js at 2.04

[espruino-discuss]

Posted at 2020-05-25 by SergeP

I still try to update my greenhouse controller. It worked at v1.92 and now it is with 2.04
I've found that it begins planned sequences at incorrect time. Fully incorrect. I've just made the check:
I've started a few setTimeouts, get dump(), then have disconnected, have waited about 10 or 12 minutes and get dump() again.
Here is the results of first dump()

setTimeout(function (s) {return console.log(s)}, 6880496.76513671875); // 3
setTimeout(startWatering, 3308897.216796875); // 4
setTimeout(startWatering, 3308899.169921875); // 5
setTimeout(startWatering, 3308901.18408203125); // 6

And second one

setTimeout(function (s) {return console.log(s)}, 6772275.60424804687); // 3
setTimeout(startWatering, 3200676.05590820312); // 4
setTimeout(startWatering, 3200678.00903320312); // 5
setTimeout(startWatering, 3200680.02319335937); // 6

As you can calculate, Puck.js thinks that I was away only about 1 or 2 minutes.
That is really problem for my greenhouse.
Is it a major bug or new feature (may be some kind of deepsleep which I should turn off)?

[espruino-discuss]

Posted at 2020-05-25 by SergeP

I've just checked that getTime() works correctly at the same time.

[espruino-discuss]

Posted at 2020-05-25 by SergeP

I have checked the same on cleaned Puck.js. And it works. So I will try to find when it happens.

[espruino-discuss]

Posted at 2020-05-25 by SergeP

At my greenhouse system it does not work. I see something like this:

>getTime()
=1282.59722900390
>dump()
setTimeout(function (s) {return console.log(s)}, 6869723.54125976562); // 3
.................. after a few minutes
>getTime()
=2236.14056396484
>dump()
setTimeout(function (s) {return console.log(s)}, 6712184.47875976562); // 3

SetTimeout is only a part of code in dump, of course. But I add the timeout manually from console, so other code do not interact with the timeout.

[gfwilliams]

Posted at 2020-05-26 by @gfwilliams

That's really odd - so you're saying that the timeout value reported in setTimeout isn't decrementing fast enough? But it works on a 'clean' Puck.js, just not with your code?

If you're waiting 'a few minutes' then 6869723.54125976562-6712184.47875976562=157539.06249999906 - so 160ish seconds, which sounds about right.

By contrast, 2236-1282 from getTime is around 15 minutes.

Honestly I'm not too sure what could be the issue here. As far as I know nothing has changed in the setTimeout code in years. Is there any way you could start pulling code out of your greenhouse controller until you can get it down to a level that I could look at it and reproduce it?

[espruino-discuss]

Posted at 2020-05-26 by SergeP

Full code of my greenhouse controller can work at standalone Puck.js. I can add it here. But it is too complex, I think. So I've cropped it. Now it is small part of code but still has the effect in setTimeout. I've just test it and results are: 1266 seconds by getTime() while only 139 with setTimeout in dump(). So the code is here. Last setTimeout is for the test.
I've observed that it depends on setInterval (there is only one in my code) which is calles NRF.setAdvertizing(). If I remove setInterval, setTimeout looks like work correctly (I'm not sure). If I do not disconnect from device in EspruinoWebIDE It may be works correctly, too.

Upd: I can not upload file (do not know why) so code is below:

var Day = true;

// usage types: 0 - unused, 1 - watering, 2 - anti-overheat fog
// wateringTime is in minutes (after start), while startHour is in hours after dawn
var channels = [
  {wateringStartedAt: 0 },
  {wateringStartedAt: 0 },
  {wateringStartedAt: 0 },
  {wateringStartedAt: 0 },
  {wateringStartedAt: 0 },
  {wateringStartedAt: 0 },
];


var VArr = new Uint8Array(4);

let updatePending = false;
function updateAdv() {
  if (!updatePending) {
    updatePending = true;
    setTimeout(function () {
      updatePending = false;
      let pack = 0;
      for (let i = 0; i < channels.length; i++)
        pack = (pack << 1) + (channels[channels.length - 1 - i].wateringStartedAt ? 1 : 0);
      VArr[2] = (Day << 7) + pack;
      VArr[3] = 255;
      NRF.setAdvertising({
        0x1813: VArr
      }, {
        name: "Green", // The name of the device
        showName: true, // include full name, or nothing
        interval: 600 // Advertising interval in msec
      });
    }, 0);
  }
}
NRF.setTxPower(4);
setInterval(function () {
  VArr[1] = Puck.light() * 255;
  updateAdv();
}, 120000);


setTimeout((s)=>console.log(s),7200000,"wwee11");

[gfwilliams]

Posted at 2020-05-27 by @gfwilliams

Thanks for stripping this down...

I just stripped it right back and there's no problem. It turns out the issue is how timers are handled when a timer is added within a timer callback.

Try this:

setInterval(function () {
  if (BTN1.read()) setTimeout(function(){},0);
}, 100);
setInterval(function() {
  digitalPulse(LED1,1,10);
}, 1000);

LED1 should flash every second. However if you press BTN1 it'll just stop!

I've filed an issue for this at espruino/Espruino#1829 and I'll try and get it fixed ASAP.

However you could fix it as-is by removing your setTimeout(function () { .... }, 0) line - I'm not entirely sure about the reasoning for that anyway?

[espruino-discuss]

Posted at 2020-05-27 by @allObjects

the issue is how timers are handled when a timer is added within a timer callback.

...ooops... I used that all over the place... not just for timing, also for 'breaking the JS thread'... - so have to go back and validate... (for example SW Button... etc.)

[espruino-discuss]

Posted at 2020-05-27 by SergeP

I'm not entirely sure about the reasoning for that anyway?

It's just to make an update of full BLE advertizing, while there are many calls of updateAdv in many functions. So I can call updateAdv in every place where I change some part of advertizing data but actually I have only one update where all these fields are changed. It is update aggregator.
I use similar code in many places. For example, in my big clock there may be few additional info, and it is resonable to update screen one time, after all data is redrawed to screenbuffer.
Ok, I'll try to turn it off and check.

[espruino-discuss]

Posted at 2020-05-27 by SergeP

Yes. The stripped version works when I remove the setTimeout. But my full version is based on Timeouts from Timeouts from Timeouts etc... Usually I do not ever know if some function is called from timeout or not.
Is it possible to use timeouts from timeouts safely? Or the only way is to wait for update? I have only one setInterval in the program and it can be removed easily, if that is significant.

[gfwilliams]

Posted at 2020-05-27 by @gfwilliams

Is it possible to use timeouts from timeouts safely?

Sadly with 2vxx (and maybe earlier) it seems that you can end up with your timeouts not being called on time. You could use events instead of setTimeout(0)...

 E.on('update', function() {
  updatePending = false; 
  //...
});

E.emit('update');

But I actually just fixed this - so in 2v06 when released (or a cutting edge build) you'll be fine

[espruino-discuss]

Posted at 2020-05-27 by SergeP

I've got cutting edge v2.05.107 and it looks like working! Wow!
Tomorrow I'll check it in my greenhouse.

[espruino-discuss]

Posted at 2020-05-28 by SergeP

It works! Wonderful! Thank you, @gfwilliams!
I choose good time for upgrade :) I've used v1.92 without the timeout bug and now I am using pre-v2.06, again without the bug. SPI is now working with TLE94112, too.
Now I still have 2 problems only: temperature is readed not every time by OneWire (about 1 reading of 100 is unsuccessful, while it was very stable at v1.92, I've never seen that last 3 years, or about 1 500 000 x 4 reads) and EspruinoHub often does something strange (but I have another topic to discuss that). And, of course, unstable connection in EspruinoWebIDE: usually I should restart IDE server 2 or 3 times before I can connect to device, but the problem is development stage only, so it is not so significant.

[gfwilliams]

Posted at 2020-05-29 by @gfwilliams

Great! As for OneWire, I'm surprised there is any difference as I didn't think much changed there.

But basically the issue is that you're always meant to give the Bluetooth stack priority. I think at some point in the past I was disabling it for OneWire, and that made Espruino unstable and it could spontaneously reboot.

I decided it was better to just have OneWire fail every so often (which is easy to recover from) rather than to have a reboot :)

I looked just now and there may be a hacky solution: espruino/Espruino#1831

However you're using OneWire for a DS18B20? http://www.espruino.com/DS18B20

If so you can just do:

function getTempReliable(callback) {
  sensor.getTemp(function (temp) {
    if (temp===null) getTempReliable(callback);
    else callback(temp);
  });
}

Note that you may also need to do similar stuff at boot time (when you're finding the address of the OneWire sensor to use) as occasionally it may not find it.

Or... you could use NRF.sleep() to disable advertising while you read the temperature and NRF.wake after() - but IMO the retry is safer