From 46301f96c9a88c0580869fb47a8d6301c7cbea7e Mon Sep 17 00:00:00 2001 From: Gajus Kuizinas Date: Sun, 24 Feb 2019 15:54:20 +0000 Subject: [PATCH] feat: move query logging to a dedicated interceptor --- .README/DEBUGGING.md | 14 ++-- .README/INTERCEPTORS.md | 1 + .README/README.md | 2 +- .README/RECIPES.md | 84 ---------------------- .README/USAGE.md | 2 + package.json | 1 - src/connectionMethods/query.js | 5 +- src/factories/createClientConfiguration.js | 20 +++--- src/factories/createPool.js | 8 ++- src/interceptors/createLogInterceptor.js | 54 -------------- src/interceptors/index.js | 3 - src/types.js | 3 + src/utilities/formatNotice.js | 20 ------ src/utilities/index.js | 2 - src/utilities/isAutoExplainJsonMessage.js | 5 -- test/helpers/createClientConfiguration.js | 1 + 16 files changed, 26 insertions(+), 199 deletions(-) delete mode 100644 src/interceptors/createLogInterceptor.js delete mode 100644 src/interceptors/index.js delete mode 100644 src/utilities/formatNotice.js delete mode 100644 src/utilities/isAutoExplainJsonMessage.js diff --git a/.README/DEBUGGING.md b/.README/DEBUGGING.md index d5cf8057..b699b401 100644 --- a/.README/DEBUGGING.md +++ b/.README/DEBUGGING.md @@ -6,19 +6,13 @@ Slonik uses [roarr](https://github.com/gajus/roarr) to log queries. To enable logging, define `ROARR_LOG=true` environment variable. -By default, Slonik logs the input query, query execution time and affected row count. +By default, Slonik logs only connection events, e.g. when connection is created, connection is acquired and notices. -You can enable additional logging details by configuring the following environment variables. +Query-level logging can be added using [`slonik-interceptor-query-logging`](https://github.com/gajus/slonik-interceptor-query-logging) interceptor. -```bash -# Logs query parameter values -export SLONIK_LOG_VALUES=true +### Capture stack trace -``` - -### Log stack trace - -`SLONIK_LOG_STACK_TRACE=1` will create a stack trace before invoking the query and include the stack trace in the logs, e.g. +Enabling `captureStackTrace` configuration will create a stack trace before invoking the query and include the stack trace in the logs, e.g. ```json {"context":{"package":"slonik","namespace":"slonik","logLevel":20,"executionTime":"357 ms","queryId":"01CV2V5S4H57KCYFFBS0BJ8K7E","rowCount":1,"sql":"SELECT schedule_cinema_data_task();","stackTrace":["/Users/gajus/Documents/dev/applaudience/data-management-program/node_modules/slonik/dist:162:28","/Users/gajus/Documents/dev/applaudience/data-management-program/node_modules/slonik/dist:314:12","/Users/gajus/Documents/dev/applaudience/data-management-program/node_modules/slonik/dist:361:20","/Users/gajus/Documents/dev/applaudience/data-management-program/node_modules/slonik/dist/utilities:17:13","/Users/gajus/Documents/dev/applaudience/data-management-program/src/bin/commands/do-cinema-data-tasks.js:59:21","/Users/gajus/Documents/dev/applaudience/data-management-program/src/bin/commands/do-cinema-data-tasks.js:590:45","internal/process/next_tick.js:68:7"],"values":[]},"message":"query","sequence":4,"time":1540915127833,"version":"1.0.0"} diff --git a/.README/INTERCEPTORS.md b/.README/INTERCEPTORS.md index 5d2688ed..4f3b7b3b 100644 --- a/.README/INTERCEPTORS.md +++ b/.README/INTERCEPTORS.md @@ -104,4 +104,5 @@ Transforms query. |---|---| |[`slonik-interceptor-field-name-transformation`](https://github.com/gajus/slonik-interceptor-field-name-transformation)|Transforms Slonik query result field names.| |[`slonik-interceptor-query-benchmarking`](https://github.com/gajus/slonik-interceptor-query-benchmarking)|Benchmarks Slonik queries.| +|[`slonik-interceptor-query-logging`](https://github.com/gajus/slonik-interceptor-query-logging)|Logs Slonik queries.| |[`slonik-interceptor-query-normalisation`](https://github.com/gajus/slonik-interceptor-query-normalisation)|Normalises Slonik queries.| diff --git a/.README/README.md b/.README/README.md index cc9cd511..e00e136e 100644 --- a/.README/README.md +++ b/.README/README.md @@ -29,7 +29,7 @@ Note: Using this project does not require TypeScript or Flow. It is a regular ES * [Safe value interpolation](#protecting-against-unsafe-value-interpolation). * [Transaction nesting](#transaction-nesting). * Detail [logging](#slonik-debugging). -* [Asynchronous stack trace resolution](#log-stack-trace). +* [Asynchronous stack trace resolution](#capture-stack-trace). * [Middlewares](#slonik-interceptors). * [Mapped errors](#error-handling). * [Atom plugin](#slonik-syntax-highlighting). diff --git a/.README/RECIPES.md b/.README/RECIPES.md index 8577e7b1..e9d13820 100644 --- a/.README/RECIPES.md +++ b/.README/RECIPES.md @@ -85,90 +85,6 @@ Produces: Inserting data this way ensures that the query is stable and reduces the amount of time it takes to parse the query. -### Logging `auto_explain` - -`executionTime` log property describes how long it took for the client to execute the query, i.e. it includes the overhead of waiting for a connection and the network latency, among other things. However, it is possible to get the real query execution time by using [`auto_explain` module](https://www.postgresql.org/docs/current/auto-explain.html). - -There are several pre-requisites: - -```sql --- Load the extension. -LOAD 'auto_explain'; --- or (if you are using AWS RDS): -LOAD '$libdir/plugins/auto_explain'; - --- Enable logging of all queries. -SET auto_explain.log_analyze=true; -SET auto_explain.log_format=json; -SET auto_explain.log_min_duration=0; -SET auto_explain.log_timing=true; - --- Enables Slonik to capture auto_explain logs. -SET client_min_messages=log; - -``` - -This can be configured using `afterPoolConnection` interceptor, e.g. - - - -```js -const pool = createPool('postgres://localhost', { - interceptors: [ - { - afterPoolConnection: async (connection) => { - await connection.query(sql`LOAD 'auto_explain'`); - await connection.query(sql`SET auto_explain.log_analyze=true`); - await connection.query(sql`SET auto_explain.log_format=json`); - await connection.query(sql`SET auto_explain.log_min_duration=0`); - await connection.query(sql`SET auto_explain.log_timing=true`); - await connection.query(sql`SET client_min_messages=log`); - } - } - ] -}); - -``` - -Slonik recognises and parses the `auto_explain` JSON message; Roarr logger will produce a pretty-print of the explain output, e.g. - -```yaml -[2018-12-31T21:15:21.010Z] INFO (30) (@slonik): notice message -notice: - level: notice - message: - Query Text: SELECT count(*) FROM actor - Plan: - Node Type: Aggregate - Strategy: Plain - Partial Mode: Simple - Parallel Aware: false - Startup Cost: 4051.33 - Total Cost: 4051.34 - Plan Rows: 1 - Plan Width: 8 - Actual Startup Time: 26.791 - Actual Total Time: 26.791 - Actual Rows: 1 - Actual Loops: 1 - Plans: - - - Node Type: Seq Scan - Parent Relationship: Outer - Parallel Aware: false - Relation Name: actor - Alias: actor - Startup Cost: 0 - Total Cost: 3561.86 - Plan Rows: 195786 - Plan Width: 0 - Actual Startup Time: 0.132 - Actual Total Time: 15.29 - Actual Rows: 195786 - Actual Loops: 1 - -``` - ### Using `sql.raw` to generate dynamic queries [`sql.raw`](#sqlraw) can be used to generate fragments of an arbitrary SQL that are interpolated into the main query, e.g. diff --git a/.README/USAGE.md b/.README/USAGE.md index 97907f3d..4213250c 100644 --- a/.README/USAGE.md +++ b/.README/USAGE.md @@ -68,10 +68,12 @@ type DatabaseConfigurationType = |}; /** + * @property captureStackTrace Dictates whether to capture stack trace before executing query. Middlewares access stack trace through query execution context. (Default: true) * @property interceptors An array of [Slonik interceptors](https://github.com/gajus/slonik#slonik-interceptors). * @property interceptors An array of [Slonik type parsers](https://github.com/gajus/slonik#slonik-type-parsers). */ type ClientConfigurationType = {| + +captureStackTrace?: boolean, +interceptors?: $ReadOnlyArray, +typeParsers?: $ReadOnlyArray |}; diff --git a/package.json b/package.json index ad3d254b..da19734e 100644 --- a/package.json +++ b/package.json @@ -12,7 +12,6 @@ "dependencies": { "boolean": "^0.2.0", "camelcase": "^5.0.0", - "crack-json": "^1.2.0", "delay": "^4.1.0", "es6-error": "^4.1.1", "get-stack-trace": "^2.0.1", diff --git a/src/connectionMethods/query.js b/src/connectionMethods/query.js index 1d1c9e40..1161fc2c 100644 --- a/src/connectionMethods/query.js +++ b/src/connectionMethods/query.js @@ -4,9 +4,6 @@ import serializeError from 'serialize-error'; import { getStackTrace } from 'get-stack-trace'; -import { - SLONIK_LOG_STACK_TRACE -} from '../config'; import { createQueryId } from '../utilities'; @@ -26,7 +23,7 @@ const query: InternalQueryFunctionType<*> = async (connectionLogger, connection, let stackTrace = null; - if (SLONIK_LOG_STACK_TRACE) { + if (clientConfiguration.captureStackTrace) { const callSites = await getStackTrace(); stackTrace = callSites diff --git a/src/factories/createClientConfiguration.js b/src/factories/createClientConfiguration.js index fb61f8f8..1543850a 100644 --- a/src/factories/createClientConfiguration.js +++ b/src/factories/createClientConfiguration.js @@ -1,8 +1,5 @@ // @flow -import { - createLogInterceptor -} from '../interceptors'; import type { ClientConfigurationType, ClientUserConfigurationType @@ -10,7 +7,14 @@ import type { import createTypeParserPreset from './createTypeParserPreset'; export default (clientUserConfiguration?: ClientUserConfigurationType): ClientConfigurationType => { - let configuration = { + const configuration = { + captureStackTrace: true, + + // $FlowFixMe + interceptors: [], + + // $FlowFixMe + typeParsers: [], ...clientUserConfiguration }; @@ -18,13 +22,5 @@ export default (clientUserConfiguration?: ClientUserConfigurationType): ClientCo configuration.typeParsers = createTypeParserPreset(); } - configuration = { - ...configuration, - interceptors: [ - createLogInterceptor(), - ...configuration.interceptors || [] - ] - }; - return configuration; }; diff --git a/src/factories/createPool.js b/src/factories/createPool.js index 61b18aa3..0f09a505 100644 --- a/src/factories/createPool.js +++ b/src/factories/createPool.js @@ -6,8 +6,7 @@ import { parse as parseConnectionString } from 'pg-connection-string'; import { - createUlid, - formatNotice + createUlid } from '../utilities'; import type { ClientUserConfigurationType, @@ -51,7 +50,10 @@ export default ( client.on('notice', (notice) => { poolLog.info({ - notice: formatNotice(notice) + notice: { + level: notice.name, + message: notice.message + } }, 'notice message'); }); diff --git a/src/interceptors/createLogInterceptor.js b/src/interceptors/createLogInterceptor.js deleted file mode 100644 index ca7ded42..00000000 --- a/src/interceptors/createLogInterceptor.js +++ /dev/null @@ -1,54 +0,0 @@ -// @flow - -import prettyMs from 'pretty-ms'; -import { - SLONIK_LOG_VALUES -} from '../config'; -import type { - InterceptorType -} from '../types'; - -const stringifyCallSite = (callSite) => { - return (callSite.fileName || '') + ':' + callSite.lineNumber + ':' + callSite.columnNumber; -}; - -export default (): InterceptorType => { - return { - afterQueryExecution: (context, query, result) => { - let rowCount: number | null = null; - - if (result.rowCount) { - rowCount = result.rowCount; - } else if (Array.isArray(result)) { - rowCount = result.length; - } - - context.log.debug({ - executionTime: prettyMs(Number(process.hrtime.bigint() - context.queryInputTime) / 1000000), - rowCount - }, 'query execution result'); - - return result; - }, - beforeQueryExecution: async (context, query) => { - let stackTrace; - - if (context.stackTrace) { - stackTrace = context.stackTrace - .filter((callSite) => { - // Hide the internal call sites. - return callSite.fileName !== null && !callSite.fileName.includes('slonik') && !callSite.fileName.includes('next_tick'); - }) - .map((callSite) => { - return stringifyCallSite(callSite); - }); - } - - context.log.debug({ - sql: query.sql, - stackTrace, - values: SLONIK_LOG_VALUES ? query.values : undefined - }, 'executing query'); - } - }; -}; diff --git a/src/interceptors/index.js b/src/interceptors/index.js deleted file mode 100644 index dc13288a..00000000 --- a/src/interceptors/index.js +++ /dev/null @@ -1,3 +0,0 @@ -// @flow - -export {default as createLogInterceptor} from './createLogInterceptor'; diff --git a/src/types.js b/src/types.js index 8943ce88..8ec75dc7 100644 --- a/src/types.js +++ b/src/types.js @@ -60,15 +60,18 @@ export type InternalDatabasePoolType = any; export type InternalDatabaseConnectionType = any; /** + * @property captureStackTrace Dictates whether to capture stack trace before executing query. Middlewares access stack trace through query execution context. (Default: true) * @property interceptors An array of [Slonik interceptors](https://github.com/gajus/slonik#slonik-interceptors). * @property interceptors An array of [Slonik type parsers](https://github.com/gajus/slonik#slonik-type-parsers). */ export type ClientUserConfigurationType = {| + +captureStackTrace?: boolean, +interceptors?: $ReadOnlyArray, +typeParsers?: $ReadOnlyArray |}; export type ClientConfigurationType = {| + +captureStackTrace: boolean, +interceptors: $ReadOnlyArray, +typeParsers: $ReadOnlyArray |}; diff --git a/src/utilities/formatNotice.js b/src/utilities/formatNotice.js deleted file mode 100644 index 5c210c89..00000000 --- a/src/utilities/formatNotice.js +++ /dev/null @@ -1,20 +0,0 @@ -// @flow - -import { - extractJson -} from 'crack-json'; -import isAutoExplainJsonMessage from './isAutoExplainJsonMessage'; - -export default (notice: Error) => { - if (isAutoExplainJsonMessage(notice.message)) { - return { - level: notice.name, - message: extractJson(notice.message)[0] - }; - } - - return { - level: notice.name, - message: notice.message - }; -}; diff --git a/src/utilities/index.js b/src/utilities/index.js index a82eff87..534e7428 100644 --- a/src/utilities/index.js +++ b/src/utilities/index.js @@ -4,7 +4,5 @@ export {default as createQueryId} from './createQueryId'; export {default as createUlid} from './createUlid'; export {default as deepFreeze} from './deepFreeze'; export {default as escapeIdentifier} from './escapeIdentifier'; -export {default as formatNotice} from './formatNotice'; -export {default as isAutoExplainJsonMessage} from './isAutoExplainJsonMessage'; export {default as isPrimitiveValueExpression} from './isPrimitiveValueExpression'; export {default as mapTaggedTemplateLiteralInvocation} from './mapTaggedTemplateLiteralInvocation'; diff --git a/src/utilities/isAutoExplainJsonMessage.js b/src/utilities/isAutoExplainJsonMessage.js deleted file mode 100644 index 3419df88..00000000 --- a/src/utilities/isAutoExplainJsonMessage.js +++ /dev/null @@ -1,5 +0,0 @@ -// @flow - -export default (message: string): boolean => { - return message.trim().startsWith('duration:') && message.includes('{'); -}; diff --git a/test/helpers/createClientConfiguration.js b/test/helpers/createClientConfiguration.js index 1365567a..46671a1d 100644 --- a/test/helpers/createClientConfiguration.js +++ b/test/helpers/createClientConfiguration.js @@ -6,6 +6,7 @@ import type { export default (): ClientConfigurationType => { return { + captureStackTrace: true, interceptors: [], typeParsers: [] };