Why can't I get context data in Typeorm's logQuerySlow when logQuery does

[ahuijiLearning]

Details

So why does logQuery get store correctly and logQuerySlow doesn't? Is there a solution to get a store in logQuerySlow？ This seems to need to use AsyncResource, but I don't know how to use it.

Node.js version

v14.19.0

Example code

// request-context.middleware.ts
export const asyncLocalStorage = new AsyncLocalStorage();

@Injectable()
export class RequestContextMiddleware implements NestMiddleware<Request, Response> {
  use(req: Request, res: Response, next: () => void) {
    if (!req.headers['x-request-id']) {
      const reqId = uuidv1().replace(/-/g, '');
      res.setHeader('x-request-id', reqId);
      req.headers['x-request-id'] = reqId;
    }
    asyncLocalStorage.run({ req, res, startTime: new Date() }, next);
    // Log.cls.run(new Log(req, res, new Date()), next);
  }
}
å

// app.module.ts
@Module({
    imports: [
        TypeOrmModule.forRoot({
            ...config.mysql,
            maxQueryExecutionTime: 0.1,
            logger: new OrmLogger(),
        }),
    ],
})
export class AppModule { }

// controller.ts
@ApiOperation({ summary: 'log 测试' })
@Get('log')
async log(@Query('id', new ParseIntPipe()) id: number): Promise < any > {
    return await this.userRepository.find({
        where: {
            id,
        }
    });
}

// OrmLogger.ts
import { Logger, QueryRunner } from "typeorm";
export class OrmLogger implements Logger {
    logQuery(query: string, parameters?: any[], queryRunner?: QueryRunner) {
        const startTime = (asyncLocalStorage.getStore() as any)?.startTime;
        console.log(`${+startTime}  Executed: ${query}`);
      }
      logQuerySlow(time: number, query: string, parameters?: any[], queryRunner?: QueryRunner) {
        const startTime = (asyncLocalStorage.getStore() as any)?.startTime;
        console.log(`${+startTime} Executed: ${query} time: ${time}ms`);
      }
}

// console
1649473829365  Executed: SELECT `User`.`id` AS `User_id`, `User`.`truename` AS `User_truename`, `User`.`studentid` AS `User_studentid` FROM `user` `User` WHERE `User`.`id` IN (?)
NaN Executed: SELECT `User`.`id` AS `User_id`, `User`.`truename` AS `User_truename`, `User`.`studentid` AS `User_studentid` FROM `user` `User` WHERE `User`.`id` IN (?) time: 30ms

I have looked at Typeorm related Mysql Query internal implementation, which is described as follows:

async query(query: string, parameters?: any[], useStructuredResult = false): Promise<any> {
        if (this.isReleased)
            throw new QueryRunnerAlreadyReleasedError();

        return new Promise(async (ok, fail) => {
            try {
                const databaseConnection = await this.connect();
                this.driver.connection.logger.logQuery(query, parameters, this);
                const queryStartTime = +new Date();
                databaseConnection.query(query, parameters, (err: any, raw: any) => {

                    // log slow queries if maxQueryExecution time is set
                    const maxQueryExecutionTime = this.driver.options.maxQueryExecutionTime;
                    const queryEndTime = +new Date();
                    const queryExecutionTime = queryEndTime - queryStartTime;
                    if (maxQueryExecutionTime && queryExecutionTime > maxQueryExecutionTime)
                        this.driver.connection.logger.logQuerySlow(queryExecutionTime, query, parameters, this);

                    if (err) {
                        this.driver.connection.logger.logQueryError(err, query, parameters, this);
                        return fail(new QueryFailedError(query, parameters, err));
                    }
                   // The following is omitted.
        });
    }

Operating system

mac

Scope

async_hooks. AsyncLocalStorage

Module and version

"@nestjs/common": "^8.0.0", "@nestjs/core": "^8.0.0", "@nestjs/typeorm": "^8.0.3",

[mouze]

I have same issue.

As workaround I did something like this:

export class OrmLogger implements Logger {
    logQuery(query: string, parameters?: any[], queryRunner?: QueryRunner) {
        const startTime = (asyncLocalStorage.getStore() as any)?.startTime;
        console.log(`${+startTime}  Executed: ${query}`);
        if(queryRunner) {
          queryRunner.data._logRc = asyncLocalStorage.getStore();;
        }
      }
      logQuerySlow(time: number, query: string, parameters?: any[], queryRunner?: QueryRunner) {
        const rc = queryRunner?.data._logRc ?? {};
        asyncLocalStorage.run(rc, () => {
          const startTime = (asyncLocalStorage.getStore() as any)?.startTime;
          console.log(`${+startTime} Executed: ${query} time: ${time}ms`);
          // I call other functions here and asyncLocalStorage.getStore() works correctly in them.
        });
      }
}

[github-actions[bot]]

It seems there has been no activity on this issue for a while, and it is being closed in 30 days. If you believe this issue should remain open, please leave a comment. If you need further assistance or have questions, you can also search for similar issues on Stack Overflow. Make sure to look at the README file for the most updated links.

[github-actions[bot]]

It seems there has been no activity on this issue for a while, and it is being closed. If you believe this issue should remain open, please leave a comment. If you need further assistance or have questions, you can also search for similar issues on Stack Overflow. Make sure to look at the README file for the most updated links.