[BUG] Listeners seem to not act on events sometimes

[thyttan]

Background

The widgets widbtstates and widbt_notify have/had problems where the connection state change did not trigger a redraw of the widget. Making it so the widget could be out of sync with the actual state. I.e. showing disconnected while the watch is actually connected and vice versa. Making me suspicious something is breaking the emit/listener chain.

Recently something similar cropped up for the drained app as well. It seemed its listener function for the charging event would not run when charging was initiated thus not setting a interval that's supposed to return the watch to normal operations when the charge goes above a threshold.

drained: handle missed "changing" events #4188
widbtstates: sync on draw() #4141
widbt_notify: redraw widget on NRF dis-/connect #3735

Possibly related other issues:
removeListener while executing events stops subsequent listeners from executing #2151
Obj.on/emit should always allocate an array #2559

Test script

I've run the following test script with a TEST_COUNT of 500 and have not seen it miss events tested this way.

 // Script to try and see if acting on events are sometimes missed.

let obj = {};
let i=0;
const TEST_COUNT = 10;
let last_e = -1;
let isEventsMissed = false;
const PRINT_EVERY_EVENT = true;

obj.on("test", (e, type)=>{
  if (PRINT_EVERY_EVENT) print("acting on test event " + e + " ("+type+")");
  if (e !== last_e+1) {
    print("\n missed events before event " + e);
    isEventsMissed = true;
  }
  last_e = e;
});

print("\n test in for loop started:");

for (i;i<TEST_COUNT;i++) {
  if (PRINT_EVERY_EVENT) print("emitting test event " + i);
  obj.emit("test", i, "for-loop");
}

setTimeout(()=>{
  print("\n\n test in interval started:");
  let interval = setInterval(()=>{
    if (PRINT_EVERY_EVENT) print("emitting test event " + i);
    obj.emit("test", i, "interval");
    i++;
    if (i > 2*TEST_COUNT-1) {
      clearInterval(interval);
    }
  },0);

},0);

setTimeout(()=>{
  if (isEventsMissed) {
    print("\nSeems like some events were missed");
  } else {
    print("\nSeems like no events were missed");
  }
},1000);

/* Resulting output running from storage:

 ____                 _
|  __|___ ___ ___ _ _|_|___ ___
|  __|_ -| . |  _| | | |   | . |
|____|___|  _|_| |___|_|_|_|___|
         |_| espruino.com
 2v29.26 (c) 2025 G.Williams

 test in for loop started:
emitting test event 0
emitting test event 1
emitting test event 2
emitting test event 3
emitting test event 4
emitting test event 5
emitting test event 6
emitting test event 7
emitting test event 8
emitting test event 9


 test in interval started:
acting on test event 0 (for-loop)
acting on test event 1 (for-loop)
acting on test event 2 (for-loop)
acting on test event 3 (for-loop)
acting on test event 4 (for-loop)
acting on test event 5 (for-loop)
acting on test event 6 (for-loop)
acting on test event 7 (for-loop)
acting on test event 8 (for-loop)
acting on test event 9 (for-loop)
emitting test event 10
acting on test event 10 (interval)
emitting test event 11
acting on test event 11 (interval)
emitting test event 12
acting on test event 12 (interval)
emitting test event 13
acting on test event 13 (interval)
emitting test event 14
acting on test event 14 (interval)
emitting test event 15
acting on test event 15 (interval)
emitting test event 16
acting on test event 16 (interval)
emitting test event 17
acting on test event 17 (interval)
emitting test event 18
acting on test event 18 (interval)
emitting test event 19
acting on test event 19 (interval)

Seems like no events were missed
>

*/

/* Resulting output running from RAM:

 ____                 _
|  __|___ ___ ___ _ _|_|___ ___
|  __|_ -| . |  _| | | |   | . |
|____|___|  _|_| |___|_|_|_|___|
         |_| espruino.com
 2v29.26 (c) 2025 G.Williams
>

 test in for loop started:
emitting test event 0
emitting test event 1
emitting test event 2
emitting test event 3
emitting test event 4
emitting test event 5
emitting test event 6
emitting test event 7
emitting test event 8
emitting test event 9
acting on test event 0 (for-loop)
acting on test event 1 (for-loop)
acting on test event 2 (for-loop)
acting on test event 3 (for-loop)
acting on test event 4 (for-loop)
acting on test event 5 (for-loop)
acting on test event 6 (for-loop)
acting on test event 7 (for-loop)
acting on test event 8 (for-loop)
acting on test event 9 (for-loop)


 test in interval started:
emitting test event 10
acting on test event 10 (interval)
emitting test event 11
acting on test event 11 (interval)
emitting test event 12
acting on test event 12 (interval)
emitting test event 13
acting on test event 13 (interval)
emitting test event 14
acting on test event 14 (interval)
emitting test event 15
acting on test event 15 (interval)
emitting test event 16
acting on test event 16 (interval)
emitting test event 17
acting on test event 17 (interval)
emitting test event 18
acting on test event 18 (interval)
emitting test event 19
acting on test event 19 (interval)

Seems like no events were missed
> 

*/

[gfwilliams]

So you're saying that this appears to happen in the watch, but you can't actually reproduce it with the test, and it doesn't happen in a reproducable manner?

It'd really help if we could find a way to reproduce reliably.

The event handling is pretty simple and has been around for years - I'd be inclined to believe it's working as-expected. About the only time I can imagine it might fail is if memory was so low that events couldn't be queued, or an event at some point earlier in execution threw an Exception.

Is it possible that something else that's running on the watch event handler is calling E.stopEventPropagation and so stopping the events after it from being executed? Maybe you could try E.stopEventPropagation=function() { print("stopEventPropagation"); } and see if that helps?

Without looking too closely I guess there's a chance that E.stopEventPropagation called outside of an event handler could cause issues, but replacing the function with print might help to narrow that down

[thyttan]

So you're saying that this appears to happen in the watch, but you can't actually reproduce it with the test, and it doesn't happen in a reproducable manner?

The bt indicator widget thing happens somewhat frequently - I'll try to make it reproducible or semi-reproducible when I get the time. 👍

The event handling is pretty simple and has been around for years - I'd be inclined to believe it's working as-expected. About the only time I can imagine it might fail is if memory was so low that events couldn't be queued, or an event at some point earlier in execution threw an Exception.

Is it possible that something else that's running on the watch event handler is calling E.stopEventPropagation and so stopping the events after it from being executed? Maybe you could try E.stopEventPropagation=function() { print("stopEventPropagation"); } and see if that helps?

Without looking too closely I guess there's a chance that E.stopEventPropagation called outside of an event handler could cause issues, but replacing the function with print might help to narrow that down

Thanks for the tips. I'll try to use them when I take a look next time.

Tagging @bobrippling if you find Gordon's tips useful as well.

[bobrippling]

Thanks! Yeah I've had no joy reproducing it, the drained one is hard as it only happens once the battery is low, and the widgets ones don't seem to emit any errors to the error file either. A difficult one