Pino js tool to make raw pino output compatible with Seq / GELF ingestion through docker

README.md

This is a small tool that allows transforms logs written with pino in newline-delimited JSON on the standard output to the Compact Log Event Format (CLEF) supported by the Seq logging server.

Typical use case for this is :

• write your logs with pino how you would normally do it

logger.info({some: 'extra', context:'info'}, 'this is the message');

• optionally use the Message Template syntax (https://messagetemplates.org/) for more user-friendly logs

logger.info({user: 'John', amount:'2345', extra: 'other info'}, '{user} just spent {amount} euros on the website');

• pipe the output of your app into pino-clef

node my-app.js | node pino-clef

At that point you should have CLEF events on your standard output...

If you are running your app in docker you can now :

• configure docker to use the GELF log driver
• use the sqelf "side-car" container to collect those logs and forward them to a Seq instance

More info

• usage of sqelf with Seq to forward docker structured logs : https://blog.datalust.co/collecting-docker-logs/
• "spec" of the CLEF format : https://github.com/serilog/serilog-formatting-compact
• pino logging library : http://getpino.io/#/
• Message Templates "spec" : https://messagetemplates.org/

pino-clef-formatter.spec.ts

import { toClef } from '../pino-clef-formatter';
import pino, { Logger } from 'pino';
import { Transform, TransformCallback, Stream } from 'stream';
import MockDate from 'mockdate';

describe('pino CLEF formatter', () => {
  describe('toClef with raw input', () => {
    test('should leave non JSON input untouched (but with new line)', () => {
      const input = 'some random string';

      const actual = toClef(input);

      expect(actual).toEqual(input + `\n`);
    });

    test('should leave JSON not coming from pino (i.e. no v:1) untouched (but with new line)', () => {
      const input = JSON.stringify({ not: 'a', pino: 'log' });

      const actual = toClef(input);

      expect(actual).toEqual(input + `\n`);
    });

    test('should leave object untouched (but with new line)', () => {
      const input = { not: 'a', pino: 'log' };

      const actual = toClef(input);

      expect(actual).toEqual(JSON.stringify(input) + `\n`);
    });
  });

  describe('pino output piped into toClef', () => {
    let logger: Logger;
    let iterator: IterableIterator<Promise<any>>;

    beforeEach(() => {
      const obj = createLogger();
      logger = obj.logger;
      iterator = obj.iterator;
    });

    afterEach(() => {
      MockDate.reset();
    });

    const usualPinoProperties = {
      level: expect.any(Number),
      time: expect.any(Number),
      v: 1,
    };

    const usualClefProperties = {
      '@t': expect.stringContaining(''),
    };

    test('should generate @t with timestamp in ISO8601 format', async () => {
      const fakeNow = new Date(1984, 4, 2, 10, 15, 23, 432);
      MockDate.set(fakeNow);
      logger.info('This is a message');

      const output = JSON.parse(toClef(await iterator.next().value));

      expect(output['@t']).toEqual(fakeNow.toISOString());
    });

    test('should generate @mt when passing a message with no template', async () => {
      logger.info('This is a message');

      const output = JSON.parse(toClef(await iterator.next().value));

      expect(output['@mt']).toEqual('This is a message');
    });

    test('should generate @mt when passing a message with a template', async () => {
      logger.info('This is a message about {user} and {app}');

      const output = JSON.parse(toClef(await iterator.next().value));

      expect(output['@mt']).toEqual('This is a message about {user} and {app}');
    });

    test('should have no message when only passing an object', async () => {
      logger.info({ just: 'passing', an: 'object' });

      const output = JSON.parse(toClef(await iterator.next().value));

      expect(output).not.toHaveProperty('@m');
      expect(output).not.toHaveProperty('@mt');
      expect(output).not.toHaveProperty('msg');
    });

    test('should preserve attached object properties', async () => {
      const contextObject = { just: 'passing', an: 'object', with: { nested: 'properties' } };

      logger.info(contextObject);

      const output = JSON.parse(toClef(await iterator.next().value));

      expect(output).toEqual({ ...contextObject, ...usualPinoProperties, ...usualClefProperties });
    });

    describe('levels', () => {
      test('should add @l=0 for trace', async () => {
        logger.trace('trace message');

        const output = JSON.parse(toClef(await iterator.next().value));

        expect(output['@l']).toEqual(0);
      });

      test('should add @l=1 for debug', async () => {
        logger.debug('debug message');

        const output = JSON.parse(toClef(await iterator.next().value));

        expect(output['@l']).toEqual(1);
      });

      test('should not have @l for info', async () => {
        logger.info('info message');

        const output = JSON.parse(toClef(await iterator.next().value));

        expect(output).not.toHaveProperty('@l');
      });

      test('should add @l=3 for warn', async () => {
        logger.warn('warning message');

        const output = JSON.parse(toClef(await iterator.next().value));

        expect(output['@l']).toEqual(3);
      });

      test('should add @l=4 for error', async () => {
        logger.error('error message');

        const output = JSON.parse(toClef(await iterator.next().value));

        expect(output['@l']).toEqual(4);
      });

      test('should add @l=5 for fatal', async () => {
        logger.fatal('fatal message');

        const output = JSON.parse(toClef(await iterator.next().value));

        expect(output['@l']).toEqual(5);
      });
    });

    describe('errors', () => {
      test('should not write @x when there is no error', async () => {
        logger.info({ ok: 'no problem' }, 'everything is fine');

        const output = JSON.parse(toClef(await iterator.next().value));

        expect(output).not.toHaveProperty('@x');
      });

      test('should write @x when error is passed with err', async () => {
        const error = new Error('boom it exploded');
        logger.info({ err: error });

        const output = JSON.parse(toClef(await iterator.next().value));

        expect(output['@x']).toEqual(error.stack);
        expect(typeof output['@x']).toBe('string');
      });
    });
  });
});

function createLogger(): { logger: Logger; iterator: IterableIterator<Promise<any>> } {
  const stream = createJsonWritableStream();
  const logger = pino({ base: {}, level: 'trace' }, stream);
  const iterator = streamToGenerator(stream);
  return {
    logger,
    iterator,
  };
}

// function heavily inspired from https://itnext.io/give-your-logs-more-context-part-2-c2c952724e04
function createJsonWritableStream(): Transform {
  return new Transform({
    objectMode: true,
    transform(chunk: any, encoding: string, cb: TransformCallback): void {
      try {
        const data = JSON.parse(chunk.toString('utf8'));
        return cb(null, data);
      } catch (err) {
        return cb(err);
      }
    },
  });
}

// function heavily inspired from https://itnext.io/give-your-logs-more-context-part-2-c2c952724e04
function* streamToGenerator(stream: Stream): IterableIterator<Promise<any>> {
  while (true) {
    const res = yield Promise.race([
      new Promise(resolve => stream.once('data', resolve)),
      new Promise(resolve => stream.once('end', resolve)),
      new Promise((resolve, reject) => stream.once('end', reject)),
    ]);

    if (!res) {
      break;
    }
  }
}

pino-clef-formatter.ts

// tslint:disable no-var-requires
const jsonParser = require('fast-json-parse');
const stringifySafe = require('fast-safe-stringify');

const EOL = '\n';
const levels: any = {
  60: 5, // FATAL
  50: 4, // ERROR
  40: 3, // WARN
  // 30: 2, // INFO = default when not provided
  20: 1, // DEBUG
  10: 0, // TRACE / Verbose
};

function isObject(input: any): input is any {
  return Object.prototype.toString.apply(input) === '[object Object]';
}

function isPinoLog(log: any): boolean {
  return log && (log.hasOwnProperty('v') && log.v === 1);
}

export function toClef(inputData: string | object): string {
  let log: any;
  if (!isObject(inputData)) {
    const parsed = jsonParser(inputData);
    log = parsed.value;
    if (parsed.err || !isPinoLog(log)) {
      // pass through
      return inputData + EOL;
    }
  } else {
    log = inputData;
  }

  // add the stuff CLEF wants ....
  if (log.time) {
    log['@t'] = new Date(log.time).toISOString();
  }
  if (log.msg) {
    log['@mt'] = log.msg;
  }

  if (log.level && levels.hasOwnProperty(log.level)) {
    log['@l'] = levels[log.level];
  }

  const exception = log.error || log.err;
  if (exception) {
    // Seq wants it as a string - try to prettify it with a legible stack trace
    log['@x'] = exception.stack;
  }

  return stringifySafe(log) + EOL;
}

pino-clef.ts

import { toClef } from './core/infrastructure/logging/pino-clef-formatter';

// tslint:disable no-var-requires
const split = require('split2');
const pump = require('pump');
const through = require('through2');

const myTransport = through.obj((chunk: any, enc: any, cb: (err?: any, res?: string) => void) => {
  const line = toClef(chunk.toString());
  if (line === undefined) return cb();
  cb(null, line);
});

pump(process.stdin, split(), myTransport, process.stdout);