Get rid of 500ms timeout

Replaces the hardcoded FIXME sleep(500ms) timeout in each test.

Instead, we track any pending `PerformanceObserver`s and wait for
them to disconnect before continuing.

This doesn't magically make the tests run faster, in a way it just
hides the timeout, because the implementation actually still waits
for `OBSERVER_WAIT_TIME_MS` (300ms) internally before disconnecting
the PO.

However, this makes the tests follow the actual real world behavior
and they are only as slow as the actual behavior IRL.

IMO, the timeout isn't actually necessary IF we have PO available,
and that can be removed in a future refactor. When we address that,
most of the tests will automatically run faster.

Author: chancancode

experimental/packages/opentelemetry-instrumentation-fetch/test/fetch.test.ts

@@ -55,6 +55,9 @@ import {
 import * as msw from 'msw';
 import { setupWorker } from 'msw/browser';
 
+// This should match the unexported constant with the same name in fetch.ts
+const OBSERVER_WAIT_TIME_MS = 300;
+
 class DummySpanExporter implements tracing.SpanExporter {
   readonly exported: tracing.ReadableSpan[][] = [];
 
@@ -91,6 +94,34 @@ const ORIGIN = location.origin;
 // "localhost:9876"
 const ORIGIN_HOST = new URL(ORIGIN).host;
 
+interface Resolvers<T> {
+  promise: Promise<T>;
+  resolve: (value: T) => void;
+  reject: (reason: any) => void;
+}
+
+// Use Promise.withResolvers when we can
+function withResolvers<T>(): Resolvers<T> {
+  let resolve: (value: T) => void;
+  let reject: (reason: any) => void;
+  let promise = new Promise<T>((res, rej) => {
+    resolve = res;
+    reject = rej;
+  });
+
+  return {
+    promise,
+    resolve: resolve!,
+    reject: reject!,
+  };
+}
+
+function waitFor(timeout: number): Promise<void> {
+  return new Promise(resolve => {
+    setTimeout(resolve, timeout);
+  });
+}
+
 describe('fetch', () => {
   let workerStarted = false;
 
@@ -105,13 +136,74 @@ describe('fetch', () => {
     workerStarted = true;
   };
 
-  afterEach(() => {
-    if (workerStarted) {
-      worker.stop();
-      workerStarted = false;
+  let pendingObservers = 0;
+  let waitForPerformanceObservers = async () => {};
+
+  beforeEach(() => {
+    if (PerformanceObserver) {
+      assert.strictEqual(
+        pendingObservers,
+        0,
+        'Did a previous test leak a PerformanceObserver?'
+      );
+
+      let resolvers: Resolvers<void> | undefined;
+
+      let _observe = PerformanceObserver.prototype.observe;
+      let _disconnect = PerformanceObserver.prototype.disconnect;
+
+      sinon.stub(PerformanceObserver.prototype, 'observe').callsFake(function (
+        this: PerformanceObserver,
+        ...args
+      ) {
+        _observe.call(this, ...args);
+        pendingObservers++;
+
+        if (!resolvers) {
+          resolvers = withResolvers();
+        }
+      });
+
+      sinon
+        .stub(PerformanceObserver.prototype, 'disconnect')
+        .callsFake(function (this: PerformanceObserver, ...args) {
+          _disconnect.call(this, ...args);
+          pendingObservers--;
+
+          if (pendingObservers === 0) {
+            resolvers?.resolve();
+            resolvers = undefined;
+          }
+        });
+
+      waitForPerformanceObservers = async (): Promise<void> => {
+        while (resolvers) {
+          await resolvers.promise;
+        }
+      };
     }
+  });
+
+  afterEach(() => {
+    try {
+      if (workerStarted) {
+        worker.stop();
+        workerStarted = false;
+      }
+
+      const _pendingObservers = pendingObservers;
 
-    sinon.restore();
+      pendingObservers = 0;
+      waitForPerformanceObservers = async () => {};
+
+      assert.strictEqual(
+        _pendingObservers,
+        0,
+        `Test leaked ${_pendingObservers} \`PerformanceObserver\`(s)!`
+      );
+    } finally {
+      sinon.restore();
+    }
   });
 
   describe('enabling/disabling', () => {
@@ -178,10 +270,7 @@ describe('fetch', () => {
           callback
         );
 
-        // FIXME!
-        await new Promise(resolve => {
-          setTimeout(resolve, 500);
-        });
+        await waitForPerformanceObservers();
 
         if (expectExport) {
           // This isn't intended to be an invariant, but in the current setup we
@@ -1594,7 +1683,28 @@ describe('fetch', () => {
 
             getEntriesByTypeSpy = sinon.spy(performance, 'getEntriesByType');
 
-            const result = await tracedFetch();
+            const result = await tracedFetch({
+              callback: async () => {
+                const response = await fetch('/api/status.json');
+
+                // This seemingly random timeout is testing real behavior!
+                //
+                // Currently, the implementation works by waiting a hardcoded
+                // OBSERVER_WAIT_TIME_MS before trying to get the resource
+                // timing entries, and hoping that they are there by then.
+                //
+                // We will match that here plus an additional 50ms. If the
+                // tests still fail despite this timeout, then we may have
+                // found a bug that could occur in the real world, and it's
+                // probably time to revisit the naïve implementation.
+                //
+                // This should be updated as the implementation changes.
+                await waitFor(OBSERVER_WAIT_TIME_MS + 50);
+
+                return response;
+              },
+            });
+
             rootSpan = result.rootSpan;
           });
 
@@ -1659,7 +1769,29 @@ describe('fetch', () => {
           beforeEach(async () => {
             sinon.stub(performance, 'getEntriesByType').value(undefined);
 
-            const result = await tracedFetch();
+            const result = await tracedFetch({
+              callback: async () => {
+                const response = await fetch('/api/status.json');
+
+                // Currently, the implementation works by waiting a hardcoded
+                // OBSERVER_WAIT_TIME_MS before closing out the span.
+                //
+                // This is really meant for the case where we use the
+                // `getEntriesByType` fallback, but the current implementation
+                // waits for that timeout unconditionally. That is a bit silly,
+                // but on the other hand, it's unclear if anyone out there is
+                // actually running this in an environment where `fetch()` is
+                // available but `getEntriesByType` is not.
+                //
+                // For now, we will match that here plus an additional 50ms.
+                // If we refactor the implementation to do without the timeout
+                // in this case, this can be safely deleted.
+                await waitFor(OBSERVER_WAIT_TIME_MS + 50);
+
+                return response;
+              },
+            });
+
             rootSpan = result.rootSpan;
           });