git clone https://github.com/pinojs/pinojs
cd pinojs
npm install
npm start
pinojs / express-pino-logger Goto Github PK
View Code? Open in Web Editor NEW🌲 an express middleware to log with pino
License: MIT License
express-pino-logger's Introduction
express-pino-logger's People
Contributors
![dependabot[bot] avatar](https://avatars.githubusercontent.com/in/29110?v=4 "dependabot[bot]")
Stargazers
Watchers
Forkers
pragmaticivan laurentgoudet bpofficial kaveet moose0621 linusu admataz njibhu molomby svikashk chengadev jmealo lpdrummerboy87 mziwiskyexpress-pino-logger's Issues
Exclude specific URLs from pino logs
My server uses /healthz endpoints which I need to tell pino to ignore, not sure how.
This feature has already been requested in hapijs/hapi-pino#26 and pinojs/koa-pino-logger#23
Perhaps something like ignorePaths should just be added to the main pino package since this is a general issue and not specific to a particular server library.
Excessively verbose `req` serializer?
Consider this example app:
'use strict'
const app = require('express')()
const pino = require('pino')
const noir = require('pino-noir')(['req.headers.host'])
const serializers = {
err: pino.stdSerializers.err
}
const logger = require('express-pino-logger')({
level: 'debug',
serializers: Object.assign({}, serializers, noir)
})
app.use(logger)
app.get('/', (req, reply) => {
req.log.error(Error('this is a test'))
reply.send('hello world')
})
app.listen(3000)Issuing a simple GET to the endpoint results in a tremendous amount of logged data for the req object:
expand for output log
[2017-11-21T14:21:02.499Z] ERROR (1370 on dalekprime.local): this is a test
Error: this is a test
at app.get (/private/tmp/21/foo/index.js:17:17)
at Layer.handle [as handle_request] (/private/tmp/21/foo/node_modules/express/lib/router/layer.js:95:5)
at next (/private/tmp/21/foo/node_modules/express/lib/router/route.js:137:13)
at Route.dispatch (/private/tmp/21/foo/node_modules/express/lib/router/route.js:112:3)
at Layer.handle [as handle_request] (/private/tmp/21/foo/node_modules/express/lib/router/layer.js:95:5)
at /private/tmp/21/foo/node_modules/express/lib/router/index.js:281:22
at Function.process_params (/private/tmp/21/foo/node_modules/express/lib/router/index.js:335:12)
at next (/private/tmp/21/foo/node_modules/express/lib/router/index.js:275:10)
at loggingMiddleware (/private/tmp/21/foo/node_modules/pino-http/logger.js:62:7)
at Layer.handle [as handle_request] (/private/tmp/21/foo/node_modules/express/lib/router/layer.js:95:5)
[2017-11-21T14:21:02.506Z] INFO (1370 on dalekprime.local): request completed
req: {
"_readableState": {
"objectMode": false,
"highWaterMark": 16384,
"buffer": {
"head": null,
"tail": null,
"length": 0
},
"length": 0,
"pipes": null,
"pipesCount": 0,
"flowing": null,
"ended": false,
"endEmitted": false,
"reading": false,
"sync": true,
"needReadable": false,
"emittedReadable": false,
"readableListening": false,
"resumeScheduled": false,
"destroyed": false,
"defaultEncoding": "utf8",
"awaitDrain": 0,
"readingMore": true,
"decoder": null,
"encoding": null
},
"readable": true,
"domain": null,
"_events": {},
"_eventsCount": 0,
"socket": {
"connecting": false,
"_hadError": false,
"_handle": {
"reading": true,
"owner": "[Circular]",
"onconnection": null,
"writeQueueSize": 0,
"_consumed": true
},
"_parent": null,
"_host": null,
"_readableState": {
"objectMode": false,
"highWaterMark": 16384,
"buffer": {
"head": null,
"tail": null,
"length": 0
},
"length": 0,
"pipes": null,
"pipesCount": 0,
"flowing": true,
"ended": false,
"endEmitted": false,
"reading": true,
"sync": false,
"needReadable": true,
"emittedReadable": false,
"readableListening": false,
"resumeScheduled": false,
"destroyed": false,
"defaultEncoding": "utf8",
"awaitDrain": 0,
"readingMore": false,
"decoder": null,
"encoding": null
},
"readable": true,
"domain": null,
"_events": {
"end": [
null,
null
],
"drain": [
null,
null
],
"close": [
null,
null
]
},
"_eventsCount": 10,
"_writableState": {
"objectMode": false,
"highWaterMark": 16384,
"finalCalled": false,
"needDrain": false,
"ending": false,
"ended": false,
"finished": false,
"destroyed": false,
"decodeStrings": false,
"defaultEncoding": "utf8",
"length": 0,
"writing": false,
"corked": 0,
"sync": true,
"bufferProcessing": false,
"writecb": null,
"writelen": 0,
"bufferedRequest": null,
"lastBufferedRequest": null,
"pendingcb": 0,
"prefinished": false,
"errorEmitted": false,
"bufferedRequestCount": 0,
"corkedRequestsFree": {
"next": null,
"entry": null
}
},
"writable": true,
"allowHalfOpen": true,
"_bytesDispatched": 0,
"_sockname": null,
"_pendingData": null,
"_pendingEncoding": "",
"server": {
"domain": null,
"_events": {},
"_eventsCount": 2,
"_connections": 1,
"_handle": {
"reading": false,
"owner": "[Circular]",
"onread": null,
"writeQueueSize": 0
},
"_usingSlaves": false,
"_slaves": [],
"_unref": false,
"allowHalfOpen": true,
"pauseOnConnect": false,
"httpAllowHalfOpen": false,
"timeout": 120000,
"keepAliveTimeout": 5000,
"_pendingResponseData": 0,
"maxHeadersCount": null,
"_connectionKey": "6::::3000"
},
"_server": {
"domain": null,
"_events": {},
"_eventsCount": 2,
"_connections": 1,
"_handle": {
"reading": false,
"owner": "[Circular]",
"onread": null,
"writeQueueSize": 0
},
"_usingSlaves": false,
"_slaves": [],
"_unref": false,
"allowHalfOpen": true,
"pauseOnConnect": false,
"httpAllowHalfOpen": false,
"timeout": 120000,
"keepAliveTimeout": 5000,
"_pendingResponseData": 0,
"maxHeadersCount": null,
"_connectionKey": "6::::3000"
},
"_idleTimeout": 120000,
"_idleNext": {
"_idleNext": "[Circular]",
"_idlePrev": "[Circular]",
"_timer": {
"_list": "[Circular]"
},
"_unrefed": true,
"msecs": 120000,
"nextTick": false
},
"_idlePrev": {
"_idleNext": "[Circular]",
"_idlePrev": "[Circular]",
"_timer": {
"_list": "[Circular]"
},
"_unrefed": true,
"msecs": 120000,
"nextTick": false
},
"_idleStart": 7229,
"_destroyed": false,
"parser": {
"_headers": [],
"_url": "",
"_consumed": true,
"socket": "[Circular]",
"incoming": "[Circular]",
"outgoing": null,
"maxHeaderPairs": 2000
},
"_paused": false,
"_consuming": true,
"_httpMessage": {
"domain": null,
"_events": {},
"_eventsCount": 1,
"output": [],
"outputEncodings": [],
"outputCallbacks": [],
"outputSize": 0,
"writable": true,
"_last": false,
"upgrading": false,
"chunkedEncoding": false,
"shouldKeepAlive": true,
"useChunkedEncodingByDefault": true,
"sendDate": true,
"_removedConnection": false,
"_removedContLen": false,
"_removedTE": false,
"_contentLength": null,
"_hasBody": true,
"_trailer": "",
"finished": false,
"_headerSent": false,
"socket": "[Circular]",
"connection": "[Circular]",
"_header": null,
"_sent100": false,
"_expect_continue": false,
"req": "[Circular]",
"locals": {}
}
},
"connection": {
"connecting": false,
"_hadError": false,
"_handle": {
"reading": true,
"owner": "[Circular]",
"onconnection": null,
"writeQueueSize": 0,
"_consumed": true
},
"_parent": null,
"_host": null,
"_readableState": {
"objectMode": false,
"highWaterMark": 16384,
"buffer": {
"head": null,
"tail": null,
"length": 0
},
"length": 0,
"pipes": null,
"pipesCount": 0,
"flowing": true,
"ended": false,
"endEmitted": false,
"reading": true,
"sync": false,
"needReadable": true,
"emittedReadable": false,
"readableListening": false,
"resumeScheduled": false,
"destroyed": false,
"defaultEncoding": "utf8",
"awaitDrain": 0,
"readingMore": false,
"decoder": null,
"encoding": null
},
"readable": true,
"domain": null,
"_events": {
"end": [
null,
null
],
"drain": [
null,
null
],
"close": [
null,
null
]
},
"_eventsCount": 10,
"_writableState": {
"objectMode": false,
"highWaterMark": 16384,
"finalCalled": false,
"needDrain": false,
"ending": false,
"ended": false,
"finished": false,
"destroyed": false,
"decodeStrings": false,
"defaultEncoding": "utf8",
"length": 0,
"writing": false,
"corked": 0,
"sync": true,
"bufferProcessing": false,
"writecb": null,
"writelen": 0,
"bufferedRequest": null,
"lastBufferedRequest": null,
"pendingcb": 0,
"prefinished": false,
"errorEmitted": false,
"bufferedRequestCount": 0,
"corkedRequestsFree": {
"next": null,
"entry": null
}
},
"writable": true,
"allowHalfOpen": true,
"_bytesDispatched": 0,
"_sockname": null,
"_pendingData": null,
"_pendingEncoding": "",
"server": {
"domain": null,
"_events": {},
"_eventsCount": 2,
"_connections": 1,
"_handle": {
"reading": false,
"owner": "[Circular]",
"onread": null,
"writeQueueSize": 0
},
"_usingSlaves": false,
"_slaves": [],
"_unref": false,
"allowHalfOpen": true,
"pauseOnConnect": false,
"httpAllowHalfOpen": false,
"timeout": 120000,
"keepAliveTimeout": 5000,
"_pendingResponseData": 0,
"maxHeadersCount": null,
"_connectionKey": "6::::3000"
},
"_server": {
"domain": null,
"_events": {},
"_eventsCount": 2,
"_connections": 1,
"_handle": {
"reading": false,
"owner": "[Circular]",
"onread": null,
"writeQueueSize": 0
},
"_usingSlaves": false,
"_slaves": [],
"_unref": false,
"allowHalfOpen": true,
"pauseOnConnect": false,
"httpAllowHalfOpen": false,
"timeout": 120000,
"keepAliveTimeout": 5000,
"_pendingResponseData": 0,
"maxHeadersCount": null,
"_connectionKey": "6::::3000"
},
"_idleTimeout": 120000,
"_idleNext": {
"_idleNext": "[Circular]",
"_idlePrev": "[Circular]",
"_timer": {
"_list": "[Circular]"
},
"_unrefed": true,
"msecs": 120000,
"nextTick": false
},
"_idlePrev": {
"_idleNext": "[Circular]",
"_idlePrev": "[Circular]",
"_timer": {
"_list": "[Circular]"
},
"_unrefed": true,
"msecs": 120000,
"nextTick": false
},
"_idleStart": 7229,
"_destroyed": false,
"parser": {
"_headers": [],
"_url": "",
"_consumed": true,
"socket": "[Circular]",
"incoming": "[Circular]",
"outgoing": null,
"maxHeaderPairs": 2000
},
"_paused": false,
"_consuming": true,
"_httpMessage": {
"domain": null,
"_events": {},
"_eventsCount": 1,
"output": [],
"outputEncodings": [],
"outputCallbacks": [],
"outputSize": 0,
"writable": true,
"_last": false,
"upgrading": false,
"chunkedEncoding": false,
"shouldKeepAlive": true,
"useChunkedEncodingByDefault": true,
"sendDate": true,
"_removedConnection": false,
"_removedContLen": false,
"_removedTE": false,
"_contentLength": null,
"_hasBody": true,
"_trailer": "",
"finished": false,
"_headerSent": false,
"socket": "[Circular]",
"connection": "[Circular]",
"_header": null,
"_sent100": false,
"_expect_continue": false,
"req": "[Circular]",
"locals": {}
}
},
"httpVersionMajor": 1,
"httpVersionMinor": 1,
"httpVersion": "1.1",
"complete": false,
"headers": {
"host": "[Redacted]",
"user-agent": "curl/7.56.1",
"accept": "*/*"
},
"rawHeaders": [
"Host",
"localhost:3000",
"User-Agent",
"curl/7.56.1",
"Accept",
"*/*"
],
"trailers": {},
"rawTrailers": [],
"upgrade": false,
"url": "/",
"method": "GET",
"statusCode": null,
"statusMessage": null,
"client": {
"connecting": false,
"_hadError": false,
"_handle": {
"reading": true,
"owner": "[Circular]",
"onconnection": null,
"writeQueueSize": 0,
"_consumed": true
},
"_parent": null,
"_host": null,
"_readableState": {
"objectMode": false,
"highWaterMark": 16384,
"buffer": {
"head": null,
"tail": null,
"length": 0
},
"length": 0,
"pipes": null,
"pipesCount": 0,
"flowing": true,
"ended": false,
"endEmitted": false,
"reading": true,
"sync": false,
"needReadable": true,
"emittedReadable": false,
"readableListening": false,
"resumeScheduled": false,
"destroyed": false,
"defaultEncoding": "utf8",
"awaitDrain": 0,
"readingMore": false,
"decoder": null,
"encoding": null
},
"readable": true,
"domain": null,
"_events": {
"end": [
null,
null
],
"drain": [
null,
null
],
"close": [
null,
null
]
},
"_eventsCount": 10,
"_writableState": {
"objectMode": false,
"highWaterMark": 16384,
"finalCalled": false,
"needDrain": false,
"ending": false,
"ended": false,
"finished": false,
"destroyed": false,
"decodeStrings": false,
"defaultEncoding": "utf8",
"length": 0,
"writing": false,
"corked": 0,
"sync": true,
"bufferProcessing": false,
"writecb": null,
"writelen": 0,
"bufferedRequest": null,
"lastBufferedRequest": null,
"pendingcb": 0,
"prefinished": false,
"errorEmitted": false,
"bufferedRequestCount": 0,
"corkedRequestsFree": {
"next": null,
"entry": null
}
},
"writable": true,
"allowHalfOpen": true,
"_bytesDispatched": 0,
"_sockname": null,
"_pendingData": null,
"_pendingEncoding": "",
"server": {
"domain": null,
"_events": {},
"_eventsCount": 2,
"_connections": 1,
"_handle": {
"reading": false,
"owner": "[Circular]",
"onread": null,
"writeQueueSize": 0
},
"_usingSlaves": false,
"_slaves": [],
"_unref": false,
"allowHalfOpen": true,
"pauseOnConnect": false,
"httpAllowHalfOpen": false,
"timeout": 120000,
"keepAliveTimeout": 5000,
"_pendingResponseData": 0,
"maxHeadersCount": null,
"_connectionKey": "6::::3000"
},
"_server": {
"domain": null,
"_events": {},
"_eventsCount": 2,
"_connections": 1,
"_handle": {
"reading": false,
"owner": "[Circular]",
"onread": null,
"writeQueueSize": 0
},
"_usingSlaves": false,
"_slaves": [],
"_unref": false,
"allowHalfOpen": true,
"pauseOnConnect": false,
"httpAllowHalfOpen": false,
"timeout": 120000,
"keepAliveTimeout": 5000,
"_pendingResponseData": 0,
"maxHeadersCount": null,
"_connectionKey": "6::::3000"
},
"_idleTimeout": 120000,
"_idleNext": {
"_idleNext": "[Circular]",
"_idlePrev": "[Circular]",
"_timer": {
"_list": "[Circular]"
},
"_unrefed": true,
"msecs": 120000,
"nextTick": false
},
"_idlePrev": {
"_idleNext": "[Circular]",
"_idlePrev": "[Circular]",
"_timer": {
"_list": "[Circular]"
},
"_unrefed": true,
"msecs": 120000,
"nextTick": false
},
"_idleStart": 7229,
"_destroyed": false,
"parser": {
"_headers": [],
"_url": "",
"_consumed": true,
"socket": "[Circular]",
"incoming": "[Circular]",
"outgoing": null,
"maxHeaderPairs": 2000
},
"_paused": false,
"_consuming": true,
"_httpMessage": {
"domain": null,
"_events": {},
"_eventsCount": 1,
"output": [],
"outputEncodings": [],
"outputCallbacks": [],
"outputSize": 0,
"writable": true,
"_last": false,
"upgrading": false,
"chunkedEncoding": false,
"shouldKeepAlive": true,
"useChunkedEncodingByDefault": true,
"sendDate": true,
"_removedConnection": false,
"_removedContLen": false,
"_removedTE": false,
"_contentLength": null,
"_hasBody": true,
"_trailer": "",
"finished": false,
"_headerSent": false,
"socket": "[Circular]",
"connection": "[Circular]",
"_header": null,
"_sent100": false,
"_expect_continue": false,
"req": "[Circular]",
"locals": {}
}
},
"_consuming": false,
"_dumped": false,
"baseUrl": "",
"originalUrl": "/",
"_parsedUrl": {
"protocol": null,
"slashes": null,
"auth": null,
"host": null,
"port": null,
"hostname": null,
"hash": null,
"search": null,
"query": null,
"pathname": "/",
"path": "/",
"href": "/",
"_raw": "/"
},
"params": {},
"query": {},
"res": {
"domain": null,
"_events": {},
"_eventsCount": 1,
"output": [],
"outputEncodings": [],
"outputCallbacks": [],
"outputSize": 0,
"writable": true,
"_last": false,
"upgrading": false,
"chunkedEncoding": false,
"shouldKeepAlive": true,
"useChunkedEncodingByDefault": true,
"sendDate": true,
"_removedConnection": false,
"_removedContLen": false,
"_removedTE": false,
"_contentLength": null,
"_hasBody": true,
"_trailer": "",
"finished": false,
"_headerSent": false,
"socket": "[Circular]",
"connection": "[Circular]",
"_header": null,
"_sent100": false,
"_expect_continue": false,
"req": "[Circular]",
"locals": {}
},
"id": 1
}
res: {
"statusCode": 200,
"header": "HTTP/1.1 200 OK\r\nX-Powered-By: Express\r\nContent-Type: text/html; charset=utf-8\r\nContent-Length: 11\r\nETag: W/\"b-Kq5sNclPz7QV2+lfQIuc6R7oRu0\"\r\nDate: Tue, 21 Nov 2017 14:21:02 GMT\r\nConnection: keep-alive\r\n\r\n"
}
responseTime: 7
This does not seem right, particularly considering the example output in the documentation here. I'm not an express guy, is this normal? Also notice that this output makes redacting material doubly complicated (e.g. req.headers and req.rawHeaders).
Ignoring serializers from pino
For some reason it does not look like my default implementation of serializers is being applied when I plug it into the expressPino API.
In my app.js:
const { logger } = require("./utils/logger");
const expressPino = require("express-pino-logger")({ logger });
app.use(expressPino);In my logger file:
const baseConfig = {
name: "hello-world",
level: "info",
env: env.type || "staging"
};
const reqSerializer = req => ({
// .. a lot more but currently redacted
url: req.url,
method: req.method,
id: req.id,
});
const resSerializer = res => ({
statusCode: res.statusCode
});
const errSerializer = err => ({
type: err.type,
message: err.message,
stack: err.stack,
code: err.code
});
const logger = new pino({
...baseConfig,
serializers: {
request: reqSerializer,
response: resSerializer,
err: errSerializer
}
});
module.exports = { logger };Yet, I'm still getting a large log output. I did some sanity checks without the middleware by and using the logger directly in the following:
app.use((req, res, next) => {
if (req) logger.info(req);
if (res) logger.info(res);
next();
});The reason why I'm not using my own middleware is because there is a lot of useful data that I want to keep track of (i.e. responseTime as one example)
Update README removing replacing pino with pino-pretty. pino usage as cli was deprecated
Custom log levels break autoLogging
Hi!
When I add customLevels to Pino instance & when I use these levels with customLogLevel, it stops autoLogging if custom level value is not bigger than all default levels values ( > 60 ).
Identify what request caused an error
I'm probably missing something here.
Using req.log.info('some info') gives an output that contains the current request id. However, using req.log.error(Error('something bad')) only outputs the stack.
Is there a way to see what request caused the error?
broken link in README
The 'autocannon` link is broken in the README
Keys added to req/res not available to serializers
Keys added to req/res are not available to serializers when they should be.
Here's an example based on the example from the main page:
'use strict'
var app = require('express')()
var ExpressPinoLogger = require('express-pino-logger')
var pino = ExpressPinoLogger({
serializers: {
req: (req) => ({
method: req.method,
url: req.url,
user: req.user,
}),
},
})
app.use(pino)
app.use((req, res, next) => {
req.user = 'testing';
next();
})
app.get('/', function (req, res) {
// each request has its own id
// so you can track the log of each request
// by using `req.log`
// the ids are cycled every 2^31 - 2
req.log.info('something else')
res.send('hello world')
})
app.listen(3000)
How to avoid the entire request being logged every time using pino?
I am new to nodejs and decided to use the pino logger in my application. Here is the code snippet showing how I am using it:
const expressPino = require('express-pino-logger');
const { LOGLEVEL } = require('../config.js');
// Constructs a Pino Instance
const logger = pino({
level: LOGLEVEL || 'trace',
prettyPrint: { levelFirst: true, colorize: true, ignore: 'pid' },
});
// Construct an express middleware using the above pino instance
const expressLogger = expressPino({ logger });
module.exports = { logger, expressLogger };
Now, every time I do req.log.debug(config['abc']), the entire request body gets logged, thus making the logs very cumbersome to read. I tried changing the log levels but that doesn't help. Here is an example output:
DEBUG [1610445271782] (on blserver-org1): sku=FIN01 Query String req: { "id": 1, "method": "POST", "url": "/ifo_params?sku=FIN01", "headers": { "channel-name": "mychannel", "content-type": "application/json", "authorization": "Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6IjVmOTcxMmEwODczMTcyMGQ2NmZkNGEyYTU5MmU0ZGZjMmI1ZGU1OTUiLCJ0eXAiOiJKV1QifQ.eyJvcmdJZCI6ImJ1eWVyMiIsImFkbWluIjp0cnVlLCJpc3MiOiJodHRwczovL3NlY3VyZXRva2VuLmdvb2dsZS5jb20vbWFya2V0c24tZGV2IiwiYXVkIjoibWFya2V0c24tZGV2IiwiYXV0aF90aW1lIjoxNjEwNDQ0ODU5LCJ1c2VyX2lkIjoibzBWZWl4VnJmZFJqbEdWZXlNS1p4Q052TkZSMiIsInN1YiI6Im8wVmVpeFZyZmRSamxHVmV5TUtaeENOdk5GUjIiLCJpYXQiOjE2MTA0NDQ4NTksImV4cCI6MTYxMDQ0ODQ1OSwiZW1haWwiOiJidXllcjJfYWRtaW5AbWFpbGluYXRvci5jb20iLCJlbWFpbF92ZXJpZmllZCI6ZmFsc2UsImZpcmViYXNlIjp7ImlkZW50aXRpZXMiOnsiZW1haWwiOlsiYnV5ZXIyX2FkbWluQG1haWxpbmF0b3IuY29tIl19LCJzaWduX2luX3Byb3ZpZGVyIjoicGFzc3dvcmQifX0.QlHxLrxcfxUmGK_Q193RdQSIBsoHly66CZDTWdRdyfZNAn-wH13el41ILnAj3YqVWgAFJY8u4BcFgZYePCujIO2gKFsM0WUs2M-a7CsMcDaWpqrQyVsfalRoYMDsk1DJypaevuKV8O4IbmdkgCbS8HmYO-dk99LRcwwYKs_vVnNBO4bTv5FFzMLh-DXrVfVBKk23Qem7JN5lX9UU6RZ-4WAVN-pN-TR5uRuF2koWjCoa90CKNhYOzKW1zeN904f1rCeuY0a4R4faFYMNAlkxslBpVSKaXCkSBXOSCjVykp611Ay6EQBkrpqbD1zHvv6eEfaaMyOzjlH3DzDye-vfMQ", "user-agent": "PostmanRuntime/7.26.8", "accept": "*/*", "cache-control": "no-cache", "postman-token": "aab26357-78ff-4899-8509-7918ca9a65c4", "host": "localhost:3000", "accept-encoding": "gzip, deflate, br", "connection": "keep-alive", "content-length": "114" } }
Can someone please tell me how to tell pino to not log the entire request every time.
Internal stack trace logged
Hi.
I think i'm just a bit confused about the way express-pino-logger/pino-http handles errors, i would expect any thrown errors to be caught & logged by pino, instead it seems they are caught but the thrown error itself is discarded and instead a default error (with useless stack trace) is logged (See 'failed with status code': https://github.com/pinojs/pino-http/blob/master/logger.js#L48)
This is because express doesn't emit the error event on the response object whenever an error is caught. I need the correct stack trace to be logged so what i had to do was to write this error-catching middleware:
app.use(function (err, req, res, next) {
res.emit('error', err)
res.status(500).json({ ... })
})
I saw that in examples.js there is a middleware that does req.log.error(err) and this actually logs the error with the stack trace, but then the internal stack trace (on LOC pasted above) is also logged:
"err":{"type":"Error","message":"failed with status code 500","stack":"Error: failed with status code 500\n at ServerResponse.onResFinished (/xxxxxx/pino-http/logger.js:48:33)\n at ServerResponse.emit (events.js:194:15)\n at onFinish (_http_outgoing.js:671:10)\n at process._tickCallback (internal/process/next_tick.js:61:11)"}
I don't want to see the internal stack trace in my log, i just want to see the request/response & eventual errors in the same json blob. Is there any sane way of doing this, i mean without doing res.emit('error', err) which is just a hack i use temporarily? Basically i just want all thrown errors to to be caught & logged with correct stack trace
Incorrect readme.md example
https://github.com/pinojs/express-pino-logger#custom-serializers
'use strict'
var app = require('express')()
+ var ExpressPinoLogger = require('express-pino-logger')
- var ExpressPinoLogger = require('express-pino-logger')() <-------- remove the `()` because we pass `serializers` below.
var pino = ExpressPinoLogger({
serializers: {
req: (req) => ({
method: req.method,
url: req.url,
user: req.raw.user,
}),
},
})
// middleware that augments the req - must be added before the pino middleware
app.use((req, res, next) => {
req.user = 'testing';
next();
})
app.use(pino)How to write to a file?
Reading https://getpino.io/#/docs/api?id=destination-sonicboom-writablestream-string, I am trying to write the log to a file.
When I write
const pino = require('express-pino-logger')('./logs');
I get error
/home/jason/projects/node/h1bhub-app/node_modules/pino-http/logger.js:15
opts.serializers = opts.serializers || {}
^
TypeError: Cannot create property 'serializers' on string './logs'
at pinoLogger (/home/jason/projects/node/h1bhub-app/node_modules/pino-http/logger.js:15:20)
at Object.<anonymous> (/home/jason/projects/node/h1bhub-app/index.js:3:44)
at Module._compile (internal/modules/cjs/loader.js:689:30)
at Object.Module._extensions..js (internal/modules/cjs/loader.js:700:10)
at Module.load (internal/modules/cjs/loader.js:599:32)
at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
at Function.Module._load (internal/modules/cjs/loader.js:530:3)
at Function.Module.runMain (internal/modules/cjs/loader.js:742:12)
at startup (internal/bootstrap/node.js:282:19)
at bootstrapNodeJSCore (internal/bootstrap/node.js:743:3)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] server: `node index.js`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the [email protected] server script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
npm ERR! A complete log of this run can be found in:
npm ERR! /home/jason/.npm/_logs/2019-03-10T20_57_50_633Z-debug.log
Any idea why?
Unable to redact certain information from existing log files
Hi,
I'm using pino-noir library in some micro services and able to redact sensitive information for e.g. req.headers.authorization in standard output of logs whenever our REST API gets a request. This is working fine as expected. I'm getting the logs where authorization information in the header is redacted.
Now, I have use case where there are already a set of logs generated in JSON format. I want to read those log files and perform the redact by passing the keys in it dynamically. If the key matches anywhere in the JSON log file then redact it else don't perform any action on it and in the end show standard output to console.
I have written a NodeJS program to read these log files but not getting my head around on how to map this log file to the pino object. I know we can pass the pino object to express app like app.use(loggerpdino()); which will start reading the request/response and perform redacting but not sure how to do the similar way using this log file object.
My program looks like this
const noir = require('pino-noir');
const fs = require('fs');
let keys = [];
const label = 'Content Masked';
const redactLogs = (file, obj) => {
console.log('Object received that needs to be whitelisted/blacklisted or both:::', obj);
console.log('JSON File Path::', file);
if(obj !== undefined && obj !== null){
console.log(Object.keys(obj));
let jsonData = {}
if (obj.hasOwnProperty("blacklisted")) {
console.log(obj['blacklisted']);
obj['blacklisted'].forEach(element => {
keys.push(element);
});
}
if (obj.hasOwnProperty("whitelisted")) {
console.log(obj['whitelisted']);
keys = keys.filter(function(x) {
return obj['whitelisted'].indexOf(x) < 0;
});
}
const redaction = noir(
paths = keys,
censor = label
);
console.log('Redaction keys:::', redaction);
if(file !== null){
fs.readFileSync(file, 'utf-8', (err, data) => {
if (err) throw err
jsonData = JSON.parse(data);
})
console.log('JSON data::',jsonData);
const redactedPino = require('pino')({
serializers: redaction
});
}
//perform logging to console
}
}
module.exports.redactLogs = redactLogs;
Other app who is going to use this my library will have to import and pass the object like this:-
const { redactLogs } = require('@vinod827/my-logging-framework/my-redacting-logs');
const myobject = {
blacklisted:['req.headers.user-agent'],
whitelisted:['req.method']
}
app.use(redactLogs('/Users/vkumar/go/mywork/mydevelopment/my-sample-app/logs/app.log', myobject));
In myobject, I will be passing an array of keys in the blacklisted variable (whitelisted is optional so please ignore that), which eventually be scanning on logs (in JSON format), if a match happens then output its value in masked form else do not mask.
Please let me know how to pass jsonData object to the redactedPino object to perform the scan.
Thank you
What are the differences with pino-http?
I've seen in the code base that the only lines are
'use strict'
module.exports = require('pino-http')So I don't understand what is the utility of this library 🤔
I've installed pino-http on my express server and it works well.
Can you help me?
What is unit of measurement for the responseTime in logs
What is unit of measurement for the responseTime that are shown in logs.
res: {
"statusCode": 200,
"header": "HTTP/1.1 200 OK\r\nX-Powered-By: Express\r\nContent-Type: text/html; charset=utf-8\r\nContent-Length: 11\r\nETag: W/\"b-XrY7u+Ae7tCTyyK7j1rNww\"\r\nDate: Thu, 31 Mar 2016 16:53:21 GMT\r\nConnection: keep-alive\r\n\r\n"
}
responseTime: 10
req: {
"id": 1,
"method": "GET",
"url": "/",
"headers": {
"host": "localhost:3000",
"user-agent": "curl/7.43.0",
"accept": "*/*"
},
"remoteAddress": "::1",
"remotePort": 64386
}
So here responseTime: 10 is in milliseconds or seconds ?
Clarify this is just a "clone" of pino-http
Update:
Nevermind, I found #41.
Not to be harsh, but it blows my mind that nobody thought it was a good idea to mention that this project is just for search purposes in the README.
Original questions:
Can you please explain how this package differs from pino-http? And why it is not mentioned in pino/Using with Express?
Thank you.
Is there an option to track the "time elapsed"?
I would like to get rid off some middlewares that I use to track the time elapsed on a request with pino, but I couldn't find an option to do so on express-pino-logger, Am I missing something?
This is what I use to keep track of the time elapsed of a request:
export function onRequestStart(req, res, next) {
if (logger.options.enabled) {
req.app.set('sequence', req.app.get('sequence') + 1);
req.start = Date.now();
req.id = uuid(); // express-pino-logger: each request has its own id but as int
}
next();
}
export function onRequestEnd(req, res, next) {
res.on('finish', () => {
if (logger.options.enabled) {
if (req.error) {
logger.error({ req, res, err: req.error }, req.error.message);
} else {
logger.info({ req, res });
}
}
});
next();
}And these are the options as a module:
const uuid = require('uuid/v4');
const os = require('os');
const Pino = require('pino');
export const options = {
base: {
instance: uuid(),
pid: process.pid,
hostname: os.hostname(),
hostport: JSON.parse(process.env.SERVER_PORT),
hostip: process.env.SERVER_HOST,
env: process.env.NODE_ENV
},
enabled: JSON.parse(process.env.LOG_ENABLED),
name: process.env.APP_NAME,
level: process.env.LOG_LEVEL,
prettyPrint: process.env.LOG_PRETTY_PRINT,
serializers: {
req: function(req) {
return {
method: req.method,
url: req.protocol + '://' + req.get('host') + req.originalUrl,
id: req.id,
seq: req.app.get('sequence'),
params: req.params,
query: req.query,
headers: req.headers,
remoteAddress: req.connection.remoteAddress,
remotePort: req.connection.remotePort
}
},
res: function(res) {
return {
elapsed: `${Date.now() - res.req.start}ms`,
status: res.statusCode,
headers: res.getHeaders()
}
},
err: Pino.stdSerializers.err
}
}
const logger = new Pino(options);
logger.options = options;
export default logger;What are your thoughts on this?
Thanks!.
Doesn't print stack trace
Using the following error handler together with express-pino-logger:
app.use((err, req, res, next) => {
const httpError = createHTTPError(err)
if (httpError.status === 500) {
req.log.error(err)
}
if (res.headersSent) {
return req.socket.destroy()
}
res.status(httpError.status)
res.send(
httpError.expose || !config.isProduction
? httpError.message
: '500 Internal Server Error'
)
})I would expect that req.log.error(err) would at least print the stack trace in development mode. However, it just prints the req and res objects.
res: {
"statusCode": 500
}
req: {
...
}
Setting useLevel to 'silent' in config results in TypeError
If you set the useLevel property in pino's config object to 'silent', it results in the following:
TypeError: log[useLevel] is not a function
Is this because either express-pino-logger or pino-http are using an older version of pino? I'm happy to make a PR for this but I'm not sure where to start with this particular issue. Any pointers are appreciated.
Use only the error logger and don't log every request
Basically, everything is said. I want to use the pino-express-logger, but only to log errors and not every request. Is there an option to disable automatic request logging?
Where would I implement it?
Thanks for your help!
How to find file and line that caused the error?
Hello, I've just started utilizing pino and express-pino-logger for my project. I've been able to find the stack traces, but the only issue is that it doesn't list my file that caused the error and rather just the node_module file that caused it internally within express. Is it possible to find which of my files caused the error?
(For context I've removed the headers from this example as they shouldn't matter and I've ran it through pino-pretty in order to read it better)
500 Error Example:
[1587329487144] INFO (5093 on paradox): request errored
req: {
"id": 8,
"method": "GET",
"url": "/stacktrace-test",
"headers": {}
}
err: {
"type": "Error",
"message": "failed with status code 500",
"stack":
Error: failed with status code 500
at ServerResponse.onResFinished (/home/jeff/NewRepo/node_modules/pino-http/logger.js:67:38)
at emitNone (events.js:111:20)
at ServerResponse.emit (events.js:208:7)
at onFinish (_http_outgoing.js:720:10)
at _combinedTickCallback (internal/process/next_tick.js:131:7)
at process._tickCallback (internal/process/next_tick.js:180:9)
}
responseTime: 11
log info from the request module
I have request module inside my app and would like to log the response. Not sure if this is possible, any tip would be greatly appreciated.
What would be the best way to log this?
See the code below.
'use strict'
var app = require('express')()
var pino = require('express-pino-logger')()
var request = require('request')
app.use(pino)
app.get('/', function (req, res) {
request({
method: 'GET',
url: encodeURI(`http://someapi.com`),
headers: {
'Content-Type': 'application/json'
},
timeout: 500,
time: true
}, function(err, req, response, body) {
req.log.info('inside reqeust module')
}
);
// each request has its own id
// so you can track the log of each request
// by using `req.log`
// the ids are cycled every 2^31 - 2
req.log.info('something else')
res.send('hello world')
})
app.listen(3000)
Upgrade pino-http dependency to 6.0.0
Since Pino v7 was launched the custom serializers for express-pino-logger have stopped working and every detail from the request gets logged which is not ideal. The pino-http. 6.0.0 already upgraded their Pino v7 inner dependency.
I already can see that master has the latest pino-http version so is this migration process in the works?
why use this instead of pino-http?
looks like this is just exporting pino-http now, maybe it would be better to indicate users to use the latest pino-http directly
[DEP0066] DeprecationWarning: OutgoingMessage.prototype._headers is deprecated
Node version: 12.9.1
Running with the latest version of express-pino-logger, I get DeprecationWarnings in my log output due to accessing OutputMessage.prototype._headers. This looks to be related to pinojs/pino-std-serializers#23 (fixed in pinojs/pino-std-serializers#24), which just needs to be propagated to pino-http and here.
Change Log level at runtime
Is there a way in pino to change Log level at runtime?
My goal is to create an endpoint where we can change log level without restarting an app.
Similar to this.
https://github.com/yannvr/Winston-dynamic-loglevel
How to not get the headers and req in logs file?
I'm using pino for logging but the default log file contains so much data that I want to delete them such as the headers and req.
How can I do that?
Readme should alert that this library (seems to be) deprecated for pino-http
Update new pino-http version
Update New version of pino-http so that it can using regex when using pathIgnore :
pinojs/pino-http#100
how to filter by http status code
I want to only log status code >400 request ,how to do it? THanks.
Ability to mask or remove the Authorization header
It would be nice to provide additional configuration to define what headers you would like removed or masked when logging. For example, the Authorization header which you might not want included in the logs.
Update to Pino 6.x and pino-http 5.x
I have a PR ready, but it's blocked on pinojs/pino-http#99
QUESTION: pino and pino-express
Hello maintainers,
Thank you for this awesomeness. I just have a question.
If I use express-pino do i still have to use pino?
im confused so im using it like this.
import pinoExpress from 'express-pino-logger';
import pino from 'pino';
const pins = pino();
app.use(pinoExpress({logger: pins, prettyPrint: true }, pino.destination(path.resolve(__dirname, '../logs/route.log'))));
// some routes implementation
pins.info('test route..'); < ---- this wont be written in the filie. is this a bug?How can I use the same instance of pino in and out of express?
Either its too early in my day or I can't see a way of say creating a pino instance and then using that within this library.
log not output on timeout
I was trying to move from morgan to express-pino-logger but noticed that a log is not output when there's a timeout. morgan will output it with a status code of - but express-pino-logger doesn't output anything. Is there a setting to enable that output?
express not responding
Request to http://localhost:3000/ freezes and does not return any response.
Node v16.16.0
https://github.com/pinojs/express-pino-logger/#example
`'use strict'
var app = require('express')()
var pino = require('express-pino-logger')
app.use(pino)
app.get('/', function (req, res) {
// each request has its own id
// so you can track the log of each request
// by using req.log
// the ids are cycled every 2^31 - 2
req.log.info('something else')
res.send('hello world')
})
app.listen(3000)`
ignore routes
Is there a way to ignore routes from logging like /health?
prevLogger.child is not a function
I am getting the following error:
C:\backend\node_modules\pino-http\logger.js:83
logger = prevLogger.child(opts)
^
TypeError: prevLogger.child is not a function
at wrapChild (C:\backend\node_modules\pino-http\logger.js:83:25)
at pinoLogger (C:\backend\node_modules\pino-http\logger.js:32:16)
at Object. (C:\backend\src\routes\auth.js:15:51)
at Module._compile (internal/modules/cjs/loader.js:689:30)
at Object.Module._extensions..js (internal/modules/cjs/loader.js:700:10)
at Module.load (internal/modules/cjs/loader.js:599:32)
at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
at Function.Module._load (internal/modules/cjs/loader.js:530:3)
at Module.require (internal/modules/cjs/loader.js:637:17)
at require (internal/modules/cjs/helpers.js:22:18)
routes/signin.js:
const router = express.Router();
const pino = require('pino');
const log = pino({ level: process.env.LOG_LEVEL || 'info' });
const expressPino = require('express-pino-logger')({
logger: pino
})
router.use(expressPino);
-Markus
child attribute is output twice
I'm using the concept described in #17 and the value that's added is logged twice. For example, user_id: 1 appears in the output JSON twice and this looks confusing and technically isn't valid JSON.
Log the req/res body
Hey there!
This lib is quite excellent.
Only issue: I'd love to log the req and res bodies as they contain useful information.
What is the desired way of doing this?
Appending to every request.
I'd like to append data to every request and found a workable solution in #17 as a middleware. However, I just want to confirm that there aren't any performance implications with creating and replacing the logger, with a child instance, on every request?
The code snippet I'm referring to is:
res.log = req.log = req.log.child({ })
Thanks!
Prevent logging of every static asset
In other loggers placing the log middleware after the static middleware seems to do the trick but here I get a log entry for every image/css/js file no matter where I place the pino entry. Is there an easy way to not log static assets?
how to remove this "REQUEST COMPLETED" from pino
How do you remove the request and response from pino? It seems too long and unnecessary. I redacted both but is there another way to remove this? I didn't get this until I was creating a test.
Redacted both but it's annoying.
Thank you much.
Ability to add child to req
Currently, it appears that you have to add child attributes to res.log for them to show up in the final message. Some frameworks, like swagger-tools only pass req so is there a way to add a child attribute to req and have it still show up in the final output?
Color support?
Is there color support for this?
How to pass custom data in all lines?
I use PassportJS and I want to insert in logs id of logger user. User is stored in req.user object.
How to add req.user.id in any log lines?
I tried to use serializers, but req serializer runs before passportjs, so req.user is not defined at that time.
how to log cdn cloudflare ip address?
req.remoteAddress does not working, how to change to req.header('x-real-ip'), mywebsite is running behind cloudflare cdn.
serializers: {
req: function requestSerializer(req) {
return {
id: req.id,
method: req.method,
url: req.url,
remoteAddress: req.header('x-real-ip') || req.connection.remoteAddress,
remotePort: req.remotePort,
body: req.raw.body,
};
},
},
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.