Skip to content

Latest commit

 

History

History
234 lines (181 loc) · 8.26 KB

README.md

File metadata and controls

234 lines (181 loc) · 8.26 KB

🐨 Request Logging 🐨

Introduction

This add-on facilitates logging information about requests and responses. It's intended to work with an app-provided logger such as pino or Bunyan.

It provides three main features:

Context Logging

createContextStorage returns a logger context storage instance with two methods: createContextMiddleware and mixin. This is simply a wrapper over an AsyncLocalStorage instance. Please note: for performance reasons it is recommended that you use Node.js version v16.2.0+ if you intend to use this.

createContextMiddleware is a function which returns a Koa Middleware that injects the logger context into an AsyncLocalStorage instance. It must be added early in the Koa Middleware chain if you want logger calls to contain request context fields. It also provides an optional getFieldsFn parameter if you wish to provide your own context fields alongside the default contextFields.

const contextMiddleware = createContextMiddleware();

const customContextMiddleware = createContextMiddleware((ctx, fields) => ({
  advertiserId: ctx.state.advertiserId,
  ...fields,
}));

mixin is a function which returns the context fields from the storage. It returns an empty object if no context can be found. This should be called every time a logger is called. You can attach this to Pino's mixin field when you create a logger instance.

Attaching the contextMiddleware to the Koa Middleware chain and mixin to the logger instance will enable you to import the logger instance in any file and still retain logger context.

Usage

// This example uses pino. See the next section for a Bunyan example.
import pino from 'pino';
import { RequestLogging } from 'seek-koala';

const { createContextMiddleware, mixin } = createLoggerContextStorage();

const contextMiddleware = createContextMiddleware();

const logger = pino({
  name: appConfig.name,
  base: {
    version: appConfig.version,
  },
  mixin,
});

const helloWorldHandler = async (ctx: Koa.Context) => {
  logger.info('About to return Hello World!');

  ctx.body = 'Hello world';
};

const router = new Router().get(
  'readGreeting',
  '/internal/:greeting',
  helloWorldHandler,
);

const app = new Koa()
  .use(contextMiddleware);
  .use(router.routes())
  .use(router.allowedMethods())

Context Fields

contextFields returns an object containing key-value pairs for the request method, route, URL, X-Request-Id and ad-hoc X-Session-Id. This is intended to provide the essential information about the request; the full request details can be correlated with the request log via x-request-id.

The route properties assume use of @koa/router, and are omitted if the expected metadata is not present on context.

The returned object can be used to construct a child logger that annotates log entries with request-specific information. This can be accomplished using the child method of Bunyan or pino loggers.

You may override or supply your own fields using the optional fields parameter.

const fields = contextFields(ctx);

const customFields = contextFields(ctx, { myField: 'hello world!' });

contextFields requires access to the Koa context to generate a stable X-Request-Id. See the TracingHeaders add-on for more information.

Example Log Entry

{
  "method": "GET",
  // `route` and `routeName` are present where provided by `@koa/router`
  "route": "/internal/:greeting",
  "routeName": "readGreeting",
  "url": "/internal/_helloworld",
  "x-request-id": "28f9be45-c403-476b-8351-f222318aeaf5",
  // `x-session-id` is present only where provided by the client
  "x-session-id": "49cd6fd8-3e74-42b6-b63d-ee7b13e5edf5",
  "name": "ca-example-service",
  "level": 30,
  "msg": "About to return Hello World!",
  "time": "2018-10-16T00:15:35.009Z",
  "version": "abcdefg.123",
}

Usage

// This example uses pino. See the next section for a Bunyan example.
import pino from 'pino';
import { RequestLogging } from 'seek-koala';

// Create a root logger with the app name and version
const rootLogger = pino({
  name: appConfig.name,
  base: {
    version: appConfig.version,
  },
});

const helloWorldHandler = async (ctx: Koa.Context) => {
  // Create a request-specific logger
  // NB: This is not required if you are using the logger context storage implementation
  const logger = rootLogger.child(RequestLogging.contextFields(ctx));
  logger.info('About to return Hello World!');

  ctx.body = 'Hello world';
};

const router = new Router().get(
  'readGreeting',
  '/internal/:greeting',
  helloWorldHandler,
);

const app = new Koa().use(router.routes()).use(router.allowedMethods());

Request Log

createMiddleware records information incoming requests and outgoing responses. It calls a provided callback for every response with a set of fields to be logged. These fields include the context fields with the addition of the request headers, response code and latency in milliseconds.

Apps deployed using Gantry have similar functionality provided by seek-auth-sidecar's access logs. This middleware should only be used if additional fields are required beyond seek-auth-sidecar's access log format.

An individual request can opt out of request logs by setting a skipRequestLogging property on the state. This is useful to reduce noise from health check handlers.

Some headers can contain sensitive information such as JWTs or session cookies. By default the request log will redact the Authorization, Authenticated-User, Cookie, User-Email, X-Seek-Oidc-Identity headers to avoid sending them to third-party logging services. The header replacements can by configured by passing a map of the lowercased header name to its replacement to createMiddleware.

If an uncaught exception passes through the request log middleware it will attach err.toString() as the internalErrorString field. This is a convenience that shouldn't be used as a replacement for error handling in handlers or app.on('error').

Usage

// This example uses Bunyan. See the previous section for a pino example.
import bunyan from 'bunyan';
import { RequestLogging } from 'seek-koala';

const logger = bunyan.createLogger({
  name: appConfig.name,
  version: appConfig.version,
});

const requestLogMiddleware = RequestLogging.createMiddleware((ctx, fields) => {
  logger.info(
    {
      userEmail: ctx.state.userEmail,
      ...fields,
    },
    'request log',
  );
});

app.use(requestLogMiddleware);

const helloWorldHandler = async (ctx: Koa.Context) => {
  ctx.body = 'Hello world';
};

const healthCheckHandler = async (ctx: Koa.Context) => {
  ctx.state.skipRequestLogging = true;
  ctx.body = 'OK';
};

Example Log Entry

{
  "method": "GET",
  "url": "/internal/_smoketest",
  "x-request-id": "3ac3971e-32e1-4f01-aa2f-4c3207366142",
  "name": "ca-example-service",
  "hostname": "L3088",
  "pid": 39198,
  "level": 30,
  "latency": 881,
  "headers": {
    "authorization": "🐨 REDACTED 🙅",
    "content-type": "application/json",
    "cache-control": "no-cache",
    "postman-token": "fd26ffff-5c33-4cec-b79a-c329941cf586",
    "user-agent": "PostmanRuntime/7.3.0",
    "host": "localhost:8001",
    "connection": "keep-alive"
  },
  "status": 500,
  "internalErrorString": "ExpiredTokenException: The security token included in the request is expired",
  "err": {
    "message": "The security token included in the request is expired",
    "name": "ExpiredTokenException",
    "stack": "..."
  },
  "msg": "request log",
  "time": "2018-10-16T00:44:41.055Z",
  "v": 0
}