From ca40c9a85210d32889889f0eae51ffedf81e5e90 Mon Sep 17 00:00:00 2001 From: Spencer Kaiser Date: Mon, 17 Apr 2023 17:15:05 -0500 Subject: [PATCH] feat(core): add label to logger --- packages/core/src/drivers/IDatabaseDriver.ts | 2 + packages/core/src/logging/DefaultLogger.ts | 6 +- packages/core/src/logging/Logger.ts | 3 + packages/core/src/logging/SimpleLogger.ts | 3 +- packages/knex/src/AbstractSqlDriver.ts | 14 +- packages/knex/src/query/QueryBuilder.ts | 6 +- tests/Logger.test.ts | 136 ++++++++++++++----- 7 files changed, 130 insertions(+), 40 deletions(-) diff --git a/packages/core/src/drivers/IDatabaseDriver.ts b/packages/core/src/drivers/IDatabaseDriver.ts index 8e456541c682..2be2d8905aa0 100644 --- a/packages/core/src/drivers/IDatabaseDriver.ts +++ b/packages/core/src/drivers/IDatabaseDriver.ts @@ -10,6 +10,7 @@ import type { Collection } from '../entity/Collection'; import type { EntityManager } from '../EntityManager'; import type { DriverException } from '../exceptions'; import type { Configuration } from '../utils/Configuration'; +import type { LoggerContext } from '../logging'; export const EntityManagerType = Symbol('EntityManagerType'); @@ -128,6 +129,7 @@ export interface FindOptions extends Omit, 'limit' | 'offset'> { diff --git a/packages/core/src/logging/DefaultLogger.ts b/packages/core/src/logging/DefaultLogger.ts index ae484cb8c23f..fab35f32fb11 100644 --- a/packages/core/src/logging/DefaultLogger.ts +++ b/packages/core/src/logging/DefaultLogger.ts @@ -32,7 +32,11 @@ export class DefaultLogger implements Logger { message = colors.yellow(message); } - this.writer(colors.grey(`[${namespace}] `) + message); + const label = context?.label + ? colors.cyan(`(${context.label}) `) + : ''; + + this.writer(colors.grey(`[${namespace}] `) + label + message); } /** diff --git a/packages/core/src/logging/Logger.ts b/packages/core/src/logging/Logger.ts index cbefcdf718fd..437f1d31ed30 100644 --- a/packages/core/src/logging/Logger.ts +++ b/packages/core/src/logging/Logger.ts @@ -35,6 +35,7 @@ export type LoggerNamespace = 'query' | 'query-params' | 'schema' | 'discovery' export interface LogContext { query?: string; + label?: string; params?: unknown[]; took?: number; level?: 'info' | 'warning' | 'error'; @@ -50,3 +51,5 @@ export interface LoggerOptions { highlighter?: Highlighter; usesReplicas?: boolean; } + +export type LoggerContext = { queryLabel?: string }; diff --git a/packages/core/src/logging/SimpleLogger.ts b/packages/core/src/logging/SimpleLogger.ts index 2eb261de635e..c232d9148ccc 100644 --- a/packages/core/src/logging/SimpleLogger.ts +++ b/packages/core/src/logging/SimpleLogger.ts @@ -13,8 +13,9 @@ export class SimpleLogger extends DefaultLogger { // clean up the whitespace message = message.replace(/\n/g, '').replace(/ +/g, ' ').trim(); + const label = context?.label ? `(${context.label}) ` : ''; - this.writer(`[${namespace}] ${message}`); + this.writer(`[${namespace}] ${label}${message}`); } /** diff --git a/packages/knex/src/AbstractSqlDriver.ts b/packages/knex/src/AbstractSqlDriver.ts index 067a26ef269c..b7e65804a8f2 100644 --- a/packages/knex/src/AbstractSqlDriver.ts +++ b/packages/knex/src/AbstractSqlDriver.ts @@ -34,6 +34,7 @@ import type { EntityKey, EntityValue, OrderDefinition, + LoggerContext, } from '@mikro-orm/core'; import { DatabaseDriver, @@ -843,9 +844,18 @@ export abstract class AbstractSqlDriver(entityName: EntityName | QueryBuilder, ctx?: Transaction, preferredConnectionType?: ConnectionType, convertCustomTypes?: boolean): QueryBuilder { + createQueryBuilder(entityName: EntityName | QueryBuilder, ctx?: Transaction, preferredConnectionType?: ConnectionType, convertCustomTypes?: boolean, loggerContext?: LoggerContext): QueryBuilder { const connectionType = this.resolveConnectionType({ ctx, connectionType: preferredConnectionType }); - const qb = new QueryBuilder(entityName, this.metadata, this, ctx, undefined, connectionType); + const qb = new QueryBuilder( + entityName, + this.metadata, + this, + ctx, + undefined, + connectionType, + undefined, + loggerContext, + ); if (!convertCustomTypes) { qb.unsetFlag(QueryFlag.CONVERT_CUSTOM_TYPES); diff --git a/packages/knex/src/query/QueryBuilder.ts b/packages/knex/src/query/QueryBuilder.ts index 4f3d9d0fcc5b..3c1f06807ca3 100644 --- a/packages/knex/src/query/QueryBuilder.ts +++ b/packages/knex/src/query/QueryBuilder.ts @@ -13,6 +13,7 @@ import type { FlatQueryOrderMap, FlushMode, GroupOperator, + LoggerContext, MetadataStorage, ObjectQuery, PopulateOptions, @@ -127,7 +128,8 @@ export class QueryBuilder { private readonly context?: Knex.Transaction, alias?: string, private connectionType?: ConnectionType, - private readonly em?: SqlEntityManager) { + private readonly em?: SqlEntityManager, + private readonly loggerContext?: LoggerContext) { if (alias) { this.aliasCounter++; this._explicitAlias = true; @@ -608,7 +610,7 @@ export class QueryBuilder { } const type = this.connectionType || (method === 'run' ? 'write' : 'read'); - const res = await this.driver.getConnection(type).execute(query.sql, query.bindings as any[], method, this.context); + const res = await this.driver.getConnection(type).execute(query.sql, query.bindings as any[], method, { ...this.context, ...this.loggerContext }); const meta = this.mainAlias.metadata; if (!mapResults || !meta) { diff --git a/tests/Logger.test.ts b/tests/Logger.test.ts index 473307decc52..a4248a24a2d6 100644 --- a/tests/Logger.test.ts +++ b/tests/Logger.test.ts @@ -1,43 +1,111 @@ -import { Configuration, DefaultLogger } from '@mikro-orm/core'; +import { Configuration, DefaultLogger, SimpleLogger, colors } from '@mikro-orm/core'; -describe('Logger', () => { +// Remove colors to allow for text matching in response +const redColorFormatterSpy = jest.spyOn(colors, 'red').mockImplementation(text => text); +const greyColorFormatterSpy = jest.spyOn(colors, 'grey').mockImplementation(text => text); +const cyanColorFormatterSpy = jest.spyOn(colors, 'cyan').mockImplementation(text => text); +const yellowColorFormatterSpy = jest.spyOn(colors, 'yellow').mockImplementation(text => text); + +const mockWriter = jest.fn(); - test('should have debug mode disabled by default', async () => { - const mock = jest.fn(); - const logger = new DefaultLogger({ writer: mock }); - expect(logger.debugMode).toBe(false); - logger.log('discovery', 'test debug msg'); - expect(mock.mock.calls.length).toBe(0); - logger.log('info', 'test info msg'); - expect(mock.mock.calls.length).toBe(0); +describe('Logger', () => { + beforeEach(() => { + jest.clearAllMocks(); }); - test('should print debug messages when debug mode enabled', async () => { - const mock = jest.fn(); - const logger = new DefaultLogger({ writer: mock, debugMode: true }); - expect(logger.debugMode).toBe(true); - logger.log('discovery', 'test debug msg'); - expect(mock.mock.calls.length).toBe(1); - logger.log('info', 'test info msg'); - expect(mock.mock.calls.length).toBe(2); - logger.log('query', 'test query msg'); - expect(mock.mock.calls.length).toBe(3); + describe('DefaultLogger', () => { + + test('should have debug mode disabled by default', async () => { + const logger = new DefaultLogger({ writer: mockWriter }); + expect(logger.debugMode).toBe(false); + logger.log('discovery', 'test debug msg'); + logger.log('info', 'test info msg'); + expect(mockWriter).toBeCalledTimes(0); + }); + + test('should print debug messages when debug mode enabled', async () => { + const logger = new DefaultLogger({ writer: mockWriter, debugMode: true }); + expect(logger.debugMode).toBe(true); + logger.log('discovery', 'test debug msg'); + expect(mockWriter).toBeCalledTimes(1); + logger.log('info', 'test info msg'); + expect(mockWriter).toBeCalledTimes(2); + logger.log('query', 'test query msg'); + expect(mockWriter).toBeCalledTimes(3); + }); + + test('should not print debug messages when given namespace not enabled', async () => { + const logger = new DefaultLogger({ writer: mockWriter, debugMode: ['query'] }); + expect(logger.debugMode).toEqual(['query']); + logger.log('discovery', 'test debug msg'); + expect(mockWriter).toBeCalledTimes(0); + logger.log('info', 'test info msg'); + expect(mockWriter).toBeCalledTimes(0); + logger.log('query', 'test query msg'); + expect(mockWriter).toBeCalledTimes(1); + logger.error('query', 'test error msg'); + expect(mockWriter).toBeCalledTimes(2); + logger.warn('query', 'test warning msg'); + expect(mockWriter).toBeCalledTimes(3); + }); + + test('should print labels correctly', () => { + const logger = new DefaultLogger({ writer: mockWriter, debugMode: ['query'] }); + const namespace = 'query'; + const message = 'test label msg'; + const label = 'hello world handler'; + logger.log(namespace, message, { label }); + expect(mockWriter).toBeCalledWith(`[${namespace}] (${label}) ${message}`); + }); + + test('should print values with the appropriate colors', () => { + const logger = new DefaultLogger({ writer: mockWriter, debugMode: ['query'] }); + const namespace = 'query'; + const label = 'handler'; + const message = 'test label msg'; + + logger.log(namespace, message, { level: 'error', label }); + expect(greyColorFormatterSpy).toBeCalledWith(`[${namespace}] `); + expect(redColorFormatterSpy).toBeCalledWith(message); + expect(cyanColorFormatterSpy).toBeCalledWith(`(${label}) `); + expect(yellowColorFormatterSpy).not.toBeCalled(); + + jest.clearAllMocks(); + + logger.log(namespace, message, { level: 'warning', label }); + expect(greyColorFormatterSpy).toBeCalledWith(`[${namespace}] `); + expect(yellowColorFormatterSpy).toBeCalledWith(message); + expect(cyanColorFormatterSpy).toBeCalledWith(`(${label}) `); + expect(redColorFormatterSpy).not.toBeCalled(); + + jest.clearAllMocks(); + + logger.log(namespace, message, { level: 'info', label }); + expect(greyColorFormatterSpy).toBeCalledWith(`[${namespace}] `); + expect(cyanColorFormatterSpy).toBeCalledWith(`(${label}) `); + expect(yellowColorFormatterSpy).not.toBeCalled(); + expect(redColorFormatterSpy).not.toBeCalled(); + }); }); - test('should not print debug messages when given namespace not enabled', async () => { - const mock = jest.fn(); - const logger = new DefaultLogger({ writer: mock, debugMode: ['query'] }); - expect(logger.debugMode).toEqual(['query']); - logger.log('discovery', 'test debug msg'); - expect(mock.mock.calls.length).toBe(0); - logger.log('info', 'test info msg'); - expect(mock.mock.calls.length).toBe(0); - logger.log('query', 'test query msg'); - expect(mock.mock.calls.length).toBe(1); - logger.error('query', 'test error msg'); - expect(mock.mock.calls.length).toBe(2); - logger.warn('query', 'test warning msg'); - expect(mock.mock.calls.length).toBe(3); + describe('SimpleLogger', () => { + + test('should print correctly without a label', () => { + const logger = new SimpleLogger({ writer: mockWriter, debugMode: ['query'] }); + const namespace = 'query'; + const message = 'test label msg'; + logger.log(namespace, message); + expect(mockWriter).toBeCalledWith(`[${namespace}] ${message}`); + }); + + test('should print labels correctly', () => { + const logger = new SimpleLogger({ writer: mockWriter, debugMode: ['query'] }); + const namespace = 'query'; + const message = 'test label msg'; + const label = 'hello world handler'; + logger.log(namespace, message, { label }); + expect(mockWriter).toBeCalledWith(`[${namespace}] (${label}) ${message}`); + }); }); });