Serialize Executor events

[rhpijnacker]

Individual calls to emit(<event>) currently start a new asynchronous promise chain. In the intern-cucumber plugin, this causes overlapping handling of the events, since the suiteEnd handling is not yet finished before the new suiteStart event is triggered. This problem is easily fixed by chaining this suiteStart event at the end of the suiteEnd chain.

[jason0x43]

Some of the timeout issues may be happening because emit will end up waiting on itself to resolve if it has to handle an error.

[jason0x43]

Actually, it looks like the root problem is the coverage event that gets emitted when the top-level suite is finished, which ends up calling emit from emit.

[rhpijnacker]

When I tweak this._notifications during the re-entrant emit of coverage to a new instance, and put it back afterward, the deadlock is broken. So, I think you were right about the root problem. However, a lot of other test cases now start failing :( . Have to dig deeper into this.

[codecov-io]

Codecov Report

Merging #1054 into 4.x will increase coverage by 0.05%. The diff coverage is 100.00%.

@@            Coverage Diff             @@
##              4.x    #1054      +/-   ##
==========================================
+ Coverage   67.01%   67.07%   +0.05%     
==========================================
  Files          60       60              
  Lines        4918     4923       +5     
  Branches     1101     1104       +3     
==========================================
+ Hits         3296     3302       +6     
+ Misses       1622     1621       -1     

Impacted Files	Coverage Δ
src/lib/executors/Executor.ts	91.04% <100.00%> (+0.13%)	:arrow_up:
src/lib/executors/Node.ts	92.22% <0.00%> (+0.20%)	:arrow_up:

---

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update d5e45d6...f9a99b5. Read the comment docs.

[jason0x43]

I haven't forgotten this, just haven't had a chance to look at it lately...

[rhpijnacker]

Thanks for letting me know. In the end it is not actually a big change. If you could have a quick look to see if you want the variable name changed, then at least I could make that work.

[jason0x43]

So, the PR does seem like it would prevent the deadlock from recursive emit calls. However...in looking at the event emitting and handling code, I seem to have forgotten exactly why the original serialization problem is occurring (the downside of long breaks while solving a problem).

I mean, emit doesn't ensure that messages are serialized, but the code that calls emit does (or at least it should). All the calls to emit during a test run should wait for emit calls to resolve before proceeding, e.g. the suite's internal "start" call:

const start = () => {
  return this.executor.emit('suiteStart', this).then(function () {
    startTime = Date.now();
  });
};

...

  task = this.publishAfterSetup
    ? before().then(start)
    : start().then(before);

  return task.then(() => {
    ...
  }).finally(() => (this.publishAfterSetup ? end() : after()));

In Suite, the task chain is basically return executor.emit('suiteStart').then(() => { run test }).finally(() => executor.emit('suiteEnd')), and the next suite shouldn't start until the current suite's run task settles. However, event handling code could still overlap if it's not returning a Promise, because Intern can only wait for handlers to finish if they return Promises.

[rhpijnacker]

The problem occurs in the intern-cucumber integration, where the event runner is using Cucumber.js's runtime to drive the tests. This means it can't ensure that the emit-calls are completely handled before a new test step is started.

An alternative would be try and solve it in the intern-cucumber integration code. I tried this as the first step, but I do not remember exactly why that did not work anymore, maybe I just did not understand it well enough before. (At least I wasn't aware that there was a requirement to wait for the emit to finish before starting the next step. I'm afraid that will be near impossible for this integration. Come to think of it, that will screw up the elapsed time recording :( .)

This PR fixes the problem in a way that at least the emit calls will be handled in the right order, ensuring that the reporters work correctly for the intern-cucumber integration.

[jason0x43]

The problem occurs in the intern-cucumber integration, where the event runner is using Cucumber.js's runtime to drive the tests.

Ah, that's right, because it's Cucumber causing the events to be emitted rather than the Intern test runner.

An alternative would be try and solve it in the intern-cucumber integration code.

What, specifically, is the problem that needs to be solved? I mean, intern-cucumber emits events, but it doesn't look like it's listening to any Intern events, so why is Intern's event-handling behavior an issue? The Cucumber engine itself doesn't wait for event handlers to complete, so a test-case-started event could be emitted before the previous test-case-finished handler had finished doing whatever it was doing. Is reporter output getting messed up because a new testStart might be emitted before the previous testEnd is finished processing? We may be better off fixing the issue in other places in Intern rather than Executor#emit.

At least I wasn't aware that there was a requirement to wait for the emit to finish before starting the next step.

It's not necessarily a requirement, but it's how Intern's test runner behaves. Code can wait for events to resolve, or not. Intern's test runner does wait for them, because it ensures that a remote test runner stays in sync with a local test runner (if desired), and can allow errors in event handlers to affect the testing process.

Come to think of it, that will screw up the elapsed time recording

Well... that may already be an issue. For example, intern-cucumber's suiteStart time is recorded in a test-run-started handler, but after Intern's suiteStart event has been processed. The time between test-run-started firing and suiteStart resolving could be arbitrarily long.

Timing is a good point to bring up, and one I hadn't initially considered. If we make event emits synchronous with each other, rather than having them execute immediately when code calls emit, then any code listening to Intern events for timing information will be broken.

[rhpijnacker]

What, specifically, is the problem that needs to be solved? ... Is reporter output getting messed up because a new testStart might be emitted before the previous testEnd is finished processing?

Exactly this is what is happening. When emitting the testEnd event, Intern will trigger the various event handlers and chain them to do their business in sequence. Before this chain is finished, Cucumber will start the next test, causing a testStart event, which will cause a separate event handler chain to be created. Because these chains are separate, it can (and does) happen that some reporters will get to handle the testStart event before they even saw the testEnd event. This causes confusing grouping in e.g. the console and html loggers.

The PR change causes the new testStart chain to be appended to the existing testEnd chain, which ensures that the reporters handle the events in the right order.

At least I wasn't aware that there was a requirement to wait for the emit to finish before starting the next step.

It's not necessarily a requirement, but it's how Intern's test runner behaves.

... and because of that the reporters are able to do their job correctly. If you do not strictly consider it a requirement, then how do you propose we ensure that the reporters get the events in the proper order?

The time between test-run-started firing and suiteStart resolving could be arbitrarily long.

Indeed. This means I should revisit this and probably put the timestamp handling code outside the Intern event handling chains (i.e. before emitting the testStart event, instead of at the end of the chain). This might pollute the timespans with some reporting activity, though...

Timing is a good point to bring up, and one I hadn't initially considered. If we make event emits synchronous with each other, rather than having them execute immediately when code calls emit, then any code listening to Intern events for timing information will be broken.

I'm not exactly sure what you mean with "if we make event emits synchronous with each other". Currently, an event handler chain is created, which -- depending on what the various reporters do -- might also be arbitrarily long than thus break any code listening to Intern events for timing information.

[jason0x43]

how do you propose we ensure that the reporters get the events in the proper order?

The problem is that calls to individual event listeners are being chained. This means that any given listener may not be called when an event is emitted, but rather after all previous listeners have finished processing. The delays due to chained listener calls are what allows listener calls to become interleaved between emit calls.

      for (const listener of listeners) {
        notifications = notifications
          .then(() => Task.resolve(listener(data)))
          .then(handleErrorEvent)
          .catch(handleListenerError);
      }

      // ...

      return notifications;

Instead of chaining the listener(data) calls, all listeners should be called at once, and those calls should be wrapped in a Promise.all. That way calls to emit will still resolve only after all listeners have finished, but listeners won't have to wait on each other.

      const notifications = [];
      for (const listener of listeners) {
        notifications.push(
          Task.resolve(listener(data))
            .then(handleErrorEvent)
            .catch(handleListenerError)
        );
      }

      // ...

      return Promise.all(notifications);

I'm not exactly sure what you mean with "if we make event emits synchronous with each other".

I mean, event listener calls should be synchronous with when events are emitted. When a test fires a testStarted event, all listeners should be notified at that time. Currently, only the first listener is actually notified right when an event is fired, and other listeners are notified later (after any previous listeners have finished). That means that event listeners aren't guaranteed to be called when an event actually occurs. This will be even more of an issue if we serialize all the listener calls (not just the calls in a single emit call, which is what happens now), because even the first listener may no longer be called when an event actually happens; it will be called after all previously emitted events have been handled.

[rhpijnacker]

Ah, ok. I see what you mean now. Is this a change that you want me to make, or do you plan to do this yourself (since you've basically provided the code already)?

[jason0x43]

I pushed a potential solution to an immediate-events branch. Could you give that a try and see if it helps?

[rhpijnacker]

Ran it against our full suite of tests and could not find anything grouped incorrectly. So, it looks like your changes work fine! Thanks

[rhpijnacker]

Are you planning to make this available as 4.8.1 (or 4.9)?

[jason0x43]

Yes, in 4.8.1, hopefully today at some point.

[jason0x43]

Closing this as it was resolved by the fix for #1124