feat(core): add customizable LoggerContext with labeling support

docs/docs/logging.md

@@ -30,9 +30,51 @@ It is also useful for debugging problems with entity discovery, as you will see
 [discovery] - entity discovery finished after 13 ms
 ```
 
-## Custom Logger
+## Disabling colored output
+
+To disable colored output, we can use multiple environment variables:
+
+- `NO_COLOR`
+- `MIKRO_ORM_NO_COLOR`
+- `FORCE_COLOR`
+
+## Logger Namespaces
+
+There are multiple Logger Namespaces that you can specifically request, while omitting the rest. Just specify array of them via the `debug` option:
+
+```ts
+return MikroORM.init({
+  debug: ['query'], // now only queries will be logged
+});
+```
+
+Currently, there are 5 namespaces – `query`, `query-params`, `schema`, `discovery` and `info`.
+
+If you provide `query-params` then you must also provide `query` in order for it to take effect.
 
-We can also provide our own logger function via `logger` option.
+## Highlighters
+
+Previously Highlight.js was used to highlight various things in the CLI, like SQL and mongo queries, or migrations or entities generated via CLI. While the library worked fine, it was causing performance issues mainly for those bundling via webpack and using lambdas, as the library was huge.
+
+Since v4, highlighting is disabled by default, and there are 2 highlighters you can optionally use (you need to install them first).
+
+```ts
+import { SqlHighlighter } from '@mikro-orm/sql-highlighter';
+
+MikroORM.init({
+  highlighter: new SqlHighlighter(),
+  // ...
+});
+```
+
+For MongoDB you can use `MongoHighlighter` from `@mikro-orm/mongo-highlighter` package.
+
+## Logger Customization
+Several customization options exist to allow for style changes or custom logic.
+
+### Using a custom logger
+
+We can provide our own logger function via the `logger` option:
 
 ```ts
 return MikroORM.init({
@@ -41,7 +83,33 @@ return MikroORM.init({
 });
 ```
 
-If we want to have more control over logging, we can use `loggerFactory` and use our own implementation of the `Logger` interface:
+### Using a custom `LoggerFactory`
+If you want more control over what is logged and how, use the `loggerFactory` option in your config and either extend the `DefaultLogger` class or make your `Logger` from scratch:
+
+#### Extending `DefaultLogger`
+We can extend the `DefaultLogger` instead of implementing everything from scratch. It is also exported from the `@mikro-orm/core` package:
+
+```ts
+class CustomLogger extends DefaultLogger {
+  log(namespace: LoggerNamespace, message: string, context?: LogContext) {
+    // Create your own implementation for output:
+    console.log(`[${namespace}] (${context.label}) ${message}`);
+
+    // OR Utilize DefaultLogger's implementation:
+    super.log(namespace, message, context)
+  }
+}
+
+return MikroORM.init({
+  debug: true,
+  loggerFactory: (options) => new CustomLogger(options),
+});
+```
+
+
+
+#### Creating a custom logger from scratch
+We can use `loggerFactory` and use our own implementation of the `Logger` interface:
 
 ```ts
 import { Logger, LoggerOptions, MikroORM, Configuration } from '@mikro-orm/core';
@@ -52,12 +120,10 @@ class MyLogger implements Logger {
 
 const orm = await MikroORM.init({
   debug: true,
-  loggerFactory: (options: LoggerOptions) => new MyLogger(config),
+  loggerFactory: (options) => new MyLogger(options),
 });
 ```
 
-We can also extend the `DefaultLogger` instead of implementing everything from scratch. It is also exported from the `@mikro-orm/core` package.
-
 The `Logger` interface is defined as follows:
 
 ```ts
@@ -70,10 +136,11 @@ interface Logger {
   isEnabled(namespace: LoggerNamespace): boolean;
 }
 
-type LoggerNamespace = 'query' | 'query-params' | 'discovery' | 'info';
+type LoggerNamespace = 'query' | 'query-params' | 'schema' | 'discovery' | 'info';
 
-interface LogContext {
+interface LogContext extends Dictionary {
   query?: string;
+  label?: string;
   params?: unknown[];
   took?: number;
   level?: 'info' | 'warning' | 'error';
@@ -84,41 +151,29 @@ interface LogContext {
 }
 ```
 
-## Disabling colored output
-
-To disable colored output, we can use multiple environment variables:
-
-- `NO_COLOR`
-- `MIKRO_ORM_NO_COLOR`
-- `FORCE_COLOR`
+### Query Labels
 
-## Logger Namespaces
+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. 
 
-There are multiple Logger Namespaces that you can specifically request, while omitting the rest. Just specify array of them via the `debug` option:
+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
-return MikroORM.init({
-  debug: ['query'], // now only queries will be logged
-});
+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]
 ```
 
-Currently, there are 4 namespaces – `query`, `query-params`, `discovery` and `info`.
-
-If you provide `query-params` then you must also provide `query` in order for it to take effect.
-
-## Highlighters
-
-Previously Highlight.js was used to highlight various things in the CLI, like SQL and mongo queries, or migrations or entities generated via CLI. While the library worked fine, it was causing performance issues mainly for those bundling via webpack and using lambdas, as the library was huge.
-
-Since v4, highlighting is disabled by default, and there are 2 highlighters you can optionally use (you need to install them first).
+### 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
-import { SqlHighlighter } from '@mikro-orm/sql-highlighter';
+const author = await em.findOne(Author, { id: 1 }, { loggerContext: { meaningOfLife: 42 } });
 
-MikroORM.init({
-  highlighter: new SqlHighlighter(),
-  // ...
-});
-```
+// ...
 
-For MongoDB you can use `MongoHighlighter` from `@mikro-orm/mongo-highlighter` package.
+class CustomLogger extends DefaultLogger {
+  log(namespace: LoggerNamespace, message: string, context?: LogContext) {
+    console.log(context?.meaningOfLife);
+    // 42
+  }
+}
+```

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<T, P extends string = never, F extends string = nev
   lockTableAliases?: string[];
   ctx?: Transaction;
   connectionType?: ConnectionType;
+  loggerContext?: LoggerContext;
 }
 
 export interface FindByCursorOptions<T extends object, P extends string = never, F extends string = never> extends Omit<FindOptions<T, P, F>, 'limit' | 'offset'> {

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);
   }
 
   /**

packages/core/src/logging/Logger.ts

@@ -1,4 +1,4 @@
-import type { Highlighter } from '../typings';
+import type { Dictionary, Highlighter } from '../typings';
 
 export interface Logger {
 
@@ -33,8 +33,9 @@ export interface Logger {
 
 export type LoggerNamespace = 'query' | 'query-params' | 'schema' | 'discovery' | 'info';
 
-export interface LogContext {
+export interface LogContext extends Dictionary {
   query?: string;
+  label?: string;
   params?: unknown[];
   took?: number;
   level?: 'info' | 'warning' | 'error';
@@ -50,3 +51,12 @@ export interface LoggerOptions {
   highlighter?: Highlighter;
   usesReplicas?: boolean;
 }
+
+/**
+ * Context for a logger to utilize to format output, including a label and additional properties that can be accessed by custom loggers
+ *
+ * @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;

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}`);
   }
 
   /**

packages/knex/src/AbstractSqlConnection.ts

@@ -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, QueryResult,
+  AnyEntity, Configuration, ConnectionOptions, EntityData, IsolationLevel, LoggerContext, QueryResult,
   Transaction, TransactionEventBroadcaster } from '@mikro-orm/core';
 import { Connection, EventType, Utils,
 } from '@mikro-orm/core';
@@ -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): 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, loggerContext?: LoggerContext): Promise<T> {
     await this.ensureConnection();
 
     if (Utils.isObject<Knex.QueryBuilder | Knex.Raw>(queryOrKnex)) {
@@ -134,7 +134,7 @@ export abstract class AbstractSqlConnection extends Connection {
       }
 
       return query;
-    }, { query: queryOrKnex, params });
+    }, { query: queryOrKnex, params, ...loggerContext });
 
     return this.transformRawResult<T>(res, method);
   }

packages/knex/src/AbstractSqlDriver.ts

@@ -34,6 +34,7 @@ import type {
   EntityKey,
   EntityValue,
   OrderDefinition,
+  LoggerContext,
 } from '@mikro-orm/core';
 import {
   DatabaseDriver,
@@ -85,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);
+    const qb = this.createQueryBuilder<T>(entityName, options.ctx, options.connectionType, false, options.loggerContext);
     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];
@@ -843,9 +844,18 @@ 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): QueryBuilder<T> {
+  createQueryBuilder<T extends object>(entityName: EntityName<T> | QueryBuilder<T>, ctx?: Transaction<Knex.Transaction>, preferredConnectionType?: ConnectionType, convertCustomTypes?: boolean, loggerContext?: LoggerContext): QueryBuilder<T> {
     const connectionType = this.resolveConnectionType({ ctx, connectionType: preferredConnectionType });
-    const qb = new QueryBuilder<T>(entityName, this.metadata, this, ctx, undefined, connectionType);
+    const qb = new QueryBuilder<T>(
+      entityName,
+      this.metadata,
+      this,
+      ctx,
+      undefined,
+      connectionType,
+      undefined,
+      loggerContext,
+    );
 
     if (!convertCustomTypes) {
       qb.unsetFlag(QueryFlag.CONVERT_CUSTOM_TYPES);

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<T extends object = AnyEntity> {
               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<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);
+    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) {

packages/mongodb/src/MongoConnection.ts

@@ -27,6 +27,7 @@ import type {
   EntityName,
   FilterQuery,
   IsolationLevel,
+  LoggerContext,
   QueryOrderMap,
   QueryResult,
   Transaction,
@@ -143,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>): 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>, loggerContext?: LoggerContext): Promise<EntityData<T>[]> {
     await this.ensureConnection();
     collection = this.getCollectionName(collection);
     const options: Dictionary = ctx ? { session: ctx } : {};
@@ -183,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 });
+    this.logQuery(`${query}.toArray();`, { took: Date.now() - now, ...loggerContext });
 
     return res as EntityData<T>[];
   }
@@ -208,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>): Promise<T[]> {
+  async aggregate<T extends object = any>(collection: string, pipeline: any[], ctx?: Transaction<ClientSession>, loggerContext?: LoggerContext): 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 });
+    this.logQuery(query, { took: Date.now() - now, ...loggerContext });
 
     return res;
   }
@@ -273,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): 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, loggerContext?: LoggerContext): Promise<U> {
     await this.ensureConnection();
     collection = this.getCollectionName(collection);
     const logger = this.config.getLogger();
@@ -336,7 +337,7 @@ export class MongoConnection extends Connection {
         break;
     }
 
-    this.logQuery(query!, { took: Date.now() - now });
+    this.logQuery(query!, { took: Date.now() - now, ...loggerContext });
 
     if (method === 'countDocuments') {
       return res! as unknown as U;