[Bug]: `vitest` complains about unhandled error when using `@LogAll` decorator

thenbe commented 1 year ago

Is there an existing issue for this?

[X] I have searched the existing issues

Current behavior

The tests pass, but when an (a) an error is thrown inside an async function and (b) we're using ogma's LogAll() decorator, then vitest will complain.

Error:

$ npx vitest run                                                                                                                                                                                                                           took 3s 07:18:38 

 RUN  v0.33.0 /home/nbe/projects/playground/repro-ogma-vitest

 ✓ src/app.service.spec.ts (2)
   ✓ AppService (2)
     ✓ getHello should throw
     ✓ getHelloAsync should throw

⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯ Unhandled Errors ⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯

Vitest caught 1 unhandled error during the test run.
This might cause false positive tests. Resolve unhandled errors to make sure your tests are not affected.

⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯ Unhandled Rejection ⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯
Error: This is also an error
 ❯ src/app.service.ts:14:14
     12|   getHelloAsync(): Promise<string> {
     13|     return new Promise((resolve, reject) => {
     14|       reject(new Error('This is also an error'));
       |              ^
     15|     });
     16|   }
 ❯ AppService.getHelloAsync src/app.service.ts:13:12
 ❯ AppService.getHelloAsync node_modules/@ogma/nestjs-module/src/decorators/ogma-logger.decorator.js:24:27
 ❯ src/app.service.spec.ts:31:26
 ❯ node_modules/@vitest/runner/dist/index.js:242:72
 ❯ node_modules/@vitest/runner/dist/index.js:41:26
 ❯ runTest node_modules/@vitest/runner/dist/index.js:599:17
 ❯ runSuite node_modules/@vitest/runner/dist/index.js:708:15
 ❯ runSuite node_modules/@vitest/runner/dist/index.js:708:15

This error originated in "src/app.service.spec.ts" test file. It doesn't mean the error was thrown inside the file itself, but while it was running.
⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯⎯

 Test Files  1 passed (1)
      Tests  2 passed (2)
     Errors  1 error
   Start at  19:18:49
   Duration  828ms (transform 142ms, setup 0ms, collect 106ms, tests 8ms, environment 0ms, prepare 496ms)

Minimum reproduction code

https://github.com/thenbe/repro-ogma-vitest

Steps to reproduce

# 1. install deps
npm install

# 2. run vitest
npx vitest

# 3. observe that tests pass, but vitest warns about unhandled error

Expected behavior

Vitest should not complain, just like the first test.

Package(s) version

@ogma/cli:
@ogma/common:
@ogma/logger:
@ogma/nestjs-module: "^5.1.1"
@ogma/platform-express:
@ogma/platform-fastify:
@ogma/platform-graphql-fastify:
@ogma/platform-graphql:
@ogma/platform-grpc:
@ogma/platform-kafka:
@ogma/platform-mqtt:
@ogma/platform-nats:
@ogma/platform-rabbitmq:
@ogma/platform-redis:
@ogma/platform-socket.io:
@ogma/platform-tcp:
@ogma/platform-ws:
@ogma/styler:

Node.js version

18.16.1

In which operating systems have you tested?

[ ] macOS
[ ] Windows
[X] Linux

Other

I haven't used ogma before, so if I can't tell if this is a genuine bug or if I'm doing something I shouldn't.

jmcdo29 commented 1 year ago

This is very interesting. Thank you for the reproduction. All that the @Log() and @LogAll() decorator should be doing is adding a finally block to log the method end. Strange that an unhandled error is arising from it.

It does happen in other test runners, so something is getting modified in an unexpected way. I'll try to look into it

jmcdo29 commented 1 year ago

I think this is because the @Log() decorator technically modifies the descriptor,value when it is a promise to add a .finally. This decorator and test causes the same warning:

const TestDec = () => {
  return (target, propertyKey, descriptor) => {
    const impl = descriptor.value;
    descriptor.value = function (...args) {
      const res = impl.apply(this, ...args);
      res.finally(() => {
        console.log('added finally');
      });
      return res;
    };
    return descriptor;
  };
};

class Foo {
  @TestDec()
  foo() {
    return Promise.reject('Boo!');
  }
}

it('testing plain decorator', async () => {
  const foo = new Foo();
  await expect(foo.foo()).rejects.toThrow();
});

Not sure what to do about it just yet, but I'll keep searching through some more obscure stuff

thenbe commented 1 year ago

I noticed that making either of the following changes will suppress the warning from vitest. Could the issue be related to this: https://typescript-eslint.io/rules/no-floating-promises/

const TestDec = () => {
  return (target, propertyKey, descriptor) => {
    const impl = descriptor.value;
-   descriptor.value = function (...args) {
+   descriptor.value = async function (...args) {
      const res = impl.apply(this, ...args);
-     res.finally(() => {
+     await res.finally(() => {
        console.log('added finally');
      });
      return res;
    };
    return descriptor;
  };
};

or

const TestDec = () => {
  return (target, propertyKey, descriptor) => {
    const impl = descriptor.value;
    descriptor.value = function (...args) {
      const res = impl.apply(this, ...args);
-     res.finally(() => {
+     return res.finally(() => {
        console.log('added finally');
      });
-     return res;
    };
    return descriptor;
  };
};

jmcdo29 commented 1 year ago

The latter would be preferable, as I don't want to modify synchronous functions to become async. I'll double check this tomorrow and get some test cases written

jmcdo29 / ogma