1 | 'use strict'
|
2 |
|
3 | const { test, tearDown } = require('tap')
|
4 | const http = require('http')
|
5 | const stream = require('stream')
|
6 | const split = require('split2')
|
7 | const Fastify = require('..')
|
8 | const pino = require('pino')
|
9 | const path = require('path')
|
10 | const os = require('os')
|
11 | const fs = require('fs')
|
12 | const sget = require('simple-get').concat
|
13 |
|
14 | const files = []
|
15 | let count = 0
|
16 |
|
17 | function file () {
|
18 | const file = path.join(os.tmpdir(), `sonic-boom-${process.pid}-${process.hrtime().toString()}-${count++}`)
|
19 | files.push(file)
|
20 | return file
|
21 | }
|
22 |
|
23 | tearDown(() => {
|
24 | files.forEach((file) => {
|
25 | try {
|
26 | fs.unlinkSync(file)
|
27 | } catch (e) {
|
28 | console.log(e)
|
29 | }
|
30 | })
|
31 | })
|
32 |
|
33 | test('defaults to info level', t => {
|
34 | t.plan(13)
|
35 | var fastify = null
|
36 | var stream = split(JSON.parse)
|
37 | try {
|
38 | fastify = Fastify({
|
39 | logger: {
|
40 | stream: stream
|
41 | }
|
42 | })
|
43 | } catch (e) {
|
44 | t.fail()
|
45 | }
|
46 |
|
47 | fastify.get('/', function (req, reply) {
|
48 | t.ok(req.log)
|
49 | reply.send({ hello: 'world' })
|
50 | })
|
51 |
|
52 | stream.once('data', listenAtLogLine => {
|
53 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
54 |
|
55 | stream.once('data', line => {
|
56 | const id = line.reqId
|
57 | t.ok(line.reqId, 'reqId is defined')
|
58 | t.ok(line.req, 'req is defined')
|
59 | t.equal(line.msg, 'incoming request', 'message is set')
|
60 | t.equal(line.req.method, 'GET', 'method is get')
|
61 |
|
62 | stream.once('data', line => {
|
63 | t.equal(line.reqId, id)
|
64 | t.ok(line.reqId, 'reqId is defined')
|
65 | t.ok(line.res, 'res is defined')
|
66 | t.equal(line.msg, 'request completed', 'message is set')
|
67 | t.equal(line.res.statusCode, 200, 'statusCode is 200')
|
68 | t.ok(line.responseTime, 'responseTime is defined')
|
69 | })
|
70 | })
|
71 | })
|
72 |
|
73 | fastify.listen(0, err => {
|
74 | t.error(err)
|
75 | fastify.server.unref()
|
76 |
|
77 | http.get('http://localhost:' + fastify.server.address().port)
|
78 | })
|
79 | })
|
80 |
|
81 | test('test log stream', t => {
|
82 | t.plan(12)
|
83 | var fastify = null
|
84 | var stream = split(JSON.parse)
|
85 | try {
|
86 | fastify = Fastify({
|
87 | logger: {
|
88 | stream: stream,
|
89 | level: 'info'
|
90 | }
|
91 | })
|
92 | } catch (e) {
|
93 | t.fail()
|
94 | }
|
95 |
|
96 | fastify.get('/', function (req, reply) {
|
97 | t.ok(req.log)
|
98 | reply.send({ hello: 'world' })
|
99 | })
|
100 |
|
101 | fastify.listen(0, err => {
|
102 | t.error(err)
|
103 | fastify.server.unref()
|
104 |
|
105 | http.get('http://localhost:' + fastify.server.address().port)
|
106 | stream.once('data', listenAtLogLine => {
|
107 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
108 |
|
109 | stream.once('data', line => {
|
110 | const id = line.reqId
|
111 | t.ok(line.reqId, 'reqId is defined')
|
112 | t.ok(line.req, 'req is defined')
|
113 | t.equal(line.msg, 'incoming request', 'message is set')
|
114 | t.equal(line.req.method, 'GET', 'method is get')
|
115 |
|
116 | stream.once('data', line => {
|
117 | t.equal(line.reqId, id)
|
118 | t.ok(line.reqId, 'reqId is defined')
|
119 | t.ok(line.res, 'res is defined')
|
120 | t.equal(line.msg, 'request completed', 'message is set')
|
121 | t.equal(line.res.statusCode, 200, 'statusCode is 200')
|
122 | })
|
123 | })
|
124 | })
|
125 | })
|
126 | })
|
127 |
|
128 | test('test error log stream', t => {
|
129 | t.plan(11)
|
130 | var fastify = null
|
131 | var stream = split(JSON.parse)
|
132 | try {
|
133 | fastify = Fastify({
|
134 | logger: {
|
135 | stream: stream,
|
136 | level: 'info'
|
137 | }
|
138 | })
|
139 | } catch (e) {
|
140 | t.fail()
|
141 | }
|
142 |
|
143 | fastify.get('/error', function (req, reply) {
|
144 | t.ok(req.log)
|
145 | reply.send(new Error('kaboom'))
|
146 | })
|
147 |
|
148 | fastify.listen(0, err => {
|
149 | t.error(err)
|
150 | fastify.server.unref()
|
151 |
|
152 | http.get('http://localhost:' + fastify.server.address().port + '/error')
|
153 | stream.once('data', listenAtLogLine => {
|
154 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
155 |
|
156 | stream.once('data', line => {
|
157 | t.ok(line.reqId, 'reqId is defined')
|
158 | t.ok(line.req, 'req is defined')
|
159 | t.equal(line.msg, 'incoming request', 'message is set')
|
160 | t.equal(line.req.method, 'GET', 'method is get')
|
161 |
|
162 | stream.once('data', line => {
|
163 | t.ok(line.reqId, 'reqId is defined')
|
164 | t.ok(line.res, 'res is defined')
|
165 | t.equal(line.msg, 'kaboom', 'message is set')
|
166 | t.equal(line.res.statusCode, 500, 'statusCode is 500')
|
167 | })
|
168 | })
|
169 | })
|
170 | })
|
171 | })
|
172 |
|
173 | test('can use external logger instance', t => {
|
174 | const lines = [/^Server listening at /, /^incoming request$/, /^log success$/, /^request completed$/]
|
175 | t.plan(lines.length + 2)
|
176 |
|
177 | const splitStream = split(JSON.parse)
|
178 | splitStream.on('data', (line) => {
|
179 | const regex = lines.shift()
|
180 | t.ok(regex.test(line.msg), '"' + line.msg + '" dont match "' + regex + '"')
|
181 | })
|
182 |
|
183 | const logger = require('pino')(splitStream)
|
184 |
|
185 | const localFastify = Fastify({ logger: logger })
|
186 |
|
187 | localFastify.get('/foo', function (req, reply) {
|
188 | t.ok(req.log)
|
189 | req.log.info('log success')
|
190 | reply.send({ hello: 'world' })
|
191 | })
|
192 |
|
193 | localFastify.listen(0, err => {
|
194 | t.error(err)
|
195 | http.get('http://localhost:' + localFastify.server.address().port + '/foo', (res) => {
|
196 | res.resume()
|
197 | res.on('end', () => {
|
198 | localFastify.server.close()
|
199 | })
|
200 | })
|
201 | })
|
202 | })
|
203 |
|
204 | test('can use external logger instance with custom serializer', t => {
|
205 | const lines = [['level', 30], ['req', { url: '/foo' }], ['level', 30], ['res', { statusCode: 200 }]]
|
206 | t.plan(lines.length + 2)
|
207 |
|
208 | const splitStream = split(JSON.parse)
|
209 | splitStream.on('data', (line) => {
|
210 | const check = lines.shift()
|
211 | const key = check[0]
|
212 | const value = check[1]
|
213 |
|
214 | t.deepEqual(line[key], value)
|
215 | })
|
216 |
|
217 | const logger = require('pino')({
|
218 | level: 'info',
|
219 | serializers: {
|
220 | req: function (req) {
|
221 | return {
|
222 | url: req.url
|
223 | }
|
224 | }
|
225 | }
|
226 | }, splitStream)
|
227 |
|
228 | const localFastify = Fastify({
|
229 | logger: logger
|
230 | })
|
231 |
|
232 | localFastify.get('/foo', function (req, reply) {
|
233 | t.ok(req.log)
|
234 | req.log.info('log success')
|
235 | reply.send({ hello: 'world' })
|
236 | })
|
237 |
|
238 | localFastify.listen(0, err => {
|
239 | t.error(err)
|
240 | http.get('http://localhost:' + localFastify.server.address().port + '/foo', (res) => {
|
241 | res.resume()
|
242 | res.on('end', () => {
|
243 | localFastify.server.close()
|
244 | })
|
245 | })
|
246 | })
|
247 | })
|
248 |
|
249 | test('expose the logger', t => {
|
250 | t.plan(2)
|
251 | var fastify = null
|
252 | var stream = split(JSON.parse)
|
253 | try {
|
254 | fastify = Fastify({
|
255 | logger: {
|
256 | stream: stream,
|
257 | level: 'info'
|
258 | }
|
259 | })
|
260 | } catch (e) {
|
261 | t.fail()
|
262 | }
|
263 |
|
264 | t.ok(fastify.log)
|
265 | t.is(typeof fastify.log, 'object')
|
266 | })
|
267 |
|
268 | test('The request id header key can be customized', t => {
|
269 | t.plan(9)
|
270 | const REQUEST_ID = '42'
|
271 |
|
272 | const stream = split(JSON.parse)
|
273 | const fastify = Fastify({
|
274 | logger: { stream: stream, level: 'info' },
|
275 | requestIdHeader: 'my-custom-request-id'
|
276 | })
|
277 | t.tearDown(() => fastify.close())
|
278 |
|
279 | fastify.get('/', (req, reply) => {
|
280 | t.equal(req.raw.id, REQUEST_ID)
|
281 | req.log.info('some log message')
|
282 | reply.send({ id: req.raw.id })
|
283 | })
|
284 |
|
285 | fastify.inject({
|
286 | method: 'GET',
|
287 | url: '/',
|
288 | headers: {
|
289 | 'my-custom-request-id': REQUEST_ID
|
290 | }
|
291 | }, (err, res) => {
|
292 | t.error(err)
|
293 | const payload = JSON.parse(res.payload)
|
294 | t.equal(payload.id, REQUEST_ID)
|
295 |
|
296 | stream.once('data', line => {
|
297 | t.equal(line.reqId, REQUEST_ID)
|
298 | t.equal(line.msg, 'incoming request', 'message is set')
|
299 |
|
300 | stream.once('data', line => {
|
301 | t.equal(line.reqId, REQUEST_ID)
|
302 | t.equal(line.msg, 'some log message', 'message is set')
|
303 |
|
304 | stream.once('data', line => {
|
305 | t.equal(line.reqId, REQUEST_ID)
|
306 | t.equal(line.msg, 'request completed', 'message is set')
|
307 | })
|
308 | })
|
309 | })
|
310 | })
|
311 | })
|
312 |
|
313 | test('The request id header key can be customized along with a custom id generator', t => {
|
314 | t.plan(12)
|
315 | const REQUEST_ID = '42'
|
316 |
|
317 | const stream = split(JSON.parse)
|
318 | const fastify = Fastify({
|
319 | logger: { stream: stream, level: 'info' },
|
320 | requestIdHeader: 'my-custom-request-id',
|
321 | genReqId () {
|
322 | return 'foo'
|
323 | }
|
324 | })
|
325 | t.tearDown(() => fastify.close())
|
326 |
|
327 | fastify.get('/one', (req, reply) => {
|
328 | t.equal(req.id, REQUEST_ID)
|
329 | req.log.info('some log message')
|
330 | reply.send({ id: req.id })
|
331 | })
|
332 |
|
333 | fastify.get('/two', (req, reply) => {
|
334 | t.equal(req.id, 'foo')
|
335 | req.log.info('some log message 2')
|
336 | reply.send({ id: req.id })
|
337 | })
|
338 |
|
339 | const matches = [
|
340 | { reqId: REQUEST_ID, msg: /incoming request/ },
|
341 | { reqId: REQUEST_ID, msg: /some log message/ },
|
342 | { reqId: REQUEST_ID, msg: /request completed/ },
|
343 | { reqId: 'foo', msg: /incoming request/ },
|
344 | { reqId: 'foo', msg: /some log message 2/ },
|
345 | { reqId: 'foo', msg: /request completed/ }
|
346 | ]
|
347 |
|
348 | let i = 0
|
349 | stream.on('data', line => {
|
350 | t.match(line, matches[i])
|
351 | i += 1
|
352 | })
|
353 |
|
354 | fastify.inject({
|
355 | method: 'GET',
|
356 | url: '/one',
|
357 | headers: {
|
358 | 'my-custom-request-id': REQUEST_ID
|
359 | }
|
360 | }, (err, res) => {
|
361 | t.error(err)
|
362 | const payload = JSON.parse(res.payload)
|
363 | t.equal(payload.id, REQUEST_ID)
|
364 | })
|
365 |
|
366 | fastify.inject({
|
367 | method: 'GET',
|
368 | url: '/two'
|
369 | }, (err, res) => {
|
370 | t.error(err)
|
371 | const payload = JSON.parse(res.payload)
|
372 | t.equal(payload.id, 'foo')
|
373 | })
|
374 | })
|
375 |
|
376 | test('The request id log label can be changed', t => {
|
377 | t.plan(6)
|
378 | const REQUEST_ID = '42'
|
379 |
|
380 | const stream = split(JSON.parse)
|
381 | const fastify = Fastify({
|
382 | logger: { stream: stream, level: 'info' },
|
383 | requestIdHeader: 'my-custom-request-id',
|
384 | requestIdLogLabel: 'traceId'
|
385 | })
|
386 | t.tearDown(() => fastify.close())
|
387 |
|
388 | fastify.get('/one', (req, reply) => {
|
389 | t.equal(req.id, REQUEST_ID)
|
390 | req.log.info('some log message')
|
391 | reply.send({ id: req.id })
|
392 | })
|
393 |
|
394 | const matches = [
|
395 | { traceId: REQUEST_ID, msg: /incoming request/ },
|
396 | { traceId: REQUEST_ID, msg: /some log message/ },
|
397 | { traceId: REQUEST_ID, msg: /request completed/ }
|
398 | ]
|
399 |
|
400 | let i = 0
|
401 | stream.on('data', line => {
|
402 | t.match(line, matches[i])
|
403 | i += 1
|
404 | })
|
405 |
|
406 | fastify.inject({
|
407 | method: 'GET',
|
408 | url: '/one',
|
409 | headers: {
|
410 | 'my-custom-request-id': REQUEST_ID
|
411 | }
|
412 | }, (err, res) => {
|
413 | t.error(err)
|
414 | const payload = JSON.parse(res.payload)
|
415 | t.equal(payload.id, REQUEST_ID)
|
416 | })
|
417 | })
|
418 |
|
419 | test('The logger should accept custom serializer', t => {
|
420 | t.plan(9)
|
421 |
|
422 | const stream = split(JSON.parse)
|
423 | const fastify = Fastify({
|
424 | logger: {
|
425 | stream: stream,
|
426 | level: 'info',
|
427 | serializers: {
|
428 | req: function (req) {
|
429 | return {
|
430 | url: req.url
|
431 | }
|
432 | }
|
433 | }
|
434 | }
|
435 | })
|
436 |
|
437 | fastify.get('/custom', function (req, reply) {
|
438 | t.ok(req.log)
|
439 | reply.send(new Error('kaboom'))
|
440 | })
|
441 |
|
442 | fastify.listen(0, err => {
|
443 | t.error(err)
|
444 | fastify.server.unref()
|
445 |
|
446 | http.get('http://localhost:' + fastify.server.address().port + '/custom')
|
447 | stream.once('data', listenAtLogLine => {
|
448 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
449 |
|
450 | stream.once('data', line => {
|
451 | t.ok(line.req, 'req is defined')
|
452 | t.equal(line.msg, 'incoming request', 'message is set')
|
453 | t.deepEqual(line.req, { url: '/custom' }, 'custom req serialiser is use')
|
454 |
|
455 | stream.once('data', line => {
|
456 | t.ok(line.res, 'res is defined')
|
457 | t.equal(line.msg, 'kaboom', 'message is set')
|
458 | t.deepEqual(line.res, { statusCode: 500 }, 'default res serialiser is use')
|
459 | })
|
460 | })
|
461 | })
|
462 | })
|
463 | })
|
464 |
|
465 | test('reply.send logs an error if called twice in a row', t => {
|
466 | const lines = ['incoming request', 'request completed', 'Reply already sent', 'Reply already sent']
|
467 | t.plan(lines.length + 2)
|
468 |
|
469 | const splitStream = split(JSON.parse)
|
470 | splitStream.on('data', (line) => {
|
471 | t.is(line.msg, lines.shift())
|
472 | })
|
473 |
|
474 | const logger = pino(splitStream)
|
475 |
|
476 | const fastify = Fastify({
|
477 | logger
|
478 | })
|
479 |
|
480 | fastify.get('/', (req, reply) => {
|
481 | reply.send({ hello: 'world' })
|
482 | reply.send({ hello: 'world2' })
|
483 | reply.send({ hello: 'world3' })
|
484 | })
|
485 |
|
486 | fastify.inject({
|
487 | method: 'GET',
|
488 | url: '/'
|
489 | }, (err, res) => {
|
490 | t.error(err)
|
491 | const payload = JSON.parse(res.payload)
|
492 | t.deepEqual(payload, { hello: 'world' })
|
493 | })
|
494 | })
|
495 |
|
496 | test('logger can be silented', t => {
|
497 | t.plan(17)
|
498 | const fastify = Fastify({
|
499 | logger: false
|
500 | })
|
501 | t.ok(fastify.log)
|
502 | t.is(typeof fastify.log, 'object')
|
503 | t.is(typeof fastify.log.fatal, 'function')
|
504 | t.is(typeof fastify.log.error, 'function')
|
505 | t.is(typeof fastify.log.warn, 'function')
|
506 | t.is(typeof fastify.log.info, 'function')
|
507 | t.is(typeof fastify.log.debug, 'function')
|
508 | t.is(typeof fastify.log.trace, 'function')
|
509 | t.is(typeof fastify.log.child, 'function')
|
510 |
|
511 | const childLog = fastify.log.child()
|
512 |
|
513 | t.is(typeof childLog, 'object')
|
514 | t.is(typeof childLog.fatal, 'function')
|
515 | t.is(typeof childLog.error, 'function')
|
516 | t.is(typeof childLog.warn, 'function')
|
517 | t.is(typeof childLog.info, 'function')
|
518 | t.is(typeof childLog.debug, 'function')
|
519 | t.is(typeof childLog.trace, 'function')
|
520 | t.is(typeof childLog.child, 'function')
|
521 | })
|
522 |
|
523 | test('Should set a custom logLevel for a plugin', t => {
|
524 | const lines = ['incoming request', 'Hello', 'request completed']
|
525 | t.plan(7)
|
526 |
|
527 | const splitStream = split(JSON.parse)
|
528 | splitStream.on('data', (line) => {
|
529 | t.is(line.msg, lines.shift())
|
530 | })
|
531 |
|
532 | const logger = pino({ level: 'error' }, splitStream)
|
533 |
|
534 | const fastify = Fastify({
|
535 | logger
|
536 | })
|
537 |
|
538 | fastify.get('/', (req, reply) => {
|
539 | req.log.info('Hello')
|
540 | reply.send({ hello: 'world' })
|
541 | })
|
542 |
|
543 | fastify.register(function (instance, opts, next) {
|
544 | instance.get('/plugin', (req, reply) => {
|
545 | req.log.info('Hello')
|
546 | reply.send({ hello: 'world' })
|
547 | })
|
548 | next()
|
549 | }, { logLevel: 'info' })
|
550 |
|
551 | fastify.inject({
|
552 | method: 'GET',
|
553 | url: '/'
|
554 | }, (err, res) => {
|
555 | t.error(err)
|
556 | const payload = JSON.parse(res.payload)
|
557 | t.deepEqual(payload, { hello: 'world' })
|
558 | })
|
559 |
|
560 | fastify.inject({
|
561 | method: 'GET',
|
562 | url: '/plugin'
|
563 | }, (err, res) => {
|
564 | t.error(err)
|
565 | const payload = JSON.parse(res.payload)
|
566 | t.deepEqual(payload, { hello: 'world' })
|
567 | })
|
568 | })
|
569 |
|
570 | test('Should set a custom logLevel for every plugin', t => {
|
571 | const lines = ['incoming request', 'request completed', 'info', 'debug']
|
572 | t.plan(18)
|
573 |
|
574 | const splitStream = split(JSON.parse)
|
575 | splitStream.on('data', (line) => {
|
576 | t.ok(line.level === 30 || line.level === 20)
|
577 | t.ok(lines.indexOf(line.msg) > -1)
|
578 | })
|
579 |
|
580 | const logger = pino({ level: 'error' }, splitStream)
|
581 |
|
582 | const fastify = Fastify({
|
583 | logger
|
584 | })
|
585 |
|
586 | fastify.get('/', (req, reply) => {
|
587 | req.log.warn('Hello')
|
588 | reply.send({ hello: 'world' })
|
589 | })
|
590 |
|
591 | fastify.register(function (instance, opts, next) {
|
592 | instance.get('/info', (req, reply) => {
|
593 | req.log.info('info')
|
594 | req.log.debug('hidden log')
|
595 | reply.send({ hello: 'world' })
|
596 | })
|
597 | next()
|
598 | }, { logLevel: 'info' })
|
599 |
|
600 | fastify.register(function (instance, opts, next) {
|
601 | instance.get('/debug', (req, reply) => {
|
602 | req.log.debug('debug')
|
603 | req.log.trace('hidden log')
|
604 | reply.send({ hello: 'world' })
|
605 | })
|
606 | next()
|
607 | }, { logLevel: 'debug' })
|
608 |
|
609 | fastify.inject({
|
610 | method: 'GET',
|
611 | url: '/'
|
612 | }, (err, res) => {
|
613 | t.error(err)
|
614 | const payload = JSON.parse(res.payload)
|
615 | t.deepEqual(payload, { hello: 'world' })
|
616 | })
|
617 |
|
618 | fastify.inject({
|
619 | method: 'GET',
|
620 | url: '/info'
|
621 | }, (err, res) => {
|
622 | t.error(err)
|
623 | const payload = JSON.parse(res.payload)
|
624 | t.deepEqual(payload, { hello: 'world' })
|
625 | })
|
626 |
|
627 | fastify.inject({
|
628 | method: 'GET',
|
629 | url: '/debug'
|
630 | }, (err, res) => {
|
631 | t.error(err)
|
632 | const payload = JSON.parse(res.payload)
|
633 | t.deepEqual(payload, { hello: 'world' })
|
634 | })
|
635 | })
|
636 |
|
637 | test('Should increase the log level for a specific plugin', t => {
|
638 | t.plan(4)
|
639 |
|
640 | const splitStream = split(JSON.parse)
|
641 | splitStream.on('data', (line) => {
|
642 | t.is(line.msg, 'Hello')
|
643 | t.ok(line.level === 50)
|
644 | })
|
645 |
|
646 | const logger = pino({ level: 'info' }, splitStream)
|
647 |
|
648 | const fastify = Fastify({
|
649 | logger
|
650 | })
|
651 |
|
652 | fastify.register(function (instance, opts, next) {
|
653 | instance.get('/', (req, reply) => {
|
654 | req.log.error('Hello')
|
655 | reply.send({ hello: 'world' })
|
656 | })
|
657 | next()
|
658 | }, { logLevel: 'error' })
|
659 |
|
660 | fastify.inject({
|
661 | method: 'GET',
|
662 | url: '/'
|
663 | }, (err, res) => {
|
664 | t.error(err)
|
665 | const payload = JSON.parse(res.payload)
|
666 | t.deepEqual(payload, { hello: 'world' })
|
667 | })
|
668 | })
|
669 |
|
670 | test('Should set the log level for the customized 404 handler', t => {
|
671 | t.plan(4)
|
672 |
|
673 | const splitStream = split(JSON.parse)
|
674 | splitStream.on('data', (line) => {
|
675 | t.is(line.msg, 'Hello')
|
676 | t.ok(line.level === 50)
|
677 | })
|
678 |
|
679 | const logger = pino({ level: 'warn' }, splitStream)
|
680 |
|
681 | const fastify = Fastify({
|
682 | logger
|
683 | })
|
684 |
|
685 | fastify.register(function (instance, opts, next) {
|
686 | instance.setNotFoundHandler(function (req, reply) {
|
687 | req.log.error('Hello')
|
688 | reply.code(404).send()
|
689 | })
|
690 | next()
|
691 | }, { logLevel: 'error' })
|
692 |
|
693 | fastify.inject({
|
694 | method: 'GET',
|
695 | url: '/'
|
696 | }, (err, res) => {
|
697 | t.error(err)
|
698 | t.strictEqual(res.statusCode, 404)
|
699 | })
|
700 | })
|
701 |
|
702 | test('Should set the log level for the customized 500 handler', t => {
|
703 | t.plan(4)
|
704 |
|
705 | const splitStream = split(JSON.parse)
|
706 | splitStream.on('data', (line) => {
|
707 | t.is(line.msg, 'Hello')
|
708 | t.ok(line.level === 60)
|
709 | })
|
710 |
|
711 | const logger = pino({ level: 'warn' }, splitStream)
|
712 |
|
713 | const fastify = Fastify({
|
714 | logger
|
715 | })
|
716 |
|
717 | fastify.register(function (instance, opts, next) {
|
718 | instance.get('/', (req, reply) => {
|
719 | req.log.error('kaboom')
|
720 | reply.send(new Error('kaboom'))
|
721 | })
|
722 |
|
723 | instance.setErrorHandler(function (e, request, reply) {
|
724 | reply.log.fatal('Hello')
|
725 | reply.code(500).send()
|
726 | })
|
727 | next()
|
728 | }, { logLevel: 'fatal' })
|
729 |
|
730 | fastify.inject({
|
731 | method: 'GET',
|
732 | url: '/'
|
733 | }, (err, res) => {
|
734 | t.error(err)
|
735 | t.strictEqual(res.statusCode, 500)
|
736 | })
|
737 | })
|
738 |
|
739 | test('Should set a custom log level for a specific route', t => {
|
740 | const lines = ['incoming request', 'Hello', 'request completed']
|
741 | t.plan(7)
|
742 |
|
743 | const splitStream = split(JSON.parse)
|
744 | splitStream.on('data', (line) => {
|
745 | t.is(line.msg, lines.shift())
|
746 | })
|
747 |
|
748 | const logger = pino({ level: 'error' }, splitStream)
|
749 |
|
750 | const fastify = Fastify({
|
751 | logger
|
752 | })
|
753 |
|
754 | fastify.get('/log', { logLevel: 'info' }, (req, reply) => {
|
755 | req.log.info('Hello')
|
756 | reply.send({ hello: 'world' })
|
757 | })
|
758 |
|
759 | fastify.get('/no-log', (req, reply) => {
|
760 | req.log.info('Hello')
|
761 | reply.send({ hello: 'world' })
|
762 | })
|
763 |
|
764 | fastify.inject({
|
765 | method: 'GET',
|
766 | url: '/log'
|
767 | }, (err, res) => {
|
768 | t.error(err)
|
769 | const payload = JSON.parse(res.payload)
|
770 | t.deepEqual(payload, { hello: 'world' })
|
771 | })
|
772 |
|
773 | fastify.inject({
|
774 | method: 'GET',
|
775 | url: '/no-log'
|
776 | }, (err, res) => {
|
777 | t.error(err)
|
778 | const payload = JSON.parse(res.payload)
|
779 | t.deepEqual(payload, { hello: 'world' })
|
780 | })
|
781 | })
|
782 |
|
783 | test('The default 404 handler logs the incoming request', t => {
|
784 | t.plan(5)
|
785 |
|
786 | const expectedMessages = [
|
787 | 'incoming request',
|
788 | 'Route GET:/not-found not found',
|
789 | 'request completed'
|
790 | ]
|
791 |
|
792 | const splitStream = split(JSON.parse)
|
793 | splitStream.on('data', (line) => {
|
794 | t.is(line.msg, expectedMessages.shift())
|
795 | })
|
796 |
|
797 | const logger = pino({ level: 'trace' }, splitStream)
|
798 |
|
799 | const fastify = Fastify({
|
800 | logger
|
801 | })
|
802 |
|
803 | fastify.inject({
|
804 | method: 'GET',
|
805 | url: '/not-found'
|
806 | }, (err, res) => {
|
807 | t.error(err)
|
808 | t.strictEqual(res.statusCode, 404)
|
809 | })
|
810 | })
|
811 |
|
812 | test('should serialize request and response', t => {
|
813 | t.plan(3)
|
814 | const lines = []
|
815 | const dest = new stream.Writable({
|
816 | write: function (chunk, enc, cb) {
|
817 | lines.push(JSON.parse(chunk))
|
818 | cb()
|
819 | }
|
820 | })
|
821 | const fastify = Fastify({ logger: { level: 'info', stream: dest } })
|
822 |
|
823 | fastify.get('/500', (req, reply) => {
|
824 | reply.code(500).send(Error('500 error'))
|
825 | })
|
826 |
|
827 | fastify.inject({
|
828 | url: '/500',
|
829 | method: 'GET'
|
830 | }, (e, res) => {
|
831 | const l = lines.find((line) => line.res && line.res.statusCode === 500)
|
832 | t.ok(l.req)
|
833 | t.is(l.req.method, 'GET')
|
834 | t.is(l.req.url, '/500')
|
835 | })
|
836 | })
|
837 |
|
838 | {
|
839 | const interfaces = os.networkInterfaces()
|
840 | const ipv6 = Object.keys(interfaces)
|
841 | .filter(name => name.substr(0, 2) === 'lo')
|
842 | .map(name => interfaces[name])
|
843 | .reduce((list, set) => list.concat(set), [])
|
844 | .filter(info => info.family === 'IPv6')
|
845 | .map(info => info.address)
|
846 | .shift()
|
847 |
|
848 | if (ipv6 !== undefined) {
|
849 | test('Wrap IPv6 address in listening log message', t => {
|
850 | t.plan(2)
|
851 | const stream = split(JSON.parse)
|
852 | const fastify = Fastify({
|
853 | logger: {
|
854 | stream: stream,
|
855 | level: 'info'
|
856 | }
|
857 | })
|
858 | fastify.listen(0, ipv6, err => {
|
859 | t.error(err)
|
860 | stream.once('data', line => {
|
861 | const expected = 'Server listening at http://[' + ipv6 + ']:' +
|
862 | fastify.server.address().port
|
863 | t.is(line.msg, expected)
|
864 | fastify.close()
|
865 | })
|
866 | })
|
867 | })
|
868 | }
|
869 | }
|
870 |
|
871 | test('Do not wrap IPv4 address', t => {
|
872 | t.plan(2)
|
873 | const stream = split(JSON.parse)
|
874 | const fastify = Fastify({
|
875 | logger: {
|
876 | stream: stream,
|
877 | level: 'info'
|
878 | }
|
879 | })
|
880 | fastify.listen(0, '127.0.0.1', err => {
|
881 | t.error(err)
|
882 | stream.once('data', line => {
|
883 | const expected = 'Server listening at http://127.0.0.1:' +
|
884 | fastify.server.address().port
|
885 | t.is(line.msg, expected)
|
886 | fastify.close()
|
887 | })
|
888 | })
|
889 | })
|
890 |
|
891 | test('file option', t => {
|
892 | t.plan(13)
|
893 | var fastify = null
|
894 | var dest = file()
|
895 |
|
896 | fastify = Fastify({
|
897 | logger: {
|
898 | file: dest
|
899 | }
|
900 | })
|
901 |
|
902 | fastify.get('/', function (req, reply) {
|
903 | t.ok(req.log)
|
904 | reply.send({ hello: 'world' })
|
905 | })
|
906 |
|
907 | fastify.listen(0, err => {
|
908 | t.error(err)
|
909 | fastify.server.unref()
|
910 |
|
911 | http.get('http://localhost:' + fastify.server.address().port, () => {
|
912 | const stream = fs.createReadStream(dest).pipe(split(JSON.parse))
|
913 |
|
914 | stream.once('data', listenAtLogLine => {
|
915 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
916 |
|
917 | stream.once('data', line => {
|
918 | const id = line.reqId
|
919 | t.ok(line.reqId, 'reqId is defined')
|
920 | t.ok(line.req, 'req is defined')
|
921 | t.equal(line.msg, 'incoming request', 'message is set')
|
922 | t.equal(line.req.method, 'GET', 'method is get')
|
923 |
|
924 | stream.once('data', line => {
|
925 | t.equal(line.reqId, id)
|
926 | t.ok(line.reqId, 'reqId is defined')
|
927 | t.ok(line.res, 'res is defined')
|
928 | t.equal(line.msg, 'request completed', 'message is set')
|
929 | t.equal(line.res.statusCode, 200, 'statusCode is 200')
|
930 | t.ok(line.responseTime, 'responseTime is defined')
|
931 | stream.resume()
|
932 | })
|
933 | })
|
934 | })
|
935 | })
|
936 | })
|
937 | })
|
938 |
|
939 | test('should log the error if no error handler is defined', t => {
|
940 | t.plan(8)
|
941 | const stream = split(JSON.parse)
|
942 | const fastify = Fastify({
|
943 | logger: {
|
944 | stream: stream,
|
945 | level: 'info'
|
946 | }
|
947 | })
|
948 | fastify.get('/error', function (req, reply) {
|
949 | t.ok(req.log)
|
950 | reply.send(new Error('a generic error'))
|
951 | })
|
952 | fastify.listen(0, err => {
|
953 | t.error(err)
|
954 | fastify.server.unref()
|
955 | http.get('http://localhost:' + fastify.server.address().port + '/error')
|
956 | stream.once('data', listenAtLogLine => {
|
957 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
958 | stream.once('data', line => {
|
959 | t.equal(line.msg, 'incoming request', 'message is set')
|
960 | stream.once('data', line => {
|
961 | t.equal(line.level, 50, 'level is correct')
|
962 | t.equal(line.msg, 'a generic error', 'message is set')
|
963 | stream.once('data', line => {
|
964 | t.equal(line.msg, 'request completed', 'message is set')
|
965 | t.deepEqual(line.res, { statusCode: 500 }, 'status code is set')
|
966 | })
|
967 | })
|
968 | })
|
969 | })
|
970 | })
|
971 | })
|
972 |
|
973 | test('should log as info if error status code >= 400 and < 500 if no error handler is defined', t => {
|
974 | t.plan(8)
|
975 | const stream = split(JSON.parse)
|
976 | const fastify = Fastify({
|
977 | logger: {
|
978 | stream: stream,
|
979 | level: 'info'
|
980 | }
|
981 | })
|
982 | fastify.get('/400', function (req, reply) {
|
983 | t.ok(req.log)
|
984 | reply.send(Object.assign(new Error('a 400 error'), { statusCode: 400 }))
|
985 | })
|
986 | fastify.get('/503', function (req, reply) {
|
987 | t.ok(req.log)
|
988 | reply.send(Object.assign(new Error('a 503 error'), { statusCode: 503 }))
|
989 | })
|
990 | fastify.listen(0, err => {
|
991 | t.error(err)
|
992 | fastify.server.unref()
|
993 | http.get('http://localhost:' + fastify.server.address().port + '/400')
|
994 | stream.once('data', listenAtLogLine => {
|
995 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
996 | stream.once('data', line => {
|
997 | t.equal(line.msg, 'incoming request', 'message is set')
|
998 | stream.once('data', line => {
|
999 | t.equal(line.level, 30, 'level is correct')
|
1000 | t.equal(line.msg, 'a 400 error', 'message is set')
|
1001 | stream.once('data', line => {
|
1002 | t.equal(line.msg, 'request completed', 'message is set')
|
1003 | t.deepEqual(line.res, { statusCode: 400 }, 'status code is set')
|
1004 | })
|
1005 | })
|
1006 | })
|
1007 | })
|
1008 | })
|
1009 | })
|
1010 |
|
1011 | test('should log as error if error status code >= 500 if no error handler is defined', t => {
|
1012 | t.plan(8)
|
1013 | const stream = split(JSON.parse)
|
1014 | const fastify = Fastify({
|
1015 | logger: {
|
1016 | stream: stream,
|
1017 | level: 'info'
|
1018 | }
|
1019 | })
|
1020 | fastify.get('/503', function (req, reply) {
|
1021 | t.ok(req.log)
|
1022 | reply.send(Object.assign(new Error('a 503 error'), { statusCode: 503 }))
|
1023 | })
|
1024 | fastify.listen(0, err => {
|
1025 | t.error(err)
|
1026 | fastify.server.unref()
|
1027 | http.get('http://localhost:' + fastify.server.address().port + '/503')
|
1028 | stream.once('data', listenAtLogLine => {
|
1029 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
1030 | stream.once('data', line => {
|
1031 | t.equal(line.msg, 'incoming request', 'message is set')
|
1032 | stream.once('data', line => {
|
1033 | t.equal(line.level, 50, 'level is correct')
|
1034 | t.equal(line.msg, 'a 503 error', 'message is set')
|
1035 | stream.once('data', line => {
|
1036 | t.equal(line.msg, 'request completed', 'message is set')
|
1037 | t.deepEqual(line.res, { statusCode: 503 }, 'status code is set')
|
1038 | })
|
1039 | })
|
1040 | })
|
1041 | })
|
1042 | })
|
1043 | })
|
1044 |
|
1045 | test('should not log the error if error handler is defined', t => {
|
1046 | t.plan(7)
|
1047 | const stream = split(JSON.parse)
|
1048 | const fastify = Fastify({
|
1049 | logger: {
|
1050 | stream: stream,
|
1051 | level: 'info'
|
1052 | }
|
1053 | })
|
1054 | fastify.get('/error', function (req, reply) {
|
1055 | t.ok(req.log)
|
1056 | reply.send(new Error('something happened'))
|
1057 | })
|
1058 | fastify.setErrorHandler((err, req, reply) => {
|
1059 | reply.send(err)
|
1060 | })
|
1061 | fastify.listen(0, err => {
|
1062 | t.error(err)
|
1063 | fastify.server.unref()
|
1064 | http.get('http://localhost:' + fastify.server.address().port + '/error')
|
1065 | stream.once('data', listenAtLogLine => {
|
1066 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
1067 | stream.once('data', line => {
|
1068 | t.equal(line.msg, 'incoming request', 'message is set')
|
1069 | stream.once('data', line => {
|
1070 | t.equal(line.level, 30, 'level is correct')
|
1071 | t.equal(line.msg, 'request completed', 'message is set')
|
1072 | t.deepEqual(line.res, { statusCode: 500 }, 'status code is set')
|
1073 | })
|
1074 | })
|
1075 | })
|
1076 | })
|
1077 | })
|
1078 |
|
1079 | test('should not rely on raw request to log errors', t => {
|
1080 | t.plan(7)
|
1081 | const stream = split(JSON.parse)
|
1082 | const fastify = Fastify({
|
1083 | modifyCoreObjects: false,
|
1084 | logger: {
|
1085 | stream: stream,
|
1086 | level: 'info'
|
1087 | }
|
1088 | })
|
1089 | fastify.get('/error', function (req, reply) {
|
1090 | t.ok(req.log)
|
1091 | reply.status(415).send(new Error('something happened'))
|
1092 | })
|
1093 | fastify.listen(0, err => {
|
1094 | t.error(err)
|
1095 | fastify.server.unref()
|
1096 | http.get('http://localhost:' + fastify.server.address().port + '/error')
|
1097 | stream.once('data', listenAtLogLine => {
|
1098 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
1099 | stream.once('data', line => {
|
1100 | t.equal(line.msg, 'incoming request', 'message is set')
|
1101 | stream.once('data', line => {
|
1102 | t.equal(line.level, 30, 'level is correct')
|
1103 | t.equal(line.msg, 'something happened', 'message is set')
|
1104 | t.deepEqual(line.res, { statusCode: 415 }, 'status code is set')
|
1105 | })
|
1106 | })
|
1107 | })
|
1108 | })
|
1109 | })
|
1110 |
|
1111 | test('should redact the authorization header if so specified', t => {
|
1112 | t.plan(7)
|
1113 | const stream = split(JSON.parse)
|
1114 | const fastify = Fastify({
|
1115 | logger: {
|
1116 | stream: stream,
|
1117 | redact: ['req.headers.authorization'],
|
1118 | level: 'info',
|
1119 | serializers: {
|
1120 | req (req) {
|
1121 | return {
|
1122 | method: req.method,
|
1123 | url: req.url,
|
1124 | headers: req.headers,
|
1125 | hostname: req.hostname,
|
1126 | remoteAddress: req.ip,
|
1127 | remotePort: req.connection.remotePort
|
1128 | }
|
1129 | }
|
1130 | }
|
1131 | }
|
1132 | })
|
1133 | fastify.get('/', function (req, reply) {
|
1134 | t.is(req.headers.authorization, 'Bearer abcde')
|
1135 | reply.send({ hello: 'world' })
|
1136 | })
|
1137 | stream.once('data', listenAtLogLine => {
|
1138 | t.ok(listenAtLogLine, 'listen at log message is ok')
|
1139 | stream.once('data', line => {
|
1140 | t.equal(line.req.headers.authorization, '[Redacted]', 'authorization is redacted')
|
1141 | })
|
1142 | })
|
1143 | fastify.listen(0, err => {
|
1144 | t.error(err)
|
1145 | fastify.server.unref()
|
1146 | sget({
|
1147 | method: 'GET',
|
1148 | url: 'http://localhost:' + fastify.server.address().port,
|
1149 | headers: {
|
1150 | authorization: 'Bearer abcde'
|
1151 | }
|
1152 | }, (err, response, body) => {
|
1153 | t.error(err)
|
1154 | t.strictEqual(response.statusCode, 200)
|
1155 | t.deepEqual(body.toString(), JSON.stringify({ hello: 'world' }))
|
1156 | })
|
1157 | })
|
1158 | })
|
1159 |
|
1160 | test('should not log incoming request and outgoing response when disabled', t => {
|
1161 | t.plan(3)
|
1162 | const lines = []
|
1163 | const dest = new stream.Writable({
|
1164 | write: function (chunk, enc, cb) {
|
1165 | lines.push(JSON.parse(chunk))
|
1166 | cb()
|
1167 | }
|
1168 | })
|
1169 | const fastify = Fastify({ disableRequestLogging: true, logger: { level: 'info', stream: dest } })
|
1170 |
|
1171 | fastify.get('/500', (req, reply) => {
|
1172 | reply.code(500).send(Error('500 error'))
|
1173 | })
|
1174 |
|
1175 | fastify.inject({
|
1176 | url: '/500',
|
1177 | method: 'GET'
|
1178 | }, (e, res) => {
|
1179 | t.is(lines.length, 1)
|
1180 | t.ok(lines[0].msg)
|
1181 | t.is(lines[0].msg, '500 error')
|
1182 | })
|
1183 | })
|