strong-tie/inbound-calls

1'use strict'2 3const stream = require('node:stream')4 5const t = require('tap')6const split = require('split2')7const pino = require('pino')8 9const Fastify = require('../../fastify')10const helper = require('../helper')11const { once, on } = stream12const { request } = require('./logger-test-utils')13 14t.test('logging', (t) => {15  t.setTimeout(60000)16 17  let localhost18  let localhostForURL19 20  t.plan(13)21 22  t.before(async function () {23    [localhost, localhostForURL] = await helper.getLoopbackHost()24  })25 26  t.test('The default 404 handler logs the incoming request', async (t) => {27    const lines = ['incoming request', 'Route GET:/not-found not found', 'request completed']28    t.plan(lines.length + 1)29 30    const stream = split(JSON.parse)31 32    const loggerInstance = pino({ level: 'trace' }, stream)33 34    const fastify = Fastify({35      loggerInstance36    })37    t.teardown(fastify.close.bind(fastify))38 39    await fastify.ready()40 41    {42      const response = await fastify.inject({ method: 'GET', url: '/not-found' })43      t.equal(response.statusCode, 404)44    }45 46    for await (const [line] of on(stream, 'data')) {47      t.equal(line.msg, lines.shift())48      if (lines.length === 0) break49    }50  })51 52  t.test('should not rely on raw request to log errors', async (t) => {53    const lines = [54      { msg: /Server listening at/ },55      { level: 30, msg: 'incoming request' },56      { res: { statusCode: 415 }, msg: 'something happened' },57      { res: { statusCode: 415 }, msg: 'request completed' }58    ]59    t.plan(lines.length + 1)60    const stream = split(JSON.parse)61    const fastify = Fastify({62      logger: {63        stream,64        level: 'info'65      }66    })67    t.teardown(fastify.close.bind(fastify))68    fastify.get('/error', function (req, reply) {69      t.ok(req.log)70      reply.status(415).send(new Error('something happened'))71    })72 73    await fastify.ready()74    await fastify.listen({ port: 0, host: localhost })75 76    await request(`http://${localhostForURL}:` + fastify.server.address().port + '/error')77 78    for await (const [line] of on(stream, 'data')) {79      t.match(line, lines.shift())80      if (lines.length === 0) break81    }82  })83 84  t.test('should log the error if no error handler is defined', async (t) => {85    const lines = [86      { msg: /Server listening at/ },87      { msg: 'incoming request' },88      { level: 50, msg: 'a generic error' },89      { res: { statusCode: 500 }, msg: 'request completed' }90    ]91    t.plan(lines.length + 1)92 93    const stream = split(JSON.parse)94    const fastify = Fastify({95      logger: {96        stream,97        level: 'info'98      }99    })100    t.teardown(fastify.close.bind(fastify))101 102    fastify.get('/error', function (req, reply) {103      t.ok(req.log)104      reply.send(new Error('a generic error'))105    })106 107    await fastify.ready()108    await fastify.listen({ port: 0, host: localhost })109 110    await request(`http://${localhostForURL}:` + fastify.server.address().port + '/error')111 112    for await (const [line] of on(stream, 'data')) {113      t.match(line, lines.shift())114      if (lines.length === 0) break115    }116  })117 118  t.test('should log as info if error status code >= 400 and < 500 if no error handler is defined', async (t) => {119    const lines = [120      { msg: /Server listening at/ },121      { msg: 'incoming request' },122      { level: 30, msg: 'a 400 error' },123      { res: { statusCode: 400 }, msg: 'request completed' }124    ]125    t.plan(lines.length + 1)126    const stream = split(JSON.parse)127    const fastify = Fastify({128      logger: {129        stream,130        level: 'info'131      }132    })133    t.teardown(fastify.close.bind(fastify))134 135    fastify.get('/400', function (req, reply) {136      t.ok(req.log)137      reply.send(Object.assign(new Error('a 400 error'), { statusCode: 400 }))138    })139    fastify.get('/503', function (req, reply) {140      t.ok(req.log)141      reply.send(Object.assign(new Error('a 503 error'), { statusCode: 503 }))142    })143 144    await fastify.ready()145    await fastify.listen({ port: 0, host: localhost })146 147    await request(`http://${localhostForURL}:` + fastify.server.address().port + '/400')148 149    for await (const [line] of on(stream, 'data')) {150      t.match(line, lines.shift())151      if (lines.length === 0) break152    }153  })154 155  t.test('should log as error if error status code >= 500 if no error handler is defined', async (t) => {156    const lines = [157      { msg: /Server listening at/ },158      { msg: 'incoming request' },159      { level: 50, msg: 'a 503 error' },160      { res: { statusCode: 503 }, msg: 'request completed' }161    ]162    t.plan(lines.length + 1)163    const stream = split(JSON.parse)164    const fastify = Fastify({165      logger: {166        stream,167        level: 'info'168      }169    })170    t.teardown(fastify.close.bind(fastify))171    fastify.get('/503', function (req, reply) {172      t.ok(req.log)173      reply.send(Object.assign(new Error('a 503 error'), { statusCode: 503 }))174    })175 176    await fastify.ready()177    await fastify.listen({ port: 0, host: localhost })178 179    await request(`http://${localhostForURL}:` + fastify.server.address().port + '/503')180 181    for await (const [line] of on(stream, 'data')) {182      t.match(line, lines.shift())183      if (lines.length === 0) break184    }185  })186 187  t.test('should not log the error if error handler is defined and it does not error', async (t) => {188    const lines = [189      { msg: /Server listening at/ },190      { level: 30, msg: 'incoming request' },191      { res: { statusCode: 200 }, msg: 'request completed' }192    ]193    t.plan(lines.length + 2)194    const stream = split(JSON.parse)195    const fastify = Fastify({196      logger: {197        stream,198        level: 'info'199      }200    })201    t.teardown(fastify.close.bind(fastify))202    fastify.get('/error', function (req, reply) {203      t.ok(req.log)204      reply.send(new Error('something happened'))205    })206    fastify.setErrorHandler((err, req, reply) => {207      t.ok(err)208      reply.send('something bad happened')209    })210 211    await fastify.ready()212    await fastify.listen({ port: 0, host: localhost })213 214    await request(`http://${localhostForURL}:` + fastify.server.address().port + '/error')215 216    for await (const [line] of on(stream, 'data')) {217      t.match(line, lines.shift())218      if (lines.length === 0) break219    }220  })221 222  t.test('reply.send logs an error if called twice in a row', async (t) => {223    const lines = [224      'incoming request',225      'request completed',226      'Reply was already sent, did you forget to "return reply" in "/" (GET)?',227      'Reply was already sent, did you forget to "return reply" in "/" (GET)?'228    ]229    t.plan(lines.length + 1)230 231    const stream = split(JSON.parse)232    const loggerInstance = pino(stream)233 234    const fastify = Fastify({235      loggerInstance236    })237    t.teardown(fastify.close.bind(fastify))238 239    fastify.get('/', (req, reply) => {240      reply.send({ hello: 'world' })241      reply.send({ hello: 'world2' })242      reply.send({ hello: 'world3' })243    })244 245    const response = await fastify.inject({ method: 'GET', url: '/' })246    const body = await response.json()247    t.same(body, { hello: 'world' })248 249    for await (const [line] of on(stream, 'data')) {250      t.same(line.msg, lines.shift())251      if (lines.length === 0) break252    }253  })254 255  t.test('should not log incoming request and outgoing response when disabled', async (t) => {256    t.plan(1)257    const stream = split(JSON.parse)258    const fastify = Fastify({ disableRequestLogging: true, logger: { level: 'info', stream } })259    t.teardown(fastify.close.bind(fastify))260 261    fastify.get('/500', (req, reply) => {262      reply.code(500).send(Error('500 error'))263    })264 265    await fastify.ready()266 267    await fastify.inject({ method: 'GET', url: '/500' })268 269    // no more readable data270    t.equal(stream.readableLength, 0)271  })272 273  t.test('should not log incoming request, outgoing response  and route not found for 404 onBadUrl when disabled', async (t) => {274    t.plan(1)275    const stream = split(JSON.parse)276    const fastify = Fastify({ disableRequestLogging: true, logger: { level: 'info', stream } })277    t.teardown(fastify.close.bind(fastify))278 279    await fastify.ready()280 281    await fastify.inject({ method: 'GET', url: '/%c0' })282 283    // no more readable data284    t.equal(stream.readableLength, 0)285  })286 287  t.test('defaults to info level', async (t) => {288    const lines = [289      { reqId: /req-/, req: { method: 'GET' }, msg: 'incoming request' },290      { reqId: /req-/, res: { statusCode: 200 }, msg: 'request completed' }291    ]292    t.plan(lines.length * 2 + 1)293    const stream = split(JSON.parse)294    const fastify = Fastify({295      logger: {296        stream297      }298    })299    t.teardown(fastify.close.bind(fastify))300 301    fastify.get('/', function (req, reply) {302      t.ok(req.log)303      reply.send({ hello: 'world' })304    })305 306    await fastify.ready()307    await fastify.listen({ port: 0 })308 309    await request(`http://${localhostForURL}:` + fastify.server.address().port)310 311    let id312    for await (const [line] of on(stream, 'data')) {313      // we skip the non-request log314      if (typeof line.reqId !== 'string') continue315      if (id === undefined && line.reqId) id = line.reqId316      if (id !== undefined && line.reqId) t.equal(line.reqId, id)317      t.match(line, lines.shift())318      if (lines.length === 0) break319    }320  })321 322  t.test('test log stream', async (t) => {323    const lines = [324      { msg: /^Server listening at / },325      { reqId: /req-/, req: { method: 'GET' }, msg: 'incoming request' },326      { reqId: /req-/, res: { statusCode: 200 }, msg: 'request completed' }327    ]328    t.plan(lines.length + 3)329 330    const stream = split(JSON.parse)331    const fastify = Fastify({332      logger: {333        stream,334        level: 'info'335      }336    })337    t.teardown(fastify.close.bind(fastify))338 339    fastify.get('/', function (req, reply) {340      t.ok(req.log)341      reply.send({ hello: 'world' })342    })343 344    await fastify.ready()345    await fastify.listen({ port: 0, host: localhost })346 347    await request(`http://${localhostForURL}:` + fastify.server.address().port)348 349    let id350    for await (const [line] of on(stream, 'data')) {351      if (id === undefined && line.reqId) id = line.reqId352      if (id !== undefined && line.reqId) t.equal(line.reqId, id)353      t.match(line, lines.shift())354      if (lines.length === 0) break355    }356  })357 358  t.test('test error log stream', async (t) => {359    const lines = [360      { msg: /^Server listening at / },361      { reqId: /req-/, req: { method: 'GET' }, msg: 'incoming request' },362      { reqId: /req-/, res: { statusCode: 500 }, msg: 'kaboom' },363      { reqId: /req-/, res: { statusCode: 500 }, msg: 'request completed' }364    ]365    t.plan(lines.length + 4)366 367    const stream = split(JSON.parse)368    const fastify = Fastify({369      logger: {370        stream,371        level: 'info'372      }373    })374    t.teardown(fastify.close.bind(fastify))375 376    fastify.get('/error', function (req, reply) {377      t.ok(req.log)378      reply.send(new Error('kaboom'))379    })380 381    await fastify.ready()382    await fastify.listen({ port: 0, host: localhost })383 384    await request(`http://${localhostForURL}:` + fastify.server.address().port + '/error')385 386    let id387    for await (const [line] of on(stream, 'data')) {388      if (id === undefined && line.reqId) id = line.reqId389      if (id !== undefined && line.reqId) t.equal(line.reqId, id)390      t.match(line, lines.shift())391      if (lines.length === 0) break392    }393  })394 395  t.test('should not log the error if request logging is disabled', async (t) => {396    t.plan(4)397 398    const stream = split(JSON.parse)399    const fastify = Fastify({400      logger: {401        stream,402        level: 'info'403      },404      disableRequestLogging: true405    })406    t.teardown(fastify.close.bind(fastify))407 408    fastify.get('/error', function (req, reply) {409      t.ok(req.log)410      reply.send(new Error('a generic error'))411    })412 413    await fastify.ready()414    await fastify.listen({ port: 0, host: localhost })415 416    await request(`http://${localhostForURL}:` + fastify.server.address().port + '/error')417 418    {419      const [line] = await once(stream, 'data')420      t.type(line.msg, 'string')421      t.ok(line.msg.startsWith('Server listening at'), 'message is set')422    }423 424    // no more readable data425    t.equal(stream.readableLength, 0)426  })427})428