Serialize Executor events #1054

rhpijnacker · 2020-01-19T14:06:19Z

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 · 2020-01-22T20:13:20Z

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 · 2020-01-22T21:14:02Z

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 · 2020-01-27T09:31:47Z

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.

rhpijnacker · 2020-03-16T16:14:13Z

src/lib/executors/Executor.ts

-      'error',
-      'log'
-    ].includes(<string>eventName);
+    const needsSeparateNotificationChain =


Instead of singling out coverage, error and log here and calling it needsSeparateNotificationChain, maybe we should name it after the actual events that are part of the test run. E.g. something like isTestLifeCycleEvent. Does that make sense?

codecov-io · 2020-03-16T16:26:14Z

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%)`	⬆️
src/lib/executors/Node.ts	`92.22% <0.00%> (+0.20%)`	⬆️

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 · 2020-03-27T12:26:56Z

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

rhpijnacker · 2020-03-27T14:34:54Z

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 · 2020-03-29T00:48:10Z

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 · 2020-03-29T09:06:58Z

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 · 2020-03-29T18:40:17Z

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 · 2020-03-30T07:11:15Z

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 · 2020-03-30T14:03:04Z

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 · 2020-03-30T20:59:02Z

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 · 2020-03-31T01:08:19Z

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

rhpijnacker · 2020-03-31T10:57:54Z

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 · 2020-04-01T09:46:35Z

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

jason0x43 · 2020-04-01T12:28:06Z

Yes, in 4.8.1, hopefully today at some point.

`Executor#emit` waits for listeners to resolve, which allows Intern to stay in sync with event processing code. However, calls to individual listeners don't need to wait on each other. This can cause event handlers to become interleaved (e.g., a `testStart` handler might be called before a `testEnd` handler for the previous test had been called.) references #1054 resolves #1124

jason0x43 · 2020-04-06T13:07:33Z

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

`Executor#emit` waits for listeners to resolve, which allows Intern to stay in sync with event processing code. However, calls to individual listeners don't need to wait on each other. This can cause event handlers to become interleaved (e.g., a `testStart` handler might be called before a `testEnd` handler for the previous test had been called.) references #1054 resolves #1124

Serialize Executor events

7989044

jason0x43 mentioned this pull request Feb 5, 2020

Intern interactivity #1021

Closed

rhpijnacker added 5 commits March 13, 2020 16:14

Use separate notification chain for coverage, error and log events

c8a7a5a

Small update

e476dd9

Fix build error

715051f

Trigger new build

275e455

IE10,IE11 do not like [].includes()

f9a99b5

rhpijnacker commented Mar 16, 2020

View reviewed changes

jason0x43 force-pushed the 4.x branch from 12de063 to f371a6e Compare April 1, 2020 20:19

jason0x43 closed this Apr 6, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Serialize Executor events #1054

Serialize Executor events #1054

rhpijnacker commented Jan 19, 2020

jason0x43 commented Jan 22, 2020

jason0x43 commented Jan 22, 2020

rhpijnacker commented Jan 27, 2020

rhpijnacker Mar 16, 2020

codecov-io commented Mar 16, 2020 •

edited

jason0x43 commented Mar 27, 2020

rhpijnacker commented Mar 27, 2020

jason0x43 commented Mar 29, 2020

rhpijnacker commented Mar 29, 2020

jason0x43 commented Mar 29, 2020

rhpijnacker commented Mar 30, 2020

jason0x43 commented Mar 30, 2020

rhpijnacker commented Mar 30, 2020

jason0x43 commented Mar 31, 2020

rhpijnacker commented Mar 31, 2020

rhpijnacker commented Apr 1, 2020

jason0x43 commented Apr 1, 2020

jason0x43 commented Apr 6, 2020

Serialize Executor events #1054

Serialize Executor events #1054

Conversation

rhpijnacker commented Jan 19, 2020

jason0x43 commented Jan 22, 2020

jason0x43 commented Jan 22, 2020

rhpijnacker commented Jan 27, 2020

rhpijnacker Mar 16, 2020

Choose a reason for hiding this comment

codecov-io commented Mar 16, 2020 • edited

Codecov Report

jason0x43 commented Mar 27, 2020

rhpijnacker commented Mar 27, 2020

jason0x43 commented Mar 29, 2020

rhpijnacker commented Mar 29, 2020

jason0x43 commented Mar 29, 2020

rhpijnacker commented Mar 30, 2020

jason0x43 commented Mar 30, 2020

rhpijnacker commented Mar 30, 2020

jason0x43 commented Mar 31, 2020

rhpijnacker commented Mar 31, 2020

rhpijnacker commented Apr 1, 2020

jason0x43 commented Apr 1, 2020

jason0x43 commented Apr 6, 2020

codecov-io commented Mar 16, 2020 •

edited