In my NestJS service, I’ve implemented a custom DB logger, which is meant to log both the before (requests), as well as the after (DB responses) info. I’ve done this by implementing the suggested interface class TypeOrmLogger. From: https://typeorm.io/logging
Below is my custom-db-logger.ts:
import { Logger } from '@nestjs/common';
import { ConfigService } from '@nestjs/config';
import { Logger as TypeOrmLogger, QueryRunner } from 'typeorm';
import { v4 as uuidv4 } from 'uuid';
export class CustomDbLogger implements TypeOrmLogger {
private readonly logger: Logger;
private serviceLabel: string;
private DB_REQUEST_LOGTYPE = 'DB_REQUEST';
private DB_RESPONSE_LOGTYPE = 'DB_RESPONSE';
constructor(private readonly configService: ConfigService) {
this.serviceLabel = this.configService.get('SERVICE_LABEL', 'DB-Requests');
this.logger = new Logger(`DB:${this.serviceLabel}`);
}
// Log the DB-request:
logQuery(query: string, parameters?: any[], queryRunner?: QueryRunner) {
console.log('nnlogQuery() called...');
const queryId = uuidv4(); // Generate a unique ID for the query
const startTime = new Date().toISOString(); // Record the current time in ISO format
const startTimestamp = Date.now();
// Store the queryId and startTimestamp in the QueryRunner for later use
if (queryRunner) {
(queryRunner as any).queryId = queryId;
(queryRunner as any).startTimestamp = startTimestamp;
console.log('QueryRunner updated with queryId and startTimestamp');
}
this.logger.log(
JSON.stringify({
service: this.serviceLabel,
logType: this.DB_REQUEST_LOGTYPE,
queryId,
query,
parameters,
startTime,
}),
);
}
// When response is Error, will use:
logQueryError(
error: string | Error,
query: string,
parameters?: any[],
queryRunner?: QueryRunner,
) {
console.log('logQueryError() called...');
const queryId = (queryRunner as any)?.queryId;
const startTimestamp = (queryRunner as any)?.startTimestamp;
const endTime = new Date().toISOString(); // Record the current time in ISO format
const duration = startTimestamp ? Date.now() - startTimestamp : null; // Calculate the duration
this.logger.error(
JSON.stringify({
service: this.serviceLabel,
logType: this.DB_RESPONSE_LOGTYPE,
queryId,
query,
parameters,
endTime,
duration,
error: error instanceof Error ? error.message : error,
}),
);
}
// When TypeOrm already designates the response as "slow", it will use:
logQuerySlow(
time: number,
query: string,
parameters?: any[],
queryRunner?: QueryRunner,
) {
console.log('logQuerySlow() called...');
const queryId = (queryRunner as any)?.queryId;
const startTimestamp = (queryRunner as any)?.startTimestamp;
const endTime = new Date().toISOString();
const duration = startTimestamp ? Date.now() - startTimestamp : null;
this.logger.warn(
JSON.stringify({
service: this.serviceLabel,
logType: this.DB_RESPONSE_LOGTYPE,
queryId,
query,
parameters,
endTime,
timeTypeORM: time, // Their own (TypeORM's) stated duration, in 'time' parm,
duration, // Our own manually calculated duration (to see if there's a difference)
}),
);
}
// All other DB-responses (i.e. not slow or error according to TypeOrm), will use:
logQueryResult(query: string, parameters?: any[], queryRunner?: QueryRunner) {
console.log('logQueryResult() called...'); // Debug statement
const queryId = (queryRunner as any)?.queryId;
const startTimestamp = (queryRunner as any)?.startTimestamp;
const endTime = new Date().toISOString(); // Record the current time in ISO format
const duration = startTimestamp ? Date.now() - startTimestamp : null; // Calculate the duration
this.logger.log(
JSON.stringify({
service: this.serviceLabel,
logType: this.DB_RESPONSE_LOGTYPE,
queryId,
// query, // Trying to minimize noise in logs, query and parms is already in request log
// parameters,
endTime,
duration,
}),
);
}
log(level: 'log' | 'info' | 'warn', message: any) {
console.log('nlog() called', level); // Debug statement
switch (level) {
case 'log':
this.logger.log(message);
break;
case 'info':
console.log('nnAbout to call the logger.debug()');
this.logger.debug(message);
break;
case 'warn':
this.logger.warn(message);
break;
}
}
logMigration(message: string) {
console.log('logMigration() called...');
this.logger.log(message);
}
logSchemaBuild(message: string) {
console.log('logSchemaBuild() called...');
this.logger.log(message);
}
}
And the above custom logger is then used in the typeorm config:
TypeOrmModule.forRootAsync({
inject: [ConfigService],
name: 'mainBackEndConnection', // Connection name, not database name
useFactory: async (configService: ConfigService) => ({
type: 'postgres',
host: configService.get('TYPEORM_HOST', '127.0.0.1'),
port: Number.parseInt(configService.get('TYPEORM_PORT', '3306')),
username: configService.get('TYPEORM_USERNAME', 'root'),
password: configService.get('TYPEORM_PASSWORD', 'root'),
database: configService.get('TYPEORM_DATABASE', 'formetoknow'),
schema: configService.get('TYPEORM_SCHEMA', 'formetoknowaswell'),
synchronize: false,
// logging: process.env.NODE_ENV !== 'production',
logging: true,
logger: new CustomDbLogger(configService),
And anyway, it works, but only for the requests. The expectation is that it should also, once the DB has responded with the query result, then also log the response data, using one of the three response functions (logQueryError, logQuerySlow, or logQueryResult
), but it isn’t hitting any of those response functions. Need to figure out why? Looking for some approach/implementation to log both before and after (with one of the key reasons of course being that we wish to log DB durations and other info)
1