Skip to content

Commit

Permalink
feat(core): allow overriding global logging options on per-query basis (
Browse files Browse the repository at this point in the history
#4273)

Closes #4223
  • Loading branch information
SpencerKaiser committed May 5, 2023
1 parent 8c54544 commit 160a651
Show file tree
Hide file tree
Showing 11 changed files with 192 additions and 46 deletions.
49 changes: 37 additions & 12 deletions docs/docs/logging.md
Expand Up @@ -73,6 +73,39 @@ For MongoDB you can use `MongoHighlighter` from `@mikro-orm/mongo-highlighter` p

Several customization options exist to allow for style changes or custom logic.

### Query Labels

It may often be beneficial to log the origin of a query when using [`EntityManager.find`](entity-manager.md#fetching-entities-with-entitymanager) or [`EntityManager.findOne`](entity-manager.md#fetching-entities-with-entitymanager) for debugging and redundancy elimination purposes.

An optional `loggerContext` option can be included within the `FindOptions` parameter of either call which will add a label to the output when debug mode is enabled.

```ts
const author = await em.findOne(Author, { id: 1 }, { loggerContext: { label: 'Author Retrieval - /authors/me' } });
// [query] (Author Retrieval - /authors/me) select "a0".* from "Author" as "a0" where "a0"."id" = 1 limit 1 [took 21 ms]
```

### Changing `debugMode` or disabling logging for specific queries

If you'd like to disable logging or change the debug mode on a per-query basis, you can leverage `FindOptions.logging` and its `enabled` or `debugMode` property:

```ts
// MikroORM.init({ debug: true });
const author = await em.findOne(Author, { id: 1 }, { logging: { enabled: false } });
// Overrides config and displays no logger output

// ...

// MikroORM.init({ debug: false });
const author = await em.findOne(Author, { id: 1 }, { logging: { enabled: true } });
// Overrides config and displays logger output

// ...

// MikroORM.init({ debug: ['query-labels'] });
const author = await em.findOne(Author, { id: 1 }, { logging: { debugMode: ['query'] } });
// Overrides config and displays logger output for query
```

### Using a custom logger

You can provide your own logger function via the `logger` option:
Expand Down Expand Up @@ -142,7 +175,7 @@ interface Logger {
warn(namespace: LoggerNamespace, message: string, context?: LogContext): void;
logQuery(context: LogContext): void;
setDebugMode(debugMode: boolean | LoggerNamespace[]): void;
isEnabled(namespace: LoggerNamespace): boolean;
isEnabled(namespace: LoggerNamespace, context?: LogContext): boolean;
}

type LoggerNamespace = 'query' | 'query-params' | 'schema' | 'discovery' | 'info';
Expand All @@ -153,25 +186,17 @@ interface LogContext extends Dictionary {
params?: unknown[];
took?: number;
level?: 'info' | 'warning' | 'error';
enabled?: boolean;
debugMode?: LoggerNamespace[];
connection?: {
type?: string;
name?: string;
};
}
```

### Query Labels

It may often be beneficial to log the origin of a query when using [`EntityManager.find`](entity-manager.md#fetching-entities-with-entitymanager) or [`EntityManager.findOne`](entity-manager.md#fetching-entities-with-entitymanager) for debugging and redundancy elimination purposes.

An optional `loggerContext` option can be included within the `FindOptions` parameter of either call which will add a label to the output when debug mode is enabled.

```ts
const author = await em.findOne(Author, { id: 1 }, { loggerContext: { label: 'Author Retrieval - /authors/me' } });
// [query] (Author Retrieval - /authors/me) select "a0".* from "Author" as "a0" where "a0"."id" = 1 limit 1 [took 21 ms]
```

### Providing additional context to a custom logger

If you have implemented your own `LoggerFactory` and need to access additional contextual values inside your customer logger implementation, utilize the `LoggerContext` property of `FindOptions`. Adding additional key/value pairs to that object will make them available inside your custom logger:

```ts
Expand Down
4 changes: 2 additions & 2 deletions packages/core/src/drivers/IDatabaseDriver.ts
Expand Up @@ -10,7 +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';
import type { LoggingOptions } from '../logging';

export const EntityManagerType = Symbol('EntityManagerType');

Expand Down Expand Up @@ -129,7 +129,7 @@ export interface FindOptions<T, P extends string = never, F extends string = nev
lockTableAliases?: string[];
ctx?: Transaction;
connectionType?: ConnectionType;
loggerContext?: LoggerContext;
logging?: LoggingOptions;
}

export interface FindByCursorOptions<T extends object, P extends string = never, F extends string = never> extends Omit<FindOptions<T, P, F>, 'limit' | 'offset'> {
Expand Down
11 changes: 7 additions & 4 deletions packages/core/src/logging/DefaultLogger.ts
Expand Up @@ -15,7 +15,7 @@ export class DefaultLogger implements Logger {
* @inheritDoc
*/
log(namespace: LoggerNamespace, message: string, context?: LogContext): void {
if (!this.isEnabled(namespace)) {
if (!this.isEnabled(namespace, context)) {
return;
}

Expand Down Expand Up @@ -60,15 +60,18 @@ export class DefaultLogger implements Logger {
this.debugMode = debugMode;
}

isEnabled(namespace: LoggerNamespace): boolean {
return !!this.debugMode && (!Array.isArray(this.debugMode) || this.debugMode.includes(namespace));
isEnabled(namespace: LoggerNamespace, context?: LogContext) {
if (context?.enabled !== undefined) { return context.enabled; }
const debugMode = context?.debugMode ?? this.debugMode;

return !!debugMode && (!Array.isArray(debugMode) || debugMode.includes(namespace));
}

/**
* @inheritDoc
*/
logQuery(context: { query: string } & LogContext): void {
if (!this.isEnabled('query')) {
if (!this.isEnabled('query', context)) {
return;
}

Expand Down
10 changes: 7 additions & 3 deletions packages/core/src/logging/Logger.ts
Expand Up @@ -27,7 +27,7 @@ export interface Logger {
*/
setDebugMode(debugMode: boolean | LoggerNamespace[]): void;

isEnabled(namespace: LoggerNamespace): boolean;
isEnabled(namespace: LoggerNamespace, context?: LogContext): boolean;

}

Expand All @@ -39,6 +39,8 @@ export interface LogContext extends Dictionary {
params?: unknown[];
took?: number;
level?: 'info' | 'warning' | 'error';
enabled?: boolean;
debugMode?: LoggerNamespace[];
connection?: {
type?: string;
name?: string;
Expand All @@ -53,10 +55,12 @@ export interface LoggerOptions {
}

/**
* Context for a logger to utilize to format output, including a label and additional properties that can be accessed by custom loggers
* Logger options to modify format output and overrides, including a label and additional properties that can be accessed by custom loggers
*
* Differs from {@link LoggerOptions} in terms of how they are used; this type is primarily a public type meant to be used within methods like `EntityManager.Find`
*
* @example
* await em.findOne(User, 1, { loggerContext: { label: 'user middleware' } };
* // [query] (user middleware) select * from user where id = 1;
*/
export type LoggerContext = Pick<LogContext, 'label'> & Dictionary;
export type LoggingOptions = Pick<LogContext, 'label' | 'enabled' | 'debugMode'> & Dictionary;
4 changes: 2 additions & 2 deletions packages/core/src/logging/SimpleLogger.ts
Expand Up @@ -10,7 +10,7 @@ export class SimpleLogger extends DefaultLogger {
* @inheritDoc
*/
override log(namespace: LoggerNamespace, message: string, context?: LogContext): void {
if (!this.isEnabled(namespace)) {
if (!this.isEnabled(namespace, context)) {
return;
}

Expand All @@ -25,7 +25,7 @@ export class SimpleLogger extends DefaultLogger {
* @inheritDoc
*/
override logQuery(context: { query: string } & LogContext): void {
if (!this.isEnabled('query')) {
if (!this.isEnabled('query', context)) {
return;
}

Expand Down
14 changes: 7 additions & 7 deletions packages/knex/src/AbstractSqlConnection.ts
Expand Up @@ -2,7 +2,7 @@ import type { Knex } from 'knex';
import { knex } from 'knex';
import { readFile } from 'fs-extra';
import type {
AnyEntity, Configuration, ConnectionOptions, EntityData, IsolationLevel, LoggerContext, QueryResult,
AnyEntity, Configuration, ConnectionOptions, EntityData, IsolationLevel, LogContext, LoggingOptions, QueryResult,
Transaction, TransactionEventBroadcaster } from '@mikro-orm/core';
import { Connection, EventType, Utils,
} from '@mikro-orm/core';
Expand Down Expand Up @@ -114,7 +114,7 @@ export abstract class AbstractSqlConnection extends Connection {
}
}

async execute<T extends QueryResult | EntityData<AnyEntity> | EntityData<AnyEntity>[] = EntityData<AnyEntity>[]>(queryOrKnex: string | Knex.QueryBuilder | Knex.Raw, params: unknown[] = [], method: 'all' | 'get' | 'run' = 'all', ctx?: Transaction, loggerContext?: LoggerContext): Promise<T> {
async execute<T extends QueryResult | EntityData<AnyEntity> | EntityData<AnyEntity>[] = EntityData<AnyEntity>[]>(queryOrKnex: string | Knex.QueryBuilder | Knex.Raw, params: unknown[] = [], method: 'all' | 'get' | 'run' = 'all', ctx?: Transaction, logging?: LoggingOptions): Promise<T> {
await this.ensureConnection();

if (Utils.isObject<Knex.QueryBuilder | Knex.Raw>(queryOrKnex)) {
Expand All @@ -125,7 +125,7 @@ export abstract class AbstractSqlConnection extends Connection {
}

const formatted = this.platform.formatQuery(queryOrKnex, params);
const sql = this.getSql(queryOrKnex, formatted);
const sql = this.getSql(queryOrKnex, formatted, logging);
const res = await this.executeQuery<any>(sql, () => {
const query = this.getKnex().raw(formatted);

Expand All @@ -134,7 +134,7 @@ export abstract class AbstractSqlConnection extends Connection {
}

return query;
}, { query: queryOrKnex, params, ...loggerContext });
}, { query: queryOrKnex, params, ...logging });

return this.transformRawResult<T>(res, method);
}
Expand Down Expand Up @@ -193,14 +193,14 @@ export abstract class AbstractSqlConnection extends Connection {
return config;
}

private getSql(query: string, formatted: string): string {
private getSql(query: string, formatted: string, context?: LogContext): string {
const logger = this.config.getLogger();

if (!logger.isEnabled('query')) {
if (!logger.isEnabled('query', context)) {
return query;
}

if (logger.isEnabled('query-params')) {
if (logger.isEnabled('query-params', context)) {
return formatted;
}

Expand Down
8 changes: 4 additions & 4 deletions packages/knex/src/AbstractSqlDriver.ts
Expand Up @@ -34,7 +34,7 @@ import type {
EntityKey,
EntityValue,
OrderDefinition,
LoggerContext,
LoggingOptions,
} from '@mikro-orm/core';
import {
DatabaseDriver,
Expand Down Expand Up @@ -86,7 +86,7 @@ export abstract class AbstractSqlDriver<Connection extends AbstractSqlConnection

const populate = this.autoJoinOneToOneOwner(meta, options.populate as unknown as PopulateOptions<T>[], options.fields);
const joinedProps = this.joinedProps(meta, populate);
const qb = this.createQueryBuilder<T>(entityName, options.ctx, options.connectionType, false, options.loggerContext);
const qb = this.createQueryBuilder<T>(entityName, options.ctx, options.connectionType, false, options.logging);
const fields = this.buildFields(meta, populate, joinedProps, qb, options.fields as unknown as Field<T>[]);
const joinedPropsOrderBy = this.buildJoinedPropsOrderBy(entityName, qb, meta, joinedProps);
const orderBy = [...Utils.asArray(options.orderBy), ...joinedPropsOrderBy];
Expand Down Expand Up @@ -844,7 +844,7 @@ export abstract class AbstractSqlDriver<Connection extends AbstractSqlConnection
}

/** @internal */
createQueryBuilder<T extends object>(entityName: EntityName<T> | QueryBuilder<T>, ctx?: Transaction<Knex.Transaction>, preferredConnectionType?: ConnectionType, convertCustomTypes?: boolean, loggerContext?: LoggerContext): QueryBuilder<T> {
createQueryBuilder<T extends object>(entityName: EntityName<T> | QueryBuilder<T>, ctx?: Transaction<Knex.Transaction>, preferredConnectionType?: ConnectionType, convertCustomTypes?: boolean, logging?: LoggingOptions): QueryBuilder<T> {
const connectionType = this.resolveConnectionType({ ctx, connectionType: preferredConnectionType });
const qb = new QueryBuilder<T>(
entityName,
Expand All @@ -854,7 +854,7 @@ export abstract class AbstractSqlDriver<Connection extends AbstractSqlConnection
undefined,
connectionType,
undefined,
loggerContext,
logging,
);

if (!convertCustomTypes) {
Expand Down
6 changes: 3 additions & 3 deletions packages/knex/src/query/QueryBuilder.ts
Expand Up @@ -13,7 +13,7 @@ import type {
FlatQueryOrderMap,
FlushMode,
GroupOperator,
LoggerContext,
LoggingOptions,
MetadataStorage,
ObjectQuery,
PopulateOptions,
Expand Down Expand Up @@ -129,7 +129,7 @@ export class QueryBuilder<T extends object = AnyEntity> {
alias?: string,
private connectionType?: ConnectionType,
private readonly em?: SqlEntityManager,
private readonly loggerContext?: LoggerContext) {
private readonly logging?: LoggingOptions) {
if (alias) {
this.aliasCounter++;
this._explicitAlias = true;
Expand Down Expand Up @@ -611,7 +611,7 @@ export class QueryBuilder<T extends object = AnyEntity> {
}

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, this.loggerContext);
const res = await this.driver.getConnection(type).execute(query.sql, query.bindings as any[], method, this.context, this.logging);
const meta = this.mainAlias.metadata;

if (!mapResults || !meta) {
Expand Down
14 changes: 7 additions & 7 deletions packages/mongodb/src/MongoConnection.ts
Expand Up @@ -27,7 +27,7 @@ import type {
EntityName,
FilterQuery,
IsolationLevel,
LoggerContext,
LoggingOptions,
QueryOrderMap,
QueryResult,
Transaction,
Expand Down Expand Up @@ -144,7 +144,7 @@ export class MongoConnection extends Connection {
throw new Error(`${this.constructor.name} does not support generic execute method`);
}

async find<T extends object>(collection: string, where: FilterQuery<T>, orderBy?: QueryOrderMap<T> | QueryOrderMap<T>[], limit?: number, offset?: number, fields?: string[], ctx?: Transaction<ClientSession>, loggerContext?: LoggerContext): Promise<EntityData<T>[]> {
async find<T extends object>(collection: string, where: FilterQuery<T>, orderBy?: QueryOrderMap<T> | QueryOrderMap<T>[], limit?: number, offset?: number, fields?: string[], ctx?: Transaction<ClientSession>, logging?: LoggingOptions): Promise<EntityData<T>[]> {
await this.ensureConnection();
collection = this.getCollectionName(collection);
const options: Dictionary = ctx ? { session: ctx } : {};
Expand Down Expand Up @@ -184,7 +184,7 @@ export class MongoConnection extends Connection {

const now = Date.now();
const res = await resultSet.toArray();
this.logQuery(`${query}.toArray();`, { took: Date.now() - now, ...loggerContext });
this.logQuery(`${query}.toArray();`, { took: Date.now() - now, ...logging });

return res as EntityData<T>[];
}
Expand All @@ -209,15 +209,15 @@ export class MongoConnection extends Connection {
return this.runQuery<T>('deleteMany', collection, undefined, where, ctx);
}

async aggregate<T extends object = any>(collection: string, pipeline: any[], ctx?: Transaction<ClientSession>, loggerContext?: LoggerContext): Promise<T[]> {
async aggregate<T extends object = any>(collection: string, pipeline: any[], ctx?: Transaction<ClientSession>, logging?: LoggingOptions): Promise<T[]> {
await this.ensureConnection();
collection = this.getCollectionName(collection);
/* istanbul ignore next */
const options: Dictionary = ctx ? { session: ctx } : {};
const query = `db.getCollection('${collection}').aggregate(${this.logObject(pipeline)}, ${this.logObject(options)}).toArray();`;
const now = Date.now();
const res = this.getCollection(collection).aggregate<T>(pipeline, options).toArray();
this.logQuery(query, { took: Date.now() - now, ...loggerContext });
this.logQuery(query, { took: Date.now() - now, ...logging });

return res;
}
Expand Down Expand Up @@ -274,7 +274,7 @@ export class MongoConnection extends Connection {
await eventBroadcaster?.dispatchEvent(EventType.afterTransactionRollback, ctx);
}

private async runQuery<T extends object, U extends QueryResult<T> | number = QueryResult<T>>(method: 'insertOne' | 'insertMany' | 'updateMany' | 'bulkUpdateMany' | 'deleteMany' | 'countDocuments', collection: string, data?: Partial<T> | Partial<T>[], where?: FilterQuery<T> | FilterQuery<T>[], ctx?: Transaction<ClientSession>, upsert?: boolean, loggerContext?: LoggerContext): Promise<U> {
private async runQuery<T extends object, U extends QueryResult<T> | number = QueryResult<T>>(method: 'insertOne' | 'insertMany' | 'updateMany' | 'bulkUpdateMany' | 'deleteMany' | 'countDocuments', collection: string, data?: Partial<T> | Partial<T>[], where?: FilterQuery<T> | FilterQuery<T>[], ctx?: Transaction<ClientSession>, upsert?: boolean, logging?: LoggingOptions): Promise<U> {
await this.ensureConnection();
collection = this.getCollectionName(collection);
const logger = this.config.getLogger();
Expand Down Expand Up @@ -337,7 +337,7 @@ export class MongoConnection extends Connection {
break;
}

this.logQuery(query!, { took: Date.now() - now, ...loggerContext });
this.logQuery(query!, { took: Date.now() - now, ...logging });

if (method === 'countDocuments') {
return res! as unknown as U;
Expand Down

0 comments on commit 160a651

Please sign in to comment.