Logging

There are two logging systems and they answer different questions.

Query logging — "what SQL did the ORM just run?" Configured with the
logging option, in the shape Sequelize uses, so existing callbacks work
unchanged.

The Logger — a levelled application logger (debug/info/warn/
error) that the ORM uses for its own lifecycle messages, and that emits
query / slowQuery events.

A third record, the audit log, answers "who changed
which row"; its entries carry a level and can drive an
escalation policy. It is not covered here.

The query event fires on every branch, including logging: false, which is
why metrics belong on the event rather than in the logging function.

Both are fed by one internal path, so every data operation logs — including
count, bulkCreate, increment and the aggregates, which are easy to miss
when logging is bolted onto only the obvious call sites.

Note: sync() DDL reaches the logging callback too, once per
statement: sync({ logging }) for that call, or the instance's logging
otherwise, and sync({ logging: false }) keeps it quiet. Before 4.9.2 the
DDL that the dialect helpers issued during sync() did not reach the
callback at all; only the built-in logger's descriptions (Created table: users) appeared.

Query logging

import { Prorm } from 'ts-prorm-orm';

const prorm = new Prorm({
  dialect: 'postgres',
  /* … */
  logging: console.log,       // false | true | (sql, timing) => void
  benchmark: true,            // append elapsed time
  logQueryParameters: true,   // append bound values
});

`logging` value	Effect
`false`	Nothing is logged.
`true`	Built-in logger writes to `console.log`.
a function	Called as `(sql, timing)`.
unset	Quiet — unless `benchmark: true`, which turns the built-in logger on.

The built-in logger's line mirrors Sequelize's format so existing log parsers
keep working:

Executed (User): SELECT * FROM "users" WHERE "name" = ?; ["Ada"] Elapsed time: 0ms

That line is captured from User.findAll({ where: { name: 'Ada' } }) on SQLite
with logging: true, benchmark: true, logQueryParameters: true.
Executed (<model>) names the model. The ; [...] parameter list appears with
logQueryParameters, and the elapsed time with benchmark. A raw
prorm.query() goes through a shorter path and prints the duration in place of
the model:

Executed (1ms): SELECT 1

A custom function gets the raw SQL, undecorated — decorating it would break
callers that parse or re-format the statement themselves. The timing is always
passed, even without benchmark.

Per-query overrides

logging on a single query wins over the instance setting, in both directions:

// Trace one query on an otherwise-quiet connection
await User.findAll({ where: { id: 1 }, logging: console.log, benchmark: true });

// Silence one noisy query on a logging connection
await Session.findAll({ where: { expired: true }, logging: false });

false at either level wins over a function at the other — silencing is treated
as the more specific intent.

The `Logger`

import { createLogger, LogLevel } from 'ts-prorm-orm';

const logger = createLogger({
  level: 'debug',            // debug | info | warn | error | quiet
  logSQL: true,
  slowQueryThreshold: 500,   // ms
  logSlowQueries: true,
  colors: true,
});

logger.info('starting up', { region: 'eu-west-1' });
logger.child({ requestId: 'req-42' }).debug('handling request');
logger.logQuery('SELECT pg_sleep(1)', 1003);

With colors: false, that prints:

[2026-09-26T22:21:40.377Z] INFO : starting up {"region":"eu-west-1"}
[2026-09-26T22:21:40.389Z] DEBUG: handling request {"requestId":"req-42"}
[2026-09-26T22:21:40.389Z] DEBUG: Executing SQL: SELECT pg_sleep(1)
[2026-09-26T22:21:40.389Z] WARN : Slow query (1003ms): SELECT pg_sleep(1)

The DEBUG: Executing SQL line comes from logSQL: true; the WARN line from
logSlowQueries with a 1003 ms query over the 500 ms threshold.

Level	Value	Shows
`debug`	0	everything
`info`	1	info and above (the default)
`warn`	2	warnings and errors
`error`	3	errors only
`quiet`	4	nothing

Method	Purpose
`debug` / `info` / `warn` / `error`	Log at a level, with optional structured `meta`.
`setLevel` / `getLevel` / `getLevelName` / `isLevelEnabled`	Level control.
`logQuery(sql, duration)`	Feed a query in — emits `query`, and `slowQuery` past the threshold.
`setLogSQL` / `setSlowQueryThreshold`	Adjust at runtime.
`child(meta)`	A logger that stamps `meta` onto every entry.

Output goes to the console with colour and an ISO timestamp; pass a logging
function in the options to route it somewhere else (a file, a JSON transport,
your own logger).

createSilentLogger() gives a logger that swallows everything — the right
thing in tests. getDefaultLogger() / setDefaultLogger() / resetDefaultLogger()
manage the process-wide instance.

Important: those three manage the default logger, which a Prorm
instance does not use — each instance builds its own from its connection
options. setDefaultLogger() therefore will not capture a connection's
lifecycle messages; configure the connection itself, or reach its logger with
prorm.getLogger().

On a connection: prorm.getLogger() returns the instance's logger, and
prorm.setLoggingLevel('debug' | 'info' | 'warn' | 'error') adjusts it.

Events

Every query emits events on the Prorm instance, whether or not logging is
on — the right hook for metrics, tracing, and alerting:

prorm.on('query', ({ sql, duration, model, timestamp }) => {
  metrics.histogram('db.query.ms', duration, { model });
});

prorm.on('slowQuery', ({ sql, duration, threshold, model }) => {
  logger.warn('slow query', { sql, duration, threshold, model });
});

prorm.on('error', (err) => Sentry.captureException(err));

The query payload, captured on SQLite from connect(), User.create() and
User.count() in that order:

{"sql":"ping","duration":0,"timestamp":"2026-09-26T22:21:40.430Z","type":"SELECT"}
{"sql":"INSERT INTO \"users\" (\"name\") VALUES (?)","duration":1,"timestamp":"2026-09-26T22:21:40.437Z","model":"User","type":"INSERT"}
{"sql":"SELECT COUNT(*) AS \"count\" FROM \"users\"","duration":0,"timestamp":"2026-09-26T22:21:40.440Z","model":"User"}

connect() emits one for its liveness ping, so a query counter attached
before connecting starts at one. A statement that fails still emits, with
error: true.

slowQuery fires when a query's duration exceeds slowQueryThreshold
(default 1000 ms), set on the connection options.

The Logger emits its own log, query, slowQuery and error events, if
you would rather listen there.

Sending it to a real logger

console.log is fine locally and wrong in production: no levels, no structure,
nothing an aggregator can query. Both logging systems take a function, so
routing them into pino or winston is a one-liner each.

import pino from 'pino';
import { Prorm, createLogger, setDefaultLogger } from 'ts-prorm-orm';

const log = pino();

const db = new Prorm({
  dialect: 'postgres',
  /* … */
  // Query logging → a debug-level event with the statement as a field, not
  // interpolated into the message, so it stays queryable.
  logging: (sql, ms) => log.debug({ sql, ms }, 'query'),
});

// The ORM's own lifecycle messages → the same logger.
setDefaultLogger(createLogger({
  level: 'info',
  colors: false,                       // no ANSI codes into a JSON transport
  logging: (message) => log.info(message),
}));

import winston from 'winston';
import { Prorm } from 'ts-prorm-orm';

const log = winston.createLogger({
  level: 'debug',
  format: winston.format.json(),
  transports: [new winston.transports.Console()],
});

const db = new Prorm({
  dialect: 'postgres',
  /* … */
  logging: (sql, ms) => log.debug('query', { sql, ms }),
});

db.on('slowQuery', ({ sql, duration, threshold }) =>
  log.warn('slow query', { sql, duration, threshold }));

Turn colors off whenever the destination is not a terminal. The default is on,
and escape codes in a JSON log field are an unpleasant thing to discover later.

Correlating a query with a request

The useful question in production is rarely "what SQL ran" — it is "what SQL ran
for this request". A child logger stamps context onto every entry:

const requestLog = logger.child({ requestId: 'r-8f2', userId: 41 });
requestLog.debug('loading dashboard');
// → [2026-09-26T22:21:40.389Z] DEBUG: loading dashboard {"requestId":"r-8f2","userId":41}

To attach that context to the queries themselves, pass a per-request logging
function. AsyncLocalStorage carries it without threading an argument through
every layer:

import { AsyncLocalStorage } from 'node:async_hooks';

const ctx = new AsyncLocalStorage<{ requestId: string }>();

app.use((req, _res, next) => ctx.run({ requestId: req.id }, next));

const db = new Prorm({
  /* … */
  logging: (sql, ms) => log.debug({ sql, ms, ...ctx.getStore() }, 'query'),
});

Every statement now carries the request that caused it, including the ones you
did not write by hand — the association loads, the hook writes, the migrations.

Recipes

Which queries does this endpoint run? Turn logging on for one request rather
than the whole process:

const rows = await User.findAll({ where: { id }, logging: console.log, benchmark: true });

Why is this slow? Log only the queries that are, and leave everything else
quiet:

const db = new Prorm({ /* … */ logSlowQueries: true, slowQueryThreshold: 200 });
db.on('slowQuery', ({ sql, duration, model }) =>
  log.warn({ sql, duration, model }, 'slow query'));

Is the ORM doing more queries than I think? Count them instead of reading
them — the answer to an N+1 suspicion is a number:

let n = 0;
db.on('query', () => { n++; });
await renderPage();
console.log(`${n} queries`);

What is it doing during startup? Drop the level for a moment:

db.setLoggingLevel('debug');
await db.sync();
db.setLoggingLevel('info');

Configuring it per environment

Keep the switches in the environment so the same build is quiet in production
and verbose on a laptop:

LOG_LEVEL=debug
DB_LOG_SQL=true
DB_SLOW_QUERY_MS=200

In config/config.ts, the file prorm init scaffolds:

import { Prorm, createLogger } from 'ts-prorm-orm';

const level = (process.env.LOG_LEVEL ?? 'info') as 'debug' | 'info' | 'warn' | 'error';
const logSql = process.env.DB_LOG_SQL === 'true';
const logger = createLogger({ level, colors: process.stdout.isTTY === true });

export const prorm = new Prorm({
  dialect: 'postgres',
  host: process.env.DB_HOST,
  database: process.env.DB_NAME,
  username: process.env.DB_USER,
  password: process.env.DB_PASSWORD,
  logging: logSql ? (sql, ms) => logger.debug(`${sql} (${ms}ms)`) : false,
  slowQueryThreshold: Number(process.env.DB_SLOW_QUERY_MS ?? 1000),
  logSlowQueries: true,
});

prorm.setLoggingLevel(level);

In production

Route query logging to debug, not info. It is one line per statement;
at info it will dominate the log volume and cost.

Leave logQueryParameters off. See Redacting values.

Prefer events to log parsing for metrics. on('query') gives you the
duration as a number; scraping it back out of a formatted line does not.

Set colors: false anywhere the output is not a terminal.

Sample rather than silence if volume is the problem — logging one query in
a hundred still shows the shape of the traffic.

import { Prorm } from 'ts-prorm-orm';

const prorm = new Prorm({
  dialect: 'postgres',
  logging: (sql: string, ms?: number) => { if (Math.random() < 0.01) log.debug({ sql, ms }, 'query'); },
});

In tests

A logger that swallows everything keeps test output readable:

import { createSilentLogger, setDefaultLogger, resetDefaultLogger } from 'ts-prorm-orm';

beforeAll(() => setDefaultLogger(createSilentLogger()));
afterAll(() => resetDefaultLogger());

That quiets anything using the process-wide logger. A Prorm instance builds
its own, so silence it where you construct it:

const db = new Prorm({ dialect: 'sqlite', storage: ':memory:', logging: false });

To assert on what was logged, collect into an array instead:

const lines: string[] = [];
const db = new Prorm({ dialect: 'sqlite', storage: ':memory:', logging: (sql) => lines.push(sql) });

await User.create({ name: 'Ada' });
expect(lines.some((l) => l.startsWith('INSERT INTO'))).toBe(true);

Asserting on the SQL is the only way to catch a change in what the ORM emits —
a test that only checks the returned rows passes just as happily when the query
underneath doubles in cost.

Redacting values

[!CAUTION]
logQueryParameters prints bound values, which will include passwords,
tokens and personal data, into every log line. Keep it off in production.

Or filter in your own callback:

const prorm = new Prorm({
  /* … */
  logging: (sql) => logger.debug(sql.replace(/'[^']*'/g, "'?'")),
});

Attributes marked @Sensitive (or @FieldClassification / @Personal) are
redacted by default: their values become [REDACTED] in logged SQL, logged
parameters and the query / slowQuery events, and an instance's toJSON()
drops them (or masks them, when the declaration has a mask). The statement
sent to the database is unchanged. Opt out per setting with false:

const prorm = new Prorm({
  /* … */
  sensitive: { redactInLogs: false, redactInToJSON: false },
});

For an audit trail of who changed what — a different problem from statement
logging — see Audit logging. For structured, policy-driven
capture of access to sensitive columns, see
Compliance.

Audit logging — row-level change history

Query optimization — the standalone SlowQueryLogger with percentiles and alerting

Error handling

Query logging#

Per-query overrides#

The Logger#

Events#

Sending it to a real logger#

Correlating a query with a request#

Recipes#

Configuring it per environment#

In production#

In tests#

Redacting values#

Related reading#