feat: move query logging to a dedicated interceptor

gajus · Feb 24, 2019 · 46301f9 · 46301f9
1 parent da11246
commit 46301f9
Show file tree

Hide file tree

Showing 16 changed files with 26 additions and 199 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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<InterceptorType>,
   +typeParsers?: $ReadOnlyArray<TypeParserType>
 |};

diff --git 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
@@ -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
@@ -1,30 +1,26 @@
 // @flow
 
-import {
-  createLogInterceptor
-} from '../interceptors';
 import type {
   ClientConfigurationType,
   ClientUserConfigurationType
 } from '../types';
 import createTypeParserPreset from './createTypeParserPreset';
 
 export default (clientUserConfiguration?: ClientUserConfigurationType): ClientConfigurationType => {
-  let configuration = {
+  const configuration = {
+    captureStackTrace: true,
+
+    // $FlowFixMe
+    interceptors: [],
+
+    // $FlowFixMe
+    typeParsers: [],
     ...clientUserConfiguration
   };
 
   if (!configuration.typeParsers) {
     configuration.typeParsers = createTypeParserPreset();
   }
 
-  configuration = {
-    ...configuration,
-    interceptors: [
-      createLogInterceptor(),
-      ...configuration.interceptors || []
-    ]
-  };
-
   return configuration;
 };
diff --git 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
diff --git a/src/interceptors/index.js b/src/interceptors/index.js
diff --git 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<InterceptorType>,
   +typeParsers?: $ReadOnlyArray<TypeParserType>
 |};
 
 export type ClientConfigurationType = {|
+  +captureStackTrace: boolean,
   +interceptors: $ReadOnlyArray<InterceptorType>,
   +typeParsers: $ReadOnlyArray<TypeParserType>
 |};

diff --git a/src/utilities/formatNotice.js b/src/utilities/formatNotice.js
diff --git 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
diff --git a/test/helpers/createClientConfiguration.js b/test/helpers/createClientConfiguration.js
@@ -6,6 +6,7 @@ import type {
 
 export default (): ClientConfigurationType => {
   return {
+    captureStackTrace: true,
     interceptors: [],
     typeParsers: []
   };