pino/test/basic.test.js

'use strict'
const os = require('os')
const { join } = require('path')
const { readFileSync } = require('fs')
const { test } = require('tap')
const { sink, check, once } = require('./helper')
const pino = require('../')
const { version } = require('../package.json')
const { pid } = process
const hostname = os.hostname()
const sleep = (ms) => new Promise((resolve) => setTimeout(resolve, ms))

test('pino version is exposed on export', async ({is}) => {
  is(pino.version, version)
})

test('pino version is exposed on instance', async ({is}) => {
  const instance = pino()
  is(instance.version, version)
})

test('child instance exposes pino version', async ({is}) => {
  const child = pino().child({foo: 'bar'})
  is(child.version, version)
})

function levelTest (name, level) {
  test(`${name} logs as ${level}`, async ({is}) => {
    const stream = sink()
    const instance = pino(stream)
    instance.level = name
    instance[name]('hello world')
    check(is, await once(stream, 'data'), level, 'hello world')
  })

  test(`passing objects at level ${name}`, async ({is}) => {
    const stream = sink()
    const instance = pino(stream)
    instance.level = name
    instance[name]({ hello: 'world' })

    const result = await once(stream, 'data')
    is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
    is(result.pid, pid)
    is(result.hostname, hostname)
    is(result.level, level)
    is(result.hello, 'world')
    is(result.v, 1)
  })

  test(`passing an object and a string at level ${name}`, async ({is, same}) => {
    const stream = sink()
    const instance = pino(stream)
    instance.level = name
    instance[name]({ hello: 'world' }, 'a string')
    const result = await once(stream, 'data')
    is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
    delete result.time
    same(result, {
      pid: pid,
      hostname: hostname,
      level: level,
      msg: 'a string',
      hello: 'world',
      v: 1
    })
  })

  test(`formatting logs as ${name}`, async ({is}) => {
    const stream = sink()
    const instance = pino(stream)
    instance.level = name
    instance[name]('hello %d', 42)
    const result = await once(stream, 'data')
    check(is, result, level, 'hello 42')
  })

  test(`passing error with a serializer at level ${name}`, async ({is, same}) => {
    const stream = sink()
    const err = new Error('myerror')
    const instance = pino({
      serializers: {
        err: pino.stdSerializers.err
      }
    }, stream)
    instance.level = name
    instance[name]({ err })
    const result = await once(stream, 'data')
    is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
    delete result.time
    same(result, {
      pid: pid,
      hostname: hostname,
      level: level,
      err: {
        type: 'Error',
        message: err.message,
        stack: err.stack
      },
      v: 1
    })
  })

  test(`child logger for level ${name}`, async ({is, same}) => {
    const stream = sink()
    const instance = pino(stream)
    instance.level = name
    const child = instance.child({ hello: 'world' })
    child[name]('hello world')
    const result = await once(stream, 'data')
    is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
    delete result.time
    same(result, {
      pid: pid,
      hostname: hostname,
      level: level,
      msg: 'hello world',
      hello: 'world',
      v: 1
    })
  })
}

levelTest('fatal', 60)
levelTest('error', 50)
levelTest('warn', 40)
levelTest('info', 30)
levelTest('debug', 20)
levelTest('trace', 10)

test('serializers can return undefined to strip field', async ({is}) => {
  const stream = sink()
  const instance = pino({
    serializers: {
      test () { return undefined }
    }
  }, stream)

  instance.info({ test: 'sensitive info' })
  const result = await once(stream, 'data')
  is('test' in result, false)
})

test('does not explode with a circular ref', async ({doesNotThrow}) => {
  const stream = sink()
  const instance = pino(stream)
  const b = {}
  const a = {
    hello: b
  }
  b.a = a // circular ref
  doesNotThrow(() => instance.info(a))
})

test('explode with a circular ref when safe is false', async ({throws}) => {
  const stream = sink()
  const instance = pino({ safe: false }, stream)
  const b = {}
  const a = {
    hello: b
  }
  b.a = a // circular ref
  throws(() => instance.info(a))
})

test('set the name', async ({is, same}) => {
  const stream = sink()
  const instance = pino({
    name: 'hello'
  }, stream)
  instance.fatal('this is fatal')
  const result = await once(stream, 'data')
  is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 60,
    name: 'hello',
    msg: 'this is fatal',
    v: 1
  })
})

test('set the messageKey', async ({is, same}) => {
  const stream = sink()
  const message = 'hello world'
  const messageKey = 'fooMessage'
  const instance = pino({
    messageKey
  }, stream)
  instance.info(message)
  const result = await once(stream, 'data')
  is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 30,
    fooMessage: message,
    v: 1
  })
})

test('set undefined properties', async ({is, same}) => {
  const stream = sink()
  const instance = pino(stream)
  instance.info({ hello: 'world', property: undefined })
  const result = await once(stream, 'data')
  is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 30,
    hello: 'world',
    v: 1
  })
})

test('prototype properties are not logged', async ({is}) => {
  const stream = sink()
  const instance = pino(stream)
  instance.info(Object.create({hello: 'world'}))
  const { hello } = await once(stream, 'data')
  is(hello, undefined)
})

test('set the base', async ({is, same}) => {
  const stream = sink()
  const instance = pino({
    base: {
      a: 'b'
    }
  }, stream)

  instance.fatal('this is fatal')
  const result = await once(stream, 'data')
  is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
  delete result.time
  same(result, {
    a: 'b',
    level: 60,
    msg: 'this is fatal',
    v: 1
  })
})

test('set the base to null', async ({is, same}) => {
  const stream = sink()
  const instance = pino({
    base: null
  }, stream)
  instance.fatal('this is fatal')
  const result = await once(stream, 'data')
  is(new Date(result.time) <= new Date(), true, 'time is greater than Date.now()')
  delete result.time
  same(result, {
    level: 60,
    msg: 'this is fatal',
    v: 1
  })
})

test('throw if creating child without bindings', async ({throws}) => {
  const stream = sink()
  const instance = pino(stream)
  throws(() => instance.child())
})

test('correctly escapes msg strings with stray double quote at end', async ({same}) => {
  const stream = sink()
  const instance = pino({
    name: 'hello'
  }, stream)

  instance.fatal('this contains "')
  const result = await once(stream, 'data')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 60,
    name: 'hello',
    msg: 'this contains "',
    v: 1
  })
})

test('correctly escape msg strings with unclosed double quote', async ({same}) => {
  const stream = sink()
  const instance = pino({
    name: 'hello'
  }, stream)
  instance.fatal('" this contains')
  const result = await once(stream, 'data')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 60,
    name: 'hello',
    msg: '" this contains',
    v: 1
  })
})

// https://github.com/pinojs/pino/issues/139
test('object and format string', async ({same}) => {
  const stream = sink()
  const instance = pino(stream)
  instance.info({}, 'foo %s', 'bar')

  const result = await once(stream, 'data')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 30,
    msg: 'foo bar',
    v: 1
  })
})

test('object and format string property', async ({same}) => {
  const stream = sink()
  const instance = pino(stream)
  instance.info({ answer: 42 }, 'foo %s', 'bar')
  const result = await once(stream, 'data')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 30,
    msg: 'foo bar',
    answer: 42,
    v: 1
  })
})

test('correctly strip undefined when returned from toJSON', async ({is}) => {
  const stream = sink()
  const instance = pino({
    test: 'this'
  }, stream)
  instance.fatal({test: {toJSON () { return undefined }}})
  const result = await once(stream, 'data')
  is('test' in result, false)
})

test('correctly supports stderr', async ({same}) => {
  // stderr inherits from Stream, rather than Writable
  const dest = {
    writable: true,
    write (result) {
      result = JSON.parse(result)
      delete result.time
      same(result, {
        pid: pid,
        hostname: hostname,
        level: 60,
        msg: 'a message',
        v: 1
      })
    }
  }
  const instance = pino(dest)
  instance.fatal('a message')
})

test('normalize number to string', async ({same}) => {
  const stream = sink()
  const instance = pino(stream)
  instance.info(1)
  const result = await once(stream, 'data')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 30,
    msg: '1',
    v: 1
  })
})

test('normalize number to string with an object', async ({same}) => {
  const stream = sink()
  const instance = pino(stream)
  instance.info({ answer: 42 }, 1)
  const result = await once(stream, 'data')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 30,
    msg: '1',
    answer: 42,
    v: 1
  })
})

test('handles objects with null prototype', async ({same}) => {
  const stream = sink()
  const instance = pino(stream)
  const o = Object.create(null)
  o.test = 'test'
  instance.info(o)
  const result = await once(stream, 'data')
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 30,
    test: 'test',
    v: 1
  })
})

test('pino.destination', async ({same}) => {
  const tmp = join(
    os.tmpdir(),
    '_' + Math.random().toString(36).substr(2, 9)
  )
  const instance = pino(pino.destination(tmp))
  instance.info('hello')
  await sleep(250)
  const result = JSON.parse(readFileSync(tmp).toString())
  delete result.time
  same(result, {
    pid: pid,
    hostname: hostname,
    level: 30,
    msg: 'hello',
    v: 1
  })
})

// https://github.com/pinojs/pino/issues/222
test('children with same names render in correct order', async ({is}) => {
  const stream = sink()
  const root = pino(stream)
  root.child({a: 1}).child({a: 2}).info({a: 3})
  const { a } = await once(stream, 'data')
  is(a, 3, 'last logged object takes precedence')
})

// https://github.com/pinojs/pino/pull/251 - use this.stringify
test('when safe is true it should ONLY use `fast-safe-stringify`', async ({deepEqual}) => {
  const stream = sink()
  const root = pino({ safe: true }, stream)
  // circular depth
  const obj = {}
  obj.a = obj
  root.info(obj)
  const { a } = await once(stream, 'data')
  deepEqual(a, { a: '[Circular]' })
})

test('when safe is true, fast-safe-stringify must be used when interpolating', async (t) => {
  const stream = sink()
  const instance = pino({safe: true}, stream)

  const o = { a: { b: {} } }
  o.a.b.c = o.a.b
  instance.info('test', o)

  const { msg } = await once(stream, 'data')
  t.is(msg, 'test {"a":{"b":{"c":"[Circular]"}}}')
})

test('when safe is false, interpolation should throw', async (t) => {
  const stream = sink()
  const instance = pino({safe: false}, stream)
  var o = { a: { b: {} } }
  o.a.b.c = o.a.b
  try {
    instance.info('test', o)
  } catch (e) {
    t.is(e.message, 'Converting circular structure to JSON')
    return
  }
  t.fail('must throw')
})