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 authored and B4nan committed Oct 25, 2023
1 parent 98d40c3 commit b1474df
Show file tree
Hide file tree
Showing 13 changed files with 208 additions and 59 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
5 changes: 3 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, LogContext } from '../logging';

export const EntityManagerType = Symbol('EntityManagerType');

Expand Down Expand Up @@ -139,7 +139,8 @@ export interface FindOptions<T, P extends string = never, F extends string = nev
comments?: string | string[];
/** sql only */
hintComments?: string | string[];
loggerContext?: LoggerContext;
loggerContext?: LogContext;
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
2 changes: 1 addition & 1 deletion packages/core/src/errors.ts
Expand Up @@ -103,7 +103,7 @@ export class ValidationError<T extends AnyEntity = AnyEntity> extends Error {
static cannotRemoveFromCollectionWithoutOrphanRemoval(owner: AnyEntity, property: EntityProperty): ValidationError {
const options = [
' - add `orphanRemoval: true` to the collection options',
' - add `onDelete: \'cascade\'` to the owning side options',
' - add `deleteRule: \'cascade\'` to the owning side options',
' - add `nullable: true` to the owning side options',
].join('\n');
return new ValidationError(`Removing items from collection ${owner.constructor.name}.${property.name} without \`orphanRemoval: true\` would break non-null constraint on the owning side. You have several options: \n${options}`, owner);
Expand Down
11 changes: 7 additions & 4 deletions packages/core/src/logging/DefaultLogger.ts
Expand Up @@ -14,7 +14,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 @@ -59,15 +59,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 @@ -40,6 +40,8 @@ export interface LogContext extends Dictionary {
took?: number;
results?: number;
level?: 'info' | 'warning' | 'error';
enabled?: boolean;
debugMode?: LoggerNamespace[];
connection?: {
type?: string;
name?: string;
Expand All @@ -54,10 +56,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
15 changes: 8 additions & 7 deletions packages/knex/src/AbstractSqlConnection.ts
Expand Up @@ -12,7 +12,8 @@ import {
type QueryResult,
type Transaction,
type TransactionEventBroadcaster,
type LoggerContext,
type LogContext,
type LoggingOptions,
} from '@mikro-orm/core';
import type { AbstractSqlPlatform } from './AbstractSqlPlatform';
import { MonkeyPatchable } from './MonkeyPatchable';
Expand Down Expand Up @@ -125,7 +126,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 @@ -136,7 +137,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);
return this.executeQuery<T>(sql, async () => {
const query = this.getKnex().raw(formatted);

Expand All @@ -146,7 +147,7 @@ export abstract class AbstractSqlConnection extends Connection {

const res = await query;
return this.transformRawResult<T>(res, method);
}, { query: queryOrKnex, params, ...loggerContext });
}, { query: queryOrKnex, params, ...logging });
}

/**
Expand Down Expand Up @@ -203,14 +204,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 @@ -31,7 +31,7 @@ import {
type IDatabaseDriver,
LoadStrategy,
type LockOptions,
type LoggerContext,
type LoggingOptions,
type NativeInsertUpdateManyOptions,
type NativeInsertUpdateOptions,
type PopulateOptions,
Expand Down Expand Up @@ -88,7 +88,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 @@ -895,7 +895,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 @@ -905,7 +905,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 @@ -33,7 +33,7 @@ import {
type QueryOrderMap,
type QueryResult,
type RequiredEntityData,
type LoggerContext,
type LoggingOptions,
} from '@mikro-orm/core';
import { QueryType } from './enums';
import type { AbstractSqlDriver } from '../AbstractSqlDriver';
Expand Down Expand Up @@ -134,7 +134,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 @@ -659,7 +659,7 @@ export class QueryBuilder<T extends object = AnyEntity> {

const write = method === 'run' || !this.platform.getConfig().get('preferReadReplicas');
const type = this.connectionType || (write ? '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 (!options.mapResults || !meta) {
Expand Down
15 changes: 8 additions & 7 deletions packages/mongodb/src/MongoConnection.ts
Expand Up @@ -38,7 +38,8 @@ import {
type TransactionEventBroadcaster,
type UpsertOptions,
type UpsertManyOptions,
type LoggerContext,
type LoggingOptions,
type LogContext,
} from '@mikro-orm/core';

export class MongoConnection extends Connection {
Expand Down Expand Up @@ -150,7 +151,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 @@ -190,7 +191,7 @@ export class MongoConnection extends Connection {

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

return res as EntityData<T>[];
}
Expand All @@ -215,15 +216,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 = await this.getCollection(collection).aggregate<T>(pipeline, options).toArray();
this.logQuery(query, { took: Date.now() - now, results: res.length, ...loggerContext });
this.logQuery(query, { took: Date.now() - now, results: res.length, ...logging });

return res;
}
Expand Down Expand Up @@ -280,7 +281,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, upsertOptions?: UpsertOptions<T>, 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, upsertOptions?: UpsertOptions<T>, logging?: LoggingOptions): Promise<U> {
await this.ensureConnection();
collection = this.getCollectionName(collection);
const logger = this.config.getLogger();
Expand Down Expand Up @@ -342,7 +343,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 b1474df

Please sign in to comment.