Test case is leaking async ops when using clearTimeout inside finally block after not catching error

[KyleJune]

If you use finally statements to do test cleanup, you can end up with the following test falsely reporting leaking async ops. In the below tests, you wouldn't expect sync2 and async2 to be leaking ops since they are not really doing anything but they end up failing with that error. I found that if you add a delay after you clearTimeout, the following test async5 will not falsely report leaking async ops.

import { delay } from "https://deno.land/[email protected]/async/delay.ts";

Deno.test("sync1", () => {
  let timer = -1;
  try {
    timer = setTimeout(() => null, 10000);
    throw new Error("fail");
  } finally {
    clearTimeout(timer);
  }
});

Deno.test("sync2", () => {});

Deno.test("sync3", () => {});

Deno.test("async1", async () => {
  let timer = -1;
  try {
    timer = setTimeout(() => null, 10000);
    await delay(0);
    throw new Error("fail");
  } finally {
    clearTimeout(timer);
  }
});

Deno.test("async2", async () => {
  await delay(0);
});

Deno.test("async3", async () => {
  await delay(0);
});

Deno.test("async4", async () => {
  let timer = -1;
  try {
    timer = setTimeout(() => null, 10000);
    await delay(0);
    throw new Error("fail");
  } finally {
    clearTimeout(timer);
    await delay(0);
  }
});

Deno.test("async5", async () => {
  await delay(0);
});

Deno.test("async6", async () => {
  await delay(0);
});

$ deno --version
deno 1.6.0 (release, x86_64-unknown-linux-gnu)
v8 8.8.278.2
typescript 4.1.2
$ deno test
running 9 tests
test sync1 ... FAILED (1ms)
test sync2 ... FAILED (2ms)
test sync3 ... ok (2ms)
test async1 ... FAILED (2ms)
test async2 ... FAILED (3ms)
test async3 ... ok (3ms)
test async4 ... FAILED (2ms)
test async5 ... ok (3ms)
test async6 ... ok (3ms)

failures:

sync1
Error: fail
    at example_test.ts:7:11
    at asyncOpSanitizer (deno:cli/rt/40_testing.js:36:13)
    at Object.resourceSanitizer [as fn] (deno:cli/rt/40_testing.js:70:13)
    at TestRunner.[Symbol.asyncIterator] (deno:cli/rt/40_testing.js:245:24)
    at AsyncGenerator.next (<anonymous>)
    at Object.runTests (deno:cli/rt/40_testing.js:322:22)
    at async $deno$test.ts:3:1

sync2
AssertionError: Test case is leaking async ops.
Before:
  - dispatched: 1
  - completed: 0
After:
  - dispatched: 2
  - completed: 2

Make sure to await all promises returned from Deno APIs before
finishing test case.
    at assert (deno:cli/rt/06_util.js:33:13)
    at asyncOpSanitizer (deno:cli/rt/40_testing.js:46:7)
    at async Object.resourceSanitizer [as fn] (deno:cli/rt/40_testing.js:70:7)
    at async TestRunner.[Symbol.asyncIterator] (deno:cli/rt/40_testing.js:245:13)
    at async Object.runTests (deno:cli/rt/40_testing.js:322:22)
    at async $deno$test.ts:3:1

async1
Error: fail
    at example_test.ts:22:11
    at async asyncOpSanitizer (deno:cli/rt/40_testing.js:36:7)
    at async Object.resourceSanitizer [as fn] (deno:cli/rt/40_testing.js:70:7)
    at async TestRunner.[Symbol.asyncIterator] (deno:cli/rt/40_testing.js:245:13)
    at async Object.runTests (deno:cli/rt/40_testing.js:322:22)
    at async $deno$test.ts:3:1

async2
AssertionError: Test case is leaking async ops.
Before:
  - dispatched: 6
  - completed: 5
After:
  - dispatched: 8
  - completed: 8

Make sure to await all promises returned from Deno APIs before
finishing test case.
    at assert (deno:cli/rt/06_util.js:33:13)
    at asyncOpSanitizer (deno:cli/rt/40_testing.js:46:7)
    at async Object.resourceSanitizer [as fn] (deno:cli/rt/40_testing.js:70:7)
    at async TestRunner.[Symbol.asyncIterator] (deno:cli/rt/40_testing.js:245:13)
    at async Object.runTests (deno:cli/rt/40_testing.js:322:22)
    at async $deno$test.ts:3:1

async4
Error: fail
    at example_test.ts:41:11
    at async asyncOpSanitizer (deno:cli/rt/40_testing.js:36:7)
    at async Object.resourceSanitizer [as fn] (deno:cli/rt/40_testing.js:70:7)
    at async TestRunner.[Symbol.asyncIterator] (deno:cli/rt/40_testing.js:245:13)
    at async Object.runTests (deno:cli/rt/40_testing.js:322:22)
    at async $deno$test.ts:3:1

failures:

        sync1
        sync2
        async1
        async2
        async4

test result: FAILED. 4 passed; 5 failed; 0 ignored; 0 measured; 0 filtered out (22ms)

[caspervonb]

We're already trying to mitigate this with a call to await new Promise(resolve => setTimeout(resolve, 0) but seems that clearing a timer takes longer than that (and it is internally async).

This was previously tracked here #4602 but can still be an issue.

[KyleJune]

@caspervonb I think the actual issue is that the delay from that PR only happens if the awaited test function does not have an error. If there is an error, the await delay(0) is skipped along with the post metrics, then it continues to the next test getting the pre metrics without any delay between the clearTimeout and the pre metrics call.

    const pre = metrics();
    await fn();
    // Defer until next event loop turn - that way timeouts and intervals
    // cleared can actually be removed from resource table, otherwise
    // false positives may occur (https://github.com/denoland/deno/issues/4591)
    await delay(0);
    const post = metrics();

I think putting the delay in a finally would fix the issue. From my examples, a delay after the clearTimeout in the async4 test fixes the issue, preventing async5 from failing with a leaking async ops error.

    const pre = metrics();
    try {
      await fn();
    } finally {
      // Defer until next event loop turn - that way timeouts and intervals
      // cleared can actually be removed from resource table, otherwise
      // false positives may occur (https://github.com/denoland/deno/issues/4591)
      await delay(0);
    }
    const post = metrics();

[caspervonb]

@caspervonb I think the actual issue is that the delay from that PR only happens if the awaited test function does not have an error. If there is an error, the await delay(0) is skipped along with the post metrics, then it continues to the next test getting the pre metrics without any delay between the clearTimeout and the pre metrics call.

    const pre = metrics();
    await fn();
    // Defer until next event loop turn - that way timeouts and intervals
    // cleared can actually be removed from resource table, otherwise
    // false positives may occur (https://github.com/denoland/deno/issues/4591)
    await delay(0);
    const post = metrics();

I think putting the delay in a finally would fix the issue. From my examples, a delay after the clearTimeout in the async4 test fixes the issue, preventing async5 from failing with a leaking async ops error.

    const pre = metrics();
    try {
      await fn();
    } finally {
      // Defer until next event loop turn - that way timeouts and intervals
      // cleared can actually be removed from resource table, otherwise
      // false positives may occur (https://github.com/denoland/deno/issues/4591)
      await delay(0);
    }
    const post = metrics();

Right, easiest is often the best.
Tried it and indeed that does work 👍