diff --git a/packages/esix/src/index.ts b/packages/esix/src/index.ts index be09026..fe35a18 100644 --- a/packages/esix/src/index.ts +++ b/packages/esix/src/index.ts @@ -2,6 +2,11 @@ import BaseModel from './base-model' import { ConnectionHandler, connectionHandler } from './connection-handler' import { getCollectionName, resolveCollectionName } from './naming' import QueryBuilder, { type Query } from './query-builder' +import { + setQueryLogger, + type QueryLogEntry, + type QueryLogger +} from './query-logger' import { type ComparisonOperator, type Dictionary, @@ -17,7 +22,8 @@ export { QueryBuilder, connectionHandler, getCollectionName, - resolveCollectionName + resolveCollectionName, + setQueryLogger } export type { ComparisonOperator, @@ -26,5 +32,7 @@ export type { ObjectType, Paginated, Query, + QueryLogEntry, + QueryLogger, QueryValue } diff --git a/packages/esix/src/query-builder.ts b/packages/esix/src/query-builder.ts index 465ae41..eebf368 100644 --- a/packages/esix/src/query-builder.ts +++ b/packages/esix/src/query-builder.ts @@ -4,6 +4,7 @@ import percentile from 'percentile' import type BaseModel from './base-model' import { connectionHandler } from './connection-handler' import { resolveCollectionName } from './naming' +import { resolveQueryLogger, withQueryLogging } from './query-logger' import { sanitize } from './sanitize' import type { ComparisonOperator, @@ -1180,7 +1181,11 @@ export default class QueryBuilder { const collection = await connection.collection(collectionName) - const result = await block(collection) + const logger = resolveQueryLogger() + + const result = await block( + logger ? withQueryLogging(collection, collectionName, logger) : collection + ) return result } diff --git a/packages/esix/src/query-logger.spec.ts b/packages/esix/src/query-logger.spec.ts new file mode 100644 index 0000000..766872d --- /dev/null +++ b/packages/esix/src/query-logger.spec.ts @@ -0,0 +1,334 @@ +import mongodb from 'mongo-mock' +import { v1 as createUuid } from 'uuid' +import { + afterAll, + afterEach, + beforeEach, + describe, + expect, + it, + vi +} from 'vitest' + +import { BaseModel, setQueryLogger, type QueryLogEntry } from './' +import { connectionHandler } from './connection-handler' +import { withQueryLogging } from './query-logger' + +mongodb.max_delay = 1 + +class Invoice extends BaseModel { + public amount = 0 + public name = '' +} + +describe('Query Logging', () => { + beforeEach(() => { + Object.assign(process.env, { + DB_ADAPTER: 'mock', + DB_DATABASE: `test-${createUuid()}` + }) + }) + + afterEach(() => { + setQueryLogger(null) + + delete process.env.DB_LOG_QUERIES + + vi.restoreAllMocks() + }) + + afterAll(() => { + connectionHandler.closeConnections() + }) + + it('logs insertOne entries for created models', async () => { + const entries: QueryLogEntry[] = [] + + setQueryLogger((entry) => { + entries.push(entry) + }) + + await Invoice.create({ name: 'INV-001', amount: 100 }) + + const entry = entries.find((entry) => entry.operation === 'insertOne') + + expect(entry).toBeDefined() + expect(entry?.collectionName).toBe('invoices') + expect(Array.isArray(entry?.args)).toBe(true) + expect(Number.isFinite(entry?.durationMs)).toBe(true) + expect(entry?.durationMs).toBeGreaterThanOrEqual(0) + expect(entry?.error).toBeUndefined() + }) + + it('logs find entries once the cursor is consumed', async () => { + await Invoice.create({ name: 'INV-002', amount: 25 }) + await Invoice.create({ name: 'INV-002', amount: 75 }) + + const entries: QueryLogEntry[] = [] + + setQueryLogger((entry) => { + entries.push(entry) + }) + + const invoices = await Invoice.where('name', 'INV-002') + .orderBy('amount', 'desc') + .limit(1) + .get() + + expect(invoices).toHaveLength(1) + expect(invoices[0].amount).toBe(75) + + const findEntries = entries.filter((entry) => entry.operation === 'find') + + expect(findEntries).toHaveLength(1) + expect(findEntries[0].collectionName).toBe('invoices') + expect(findEntries[0].args[0]).toEqual({ name: 'INV-002' }) + expect(Number.isFinite(findEntries[0].durationMs)).toBe(true) + expect(findEntries[0].durationMs).toBeGreaterThanOrEqual(0) + }) + + it('logs updateOne entries when a model is saved', async () => { + const invoice = await Invoice.create({ name: 'INV-003', amount: 10 }) + + const existingInvoice = await Invoice.find(invoice.id) + + expect(existingInvoice).not.toBeNull() + + if (!existingInvoice) { + return + } + + const entries: QueryLogEntry[] = [] + + setQueryLogger((entry) => { + entries.push(entry) + }) + + existingInvoice.amount = 20 + + await existingInvoice.save() + + const entry = entries.find((entry) => entry.operation === 'updateOne') + + expect(entry).toBeDefined() + expect(entry?.collectionName).toBe('invoices') + expect(entry?.durationMs).toBeGreaterThanOrEqual(0) + }) + + it('logs aggregate entries', async () => { + await Invoice.create({ name: 'INV-004', amount: 5 }) + + // mongo-mock does not implement aggregate, so stub it with a + // cursor-like object to exercise the full logging path. + const connection = await connectionHandler.getConnection() + const collection = await connection.collection('invoices') + + vi.spyOn(collection, 'aggregate').mockReturnValue({ + toArray: () => Promise.resolve([{ total: 5 }]) + } as any) + + const entries: QueryLogEntry[] = [] + + setQueryLogger((entry) => { + entries.push(entry) + }) + + const stages = [{ $group: { _id: null, total: { $sum: '$amount' } } }] + const results = await Invoice.aggregate(stages) + + expect(results).toEqual([{ total: 5 }]) + + const entry = entries.find((entry) => entry.operation === 'aggregate') + + expect(entry).toBeDefined() + expect(entry?.collectionName).toBe('invoices') + expect(entry?.args[0]).toEqual(stages) + expect(entry?.durationMs).toBeGreaterThanOrEqual(0) + }) + + it('logs to console.debug when DB_LOG_QUERIES is enabled', async () => { + process.env.DB_LOG_QUERIES = 'true' + + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}) + + const invoice = await Invoice.create({ name: 'INV-005', amount: 42 }) + const foundInvoice = await Invoice.find(invoice.id) + + expect(foundInvoice?.name).toBe('INV-005') + expect(debugSpy).toHaveBeenCalled() + + const messages = debugSpy.mock.calls.map((call) => call[0]) + + expect( + messages.some( + (message) => + typeof message === 'string' && + message.includes('invoices.insertOne(') && + / took \d+(\.\d+)?ms$/.test(message) + ) + ).toBe(true) + }) + + it('does not log when logging is disabled', async () => { + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}) + + const invoice = await Invoice.create({ name: 'INV-006', amount: 7 }) + const foundInvoice = await Invoice.find(invoice.id) + + expect(foundInvoice?.name).toBe('INV-006') + expect(debugSpy).not.toHaveBeenCalled() + }) + + it('prefers the custom logger over the console logger', async () => { + process.env.DB_LOG_QUERIES = 'true' + + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}) + + const entries: QueryLogEntry[] = [] + + setQueryLogger((entry) => { + entries.push(entry) + }) + + await Invoice.create({ name: 'INV-007', amount: 3 }) + + expect(entries.length).toBeGreaterThan(0) + expect(debugSpy).not.toHaveBeenCalled() + }) +}) + +describe('withQueryLogging', () => { + it('logs the error and still rejects when an operation fails', async () => { + const failure = new Error('write failed') + + const fakeCollection = { + insertOne: (): Promise => Promise.reject(failure) + } + + const entries: QueryLogEntry[] = [] + + const collection = withQueryLogging(fakeCollection, 'books', (entry) => { + entries.push(entry) + }) + + await expect(collection.insertOne()).rejects.toThrow('write failed') + + expect(entries).toHaveLength(1) + expect(entries[0].collectionName).toBe('books') + expect(entries[0].error).toBe(failure) + expect(entries[0].operation).toBe('insertOne') + expect(entries[0].durationMs).toBeGreaterThanOrEqual(0) + }) + + it('does not reject a successful operation when the logger throws', async () => { + const fakeCollection = { + insertOne: (): Promise<{ insertedId: string }> => { + return Promise.resolve({ insertedId: 'book-1' }) + } + } + + const collection = withQueryLogging(fakeCollection, 'books', () => { + throw new Error('logger blew up') + }) + + await expect(collection.insertOne()).resolves.toEqual({ + insertedId: 'book-1' + }) + }) + + it('rejects with the original error when the logger throws', async () => { + const failure = new Error('write failed') + + const fakeCollection = { + updateOne: (): Promise => Promise.reject(failure) + } + + const collection = withQueryLogging(fakeCollection, 'books', () => { + throw new Error('logger blew up') + }) + + await expect(collection.updateOne()).rejects.toBe(failure) + }) + + it('does not break cursor consumption when the logger throws', async () => { + const documents = [{ title: 'Dune' }] + + const fakeCursor = { + toArray: (): Promise[]> => { + return Promise.resolve(documents) + } + } + + const fakeCollection = { + find: () => fakeCursor + } + + const collection = withQueryLogging(fakeCollection, 'books', () => { + throw new Error('logger blew up') + }) + + await expect(collection.find().toArray()).resolves.toEqual(documents) + }) + + it('logs a chained find exactly once with the original arguments', async () => { + const documents = [{ title: 'Dune' }] + + interface FakeCursor { + limit: (count: number) => FakeCursor + sort: (order: Record) => FakeCursor + toArray: () => Promise[]> + } + + const fakeCursor: FakeCursor = { + limit: () => fakeCursor, + sort: () => fakeCursor, + toArray: () => Promise.resolve(documents) + } + + const fakeCollection = { + find: (query: Record): FakeCursor => { + expect(query).toEqual({ title: 'Dune' }) + + return fakeCursor + } + } + + const entries: QueryLogEntry[] = [] + + const collection = withQueryLogging(fakeCollection, 'books', (entry) => { + entries.push(entry) + }) + + const result = await collection + .find({ title: 'Dune' }) + .sort({ title: 1 }) + .limit(1) + .toArray() + + expect(result).toEqual(documents) + + expect(entries).toHaveLength(1) + expect(entries[0].args).toEqual([{ title: 'Dune' }]) + expect(entries[0].collectionName).toBe('books') + expect(entries[0].operation).toBe('find') + expect(entries[0].durationMs).toBeGreaterThanOrEqual(0) + }) + + it('passes non-logged properties through untouched', () => { + const fakeCollection = { + collectionName: 'books', + createIndex: (keys: Record): string => { + return `index:${Object.keys(keys).join(',')}` + }, + namespace: 'library.books' + } + + const collection = withQueryLogging(fakeCollection, 'books', () => { + throw new Error('The logger should not be called.') + }) + + expect(collection.collectionName).toBe('books') + expect(collection.namespace).toBe('library.books') + expect(collection.createIndex({ title: 1 })).toBe('index:title') + }) +}) diff --git a/packages/esix/src/query-logger.ts b/packages/esix/src/query-logger.ts new file mode 100644 index 0000000..66f8da7 --- /dev/null +++ b/packages/esix/src/query-logger.ts @@ -0,0 +1,288 @@ +import { env } from './env' + +/** + * Describes a single MongoDB operation performed by esix. + */ +export interface QueryLogEntry { + /** + * The arguments that were passed to the driver method. + */ + args: unknown[] + + /** + * The name of the collection the operation ran against. + */ + collectionName: string + + /** + * How long the operation took to complete, in milliseconds. + */ + durationMs: number + + /** + * The error the operation rejected with, if any. The rejection still + * propagates to the caller. + */ + error?: unknown + + /** + * The name of the driver method that was invoked, e.g. `updateOne`. + */ + operation: string +} + +/** + * A function that receives a `QueryLogEntry` for every MongoDB operation + * esix runs. Errors thrown by the logger are ignored, so a faulty logger + * never changes the outcome of the operation it observes. + */ +export type QueryLogger = (entry: QueryLogEntry) => void + +type AnyFunction = (...args: unknown[]) => unknown + +interface CursorLogContext { + args: unknown[] + collectionName: string + logger: QueryLogger + operation: string + startedAt: number +} + +const CURSOR_OPERATIONS: ReadonlySet = new Set(['aggregate', 'find']) + +const PROMISE_OPERATIONS: ReadonlySet = new Set([ + 'count', + 'deleteMany', + 'deleteOne', + 'findOne', + 'findOneAndUpdate', + 'insertOne', + 'updateMany', + 'updateOne' +]) + +let customLogger: QueryLogger | null = null + +/** + * Returns the active query logger. A custom logger set with `setQueryLogger` + * takes precedence. When no custom logger is set and the `DB_LOG_QUERIES` + * environment variable is `1` or `true` (case-insensitive), a built-in + * logger that writes to `console.debug` is returned. + * + * @returns The active logger, or `null` when query logging is disabled. + */ +export function resolveQueryLogger(): QueryLogger | null { + if (customLogger) { + return customLogger + } + + const flag = env('DB_LOG_QUERIES').toLowerCase() + + if (flag === '1' || flag === 'true') { + return consoleLogger + } + + return null +} + +/** + * Sets a custom logger that receives a `QueryLogEntry` for every MongoDB + * operation esix runs. + * + * @param logger The logger to use, or `null` to clear the custom logger. + */ +export function setQueryLogger(logger: QueryLogger | null): void { + customLogger = logger +} + +/** + * Wraps a collection in a proxy that reports every MongoDB operation to the + * given logger. Operations that return cursors (`aggregate` and `find`) are + * logged when the cursor is consumed with `toArray`, so their duration + * covers the whole operation including any `sort`, `skip`, or `limit` + * chaining. All other properties pass through untouched. + * + * @param collection The collection to wrap. + * @param collectionName The name of the collection, included in log entries. + * @param logger The logger to report operations to. + * @returns A proxy that behaves like the given collection. + */ +export function withQueryLogging( + collection: T, + collectionName: string, + logger: QueryLogger +): T { + return new Proxy(collection, { + get(target, property) { + const value = Reflect.get(target, property) as unknown + + if (typeof value !== 'function') { + return value + } + + const method = value as AnyFunction + + if (typeof property === 'string') { + if (PROMISE_OPERATIONS.has(property)) { + return createPromiseOperation( + target, + property, + method, + collectionName, + logger + ) + } + + if (CURSOR_OPERATIONS.has(property)) { + return createCursorOperation( + target, + property, + method, + collectionName, + logger + ) + } + } + + return method.bind(target) + } + }) +} + +function consoleLogger(entry: QueryLogEntry): void { + const { args, collectionName, durationMs, operation } = entry + + console.debug( + `esix ${collectionName}.${operation}(${safeStringify(args)}) took ${durationMs.toFixed(1)}ms` + ) +} + +function createCursorOperation( + target: object, + operation: string, + method: AnyFunction, + collectionName: string, + logger: QueryLogger +): AnyFunction { + return (...args: unknown[]) => { + const startedAt = performance.now() + + const cursor = method.apply(target, args) as object + + return wrapCursor(cursor, { + args, + collectionName, + logger, + operation, + startedAt + }) + } +} + +function createPromiseOperation( + target: object, + operation: string, + method: AnyFunction, + collectionName: string, + logger: QueryLogger +): (...args: unknown[]) => Promise { + return (...args: unknown[]) => { + const startedAt = performance.now() + + const result = method.apply(target, args) as Promise + + return result.then( + (value) => { + safeLog(logger, { + args, + collectionName, + durationMs: performance.now() - startedAt, + operation + }) + + return value + }, + (error: unknown) => { + safeLog(logger, { + args, + collectionName, + durationMs: performance.now() - startedAt, + error, + operation + }) + + throw error + } + ) + } +} + +function safeLog(logger: QueryLogger, entry: QueryLogEntry): void { + try { + logger(entry) + } catch { + // A faulty logger must never change the outcome of the operation. + } +} + +function safeStringify(value: unknown): string { + try { + return JSON.stringify(value) + } catch { + return '[unserializable]' + } +} + +function wrapCursor(cursor: object, context: CursorLogContext): object { + const { args, collectionName, logger, operation, startedAt } = context + + const proxy: object = new Proxy(cursor, { + get(target, property) { + const value = Reflect.get(target, property) as unknown + + if (typeof value !== 'function') { + return value + } + + const method = value as AnyFunction + + if (property === 'toArray') { + return (...toArrayArgs: unknown[]) => { + const result = method.apply(target, toArrayArgs) as Promise + + return result.then( + (documents) => { + safeLog(logger, { + args, + collectionName, + durationMs: performance.now() - startedAt, + operation + }) + + return documents + }, + (error: unknown) => { + safeLog(logger, { + args, + collectionName, + durationMs: performance.now() - startedAt, + error, + operation + }) + + throw error + } + ) + } + } + + return (...methodArgs: unknown[]) => { + const result = method.apply(target, methodArgs) + + return result === target ? proxy : result + } + } + }) + + return proxy +} diff --git a/packages/website/docs/configuration.md b/packages/website/docs/configuration.md index e52868e..0066cb5 100644 --- a/packages/website/docs/configuration.md +++ b/packages/website/docs/configuration.md @@ -1,19 +1,28 @@ --- title: Configuration -description: Learn how to configure Esix for your MongoDB database, including connection settings, environment variables, and advanced configuration options. +description: + Learn how to configure Esix for your MongoDB database, including connection + settings, environment variables, and advanced configuration options. --- -Esix makes it easy to configure your database connection for different environments (local, test, and production) using environment variables. This approach helps keep your configuration flexible and secure. +Esix makes it easy to configure your database connection for different +environments (local, test, and production) using environment variables. This +approach helps keep your configuration flexible and secure. ## Database Connection Options -Here are the environment variables you can use to configure your database connection: +Here are the environment variables you can use to configure your database +connection: ### `DB_ADAPTER` The adapter handles the MongoDB connection. You can choose between: -- `default` - Uses the [official MongoDB package](https://www.npmjs.com/package/mongodb) for production -- `mock` - Uses [mongo-mock](https://github.com/williamkapke/mongo-mock) which is perfect for testing + +- `default` - Uses the + [official MongoDB package](https://www.npmjs.com/package/mongodb) for + production +- `mock` - Uses [mongo-mock](https://github.com/williamkapke/mongo-mock) which + is perfect for testing **Default:** `default` @@ -24,6 +33,7 @@ The connection URL for your MongoDB database. **Default:** `mongodb://127.0.0.1:27017/` **Example:** + ```bash DB_URL=mongodb://localhost:27017/ # or for MongoDB Atlas @@ -32,7 +42,8 @@ DB_URL=mongodb+srv://username:password@cluster.mongodb.net/ ### `DB_MAX_POOL_SIZE` -The maximum number of connections in the connection pool. This helps manage database performance under load. +The maximum number of connections in the connection pool. This helps manage +database performance under load. **Default:** `10` @@ -43,13 +54,30 @@ The name of the database to connect to. **Default:** (empty string) **Example:** + ```bash DB_DATABASE=myapp_production ``` +### `DB_LOG_QUERIES` + +Enables the built-in query logger. When set to `1` or `true`, Esix logs every +MongoDB operation to the console using `console.debug`, including the +collection, operation, arguments, and duration. + +**Default:** (disabled) + +**Example:** + +```bash +DB_LOG_QUERIES=true +``` + ## Setting Up Environment Variables -For local development, we recommend using the [dotenv package](https://www.npmjs.com/package/dotenv) to manage your environment variables: +For local development, we recommend using the +[dotenv package](https://www.npmjs.com/package/dotenv) to manage your +environment variables: ```bash npm install dotenv @@ -70,4 +98,43 @@ import 'dotenv/config' // Your Esix code here ``` -> **⚠️ Security Note:** Never commit secrets or production credentials to version control. Add `.env` to your `.gitignore` file! +> **⚠️ Security Note:** Never commit secrets or production credentials to +> version control. Add `.env` to your `.gitignore` file! + +## Query Logging + +Query logging is opt-in and has zero overhead when disabled. The quickest way to +turn it on is the `DB_LOG_QUERIES` environment variable, which logs every +MongoDB operation with `console.debug`: + +``` +esix blog-posts.findOne([{"_id":"5f3568f2a0cdd1c9ba411c43"}]) took 0.8ms +``` + +For full control over where the entries go, register a custom logger with +`setQueryLogger`. The custom logger takes precedence over the built-in console +logger: + +```ts +import { setQueryLogger } from 'esix' + +setQueryLogger((entry) => { + console.log( + `${entry.collectionName}.${entry.operation} took ${entry.durationMs.toFixed(1)}ms` + ) +}) +``` + +Each entry contains: + +- `args` - the arguments passed to the driver method +- `collectionName` - the collection the operation ran against +- `durationMs` - how long the operation took, in milliseconds +- `error` - the error the operation rejected with, if any +- `operation` - the driver method that was invoked, e.g. `find` or `updateOne` + +Pass `null` to clear the custom logger again: + +```ts +setQueryLogger(null) +```