Skip to content

Commit

Permalink
Add custom object hooks (#231)
Browse files Browse the repository at this point in the history 
* Add custom object hooks

This adds a functionality for overriding/customising the structured object
logged at request received/success/error. It is *like* the
custom[Received|Success|Error]Message hooks, but works on customising the
structured object.

It was opted not to overload *Message due to that being specifically about
messages, and the risk that adjusting that could break an existing usage
of that hook.

The README has been updated with example usage.

* Add tests for custom hooks

* Pull request feedback
Convert from local functions, and reduce conditional complexity

* Make function casing consistent with existing code
  • Loading branch information
@Simon-Campbell
Simon-Campbell authored Jun 26, 2022
1 parent 1cda3d5 commit 379932c
Show file tree
Hide file tree
Showing 4 changed files with 198 additions and 14 deletions.
50 changes: 50 additions & 0 deletions README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -101,8 +101,11 @@ $ node example.js | pino-pretty
* `autoLogging.ignore`: set to a `function (req) => { /* returns boolean */ }`. Useful for defining logic based on req properties (such as a user-agent header) to ignore successful requests.
* `stream`: same as the second parameter
* `customReceivedMessage`: set to a `function (req, res) => { /* returns message string */ }` This function will be invoked at each request received, setting "msg" property to returned string. If not set, nothing value will be used.
* `customReceivedObject`: set to a `function (req, res, loggableObject) => { /* returns loggable object */ }` This function will be invoked at each request received, replacing the base loggable received object. When set, it is up to the reponsibility of the caller to merge with the `loggableObject` parameter. If not set, default value will be used.
* `customSuccessMessage`: set to a `function (req, res) => { /* returns message string */ }` This function will be invoked at each successful response, setting "msg" property to returned string. If not set, default value will be used.
* `customSuccessObject`: set to a `function (req, res, loggableObject) => { /* returns loggable object */ }` This function will be invoked at each successful response, replacing the base loggable success object. When set, it is up to the reponsibility of the caller to merge with the `loggableObject` parameter. If not set, default value will be used.
* `customErrorMessage`: set to a `function (req, res, err) => { /* returns message string */ }` This function will be invoked at each failed response, setting "msg" property to returned string. If not set, default value will be used.
* `customErrorObject`: set to a `function (req, res, err, loggableObject) => { /* returns message string */ }` This function will be invoked at each failed response, the base loggable error object. When set, it is up to the reponsibility of the caller to merge with the `loggableObject` parameter. If not set, default value will be used.
* `customAttributeKeys`: allows the log object attributes added by `pino-http` to be given custom keys. Accepts an object of format `{ [original]: [override] }`. Attributes available for override are `req`, `res`, `err`, `responseTime` and, when using quietReqLogger, `reqId`.
* `wrapSerializers`: when `false`, custom serializers will be passed the raw value directly. Defaults to `true`.
* `customProps`: set to a `function (req, res) => { /* returns on object */ }` or `{ /* returns on object */ }` This function will be invoked for each request with `req` and `res` where we could pass additional properties that need to be logged outside the `req`.
Expand Down Expand Up @@ -197,6 +200,53 @@ function handle (req, res) {
server.listen(3000)
```

##### Structured Object Hooks

It is possible to override the default structured object with your own. The hook is provided with the
pino-http base object so that you can merge in your own keys.

This is useful in scenarios where you want to augment core pino-http logger object with your own event
labels.

> If you simply want to change the message which is logged then check out the custom[Received|Error|Success]Message
> hooks e.g. customReceivedMessage
```js
const logger = require('pino-http')({
//... remaining config omitted for brevity
customReceivedObject: (req, res, val) => {
return {
category: 'ApplicationEvent',
eventCode: 'REQUEST_RECEIVED'
};
},

customSuccessObject: (req, res, val) => {
return {
...val,
category: 'ApplicationEvent',
eventCode:
res.statusCode < 300
? 'REQUEST_PROCESSED'
: 'REQUEST_FAILED'
};
},

customErrorObject: (req, res, error, val) => {
const store = storage.getStore();
const formattedBaggage = convertBaggageToObject(store?.baggage);

return {
...val,
category: 'ApplicationEvent',
eventCode: 'REQUEST_FAILED'
};
}

// ...remaining config omitted for brevity
})
```
##### PinoHttp.logger (P.Logger)
The `pinoHttp` instance has a property `logger`, which references to an actual logger instance, used
Expand Down
3 changes: 3 additions & 0 deletions index.d.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,9 @@ export interface Options extends pino.LoggerOptions {
customReceivedMessage?: ((req: IncomingMessage, res: ServerResponse) => string) | undefined;
customSuccessMessage?: ((req: IncomingMessage, res: ServerResponse) => string) | undefined;
customErrorMessage?: ((req: IncomingMessage, res: ServerResponse, error: Error) => string) | undefined;
customReceivedObject?: ((req: IncomingMessage, res: ServerResponse, val?: any) => any) | undefined;
customSuccessObject?: ((req: IncomingMessage, res: ServerResponse, val: any) => any) | undefined;
customErrorObject?: ((req: IncomingMessage, res: ServerResponse, error: Error, val: any) => string) | undefined;
customAttributeKeys?: CustomAttributeKeys | undefined;
wrapSerializers?: boolean | undefined;
customProps?: ((req: IncomingMessage, res: ServerResponse) => object) | undefined;
Expand Down
70 changes: 56 additions & 14 deletions logger.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -64,9 +64,15 @@ function pinoLogger (opts, stream) {
const autoLoggingIgnore = opts.autoLogging && opts.autoLogging.ignore ? opts.autoLogging.ignore : null
delete opts.autoLogging

const receivedMessage = opts.customReceivedMessage && typeof opts.customReceivedMessage === 'function' ? opts.customReceivedMessage : undefined
const successMessage = opts.customSuccessMessage || function (req, res) { return res.writableEnded ? 'request completed' : 'request aborted' }
const errorMessage = opts.customErrorMessage || function () { return 'request errored' }
const onRequestReceivedObject = getFunctionOrDefault(opts.customReceivedObject, undefined)
const receivedMessage = getFunctionOrDefault(opts.customReceivedMessage, undefined)

const onRequestSuccessObject = getFunctionOrDefault(opts.customSuccessObject, defaultSuccessfulRequestObjectProvider)
const successMessage = getFunctionOrDefault(opts.customSuccessMessage, defaultSuccessfulRequestMessageProvider)

const onRequestErrorObject = getFunctionOrDefault(opts.customErrorObject, defaultFailedRequestObjectProvider)
const errorMessage = getFunctionOrDefault(opts.customErrorMessage, defaultFailedRequestMessageProvider)

delete opts.customSuccessfulMessage
delete opts.customErroredMessage

Expand Down Expand Up @@ -106,18 +112,25 @@ function pinoLogger (opts, stream) {
if (err || this.err || this.statusCode >= 500) {
const error = err || this.err || new Error('failed with status code ' + this.statusCode)

log[level]({
[resKey]: this,
[errKey]: error,
[responseTimeKey]: responseTime
}, errorMessage(req, this, error))
log[level](
onRequestErrorObject(req, this, error, {
[resKey]: this,
[errKey]: error,
[responseTimeKey]: responseTime
}),
errorMessage(req, this, error)
)

return
}

log[level]({
[resKey]: this,
[responseTimeKey]: responseTime
}, successMessage(req, this))
log[level](
onRequestSuccessObject(req, this, {
[resKey]: this,
[responseTimeKey]: responseTime
}),
successMessage(req, this)
)
}

function loggingMiddleware (req, res, next) {
Expand Down Expand Up @@ -147,9 +160,14 @@ function pinoLogger (opts, stream) {
}

if (shouldLogSuccess) {
if (receivedMessage !== undefined) {
const shouldLogReceived = receivedMessage !== undefined || onRequestReceivedObject !== undefined

if (shouldLogReceived) {
const level = getLogLevelFromCustomLogLevel(customLogLevel, useLevel, res, undefined, req)
req.log[level](receivedMessage(req, res))
const receivedObjectResult = onRequestReceivedObject !== undefined ? onRequestReceivedObject(req, res, undefined) : {}
const receivedStringResult = receivedMessage !== undefined ? receivedMessage(req, res) : undefined

req.log[level](receivedObjectResult, receivedStringResult)
}

res.on('close', onResFinished)
Expand Down Expand Up @@ -196,6 +214,30 @@ function reqIdGenFactory (func) {
}
}

function getFunctionOrDefault (value, defaultValue) {
if (value && typeof value === 'function') {
return value
}

return defaultValue
}

function defaultSuccessfulRequestObjectProvider (req, res, successObject) {
return successObject
}

function defaultFailedRequestObjectProvider (req, res, error, errorObject) {
return errorObject
}

function defaultFailedRequestMessageProvider () {
return 'request errored'
}

function defaultSuccessfulRequestMessageProvider (req, res) {
return res.writableEnded ? 'request completed' : 'request aborted'
}

module.exports = pinoLogger
module.exports.stdSerializers = {
err: serializers.err,
Expand Down
89 changes: 89 additions & 0 deletions test/test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -829,6 +829,25 @@ test('uses the custom successMessage callback if passed in as an option', functi
})
})

test('uses the custom successObject callback if passed in as an option', function (t) {
const dest = split(JSON.parse)
const logger = pinoHttp({
customSuccessObject: function (req, res, val) {
return { ...val, label: req.method + ' customSuccessObject' }
}
}, dest)

setup(t, logger, function (err, server) {
t.error(err)
doGet(server)
})

dest.on('data', function (line) {
t.equal(line.label, 'GET customSuccessObject')
t.end()
})
})

test('uses the custom receivedMessage callback if passed in as an option', function (t) {
const dest = split(JSON.parse)
const message = DEFAULT_REQUEST_RECEIVED_MSG
Expand All @@ -852,6 +871,57 @@ test('uses the custom receivedMessage callback if passed in as an option', funct
})
})

test('uses the custom receivedObject callback if passed in as an option', function (t) {
const dest = split(JSON.parse)
const logger = pinoHttp({
customReceivedObject: function (req, val) {
return { label: req.method + ' customReceivedObject' }
}
}, dest)

setup(t, logger, function (err, server) {
t.error(err)
doGet(server)
})

dest.on('data', function (line) {
if (line.label === undefined) {
return
}

t.equal(line.label, 'GET customReceivedObject')
t.end()
})
})

test('uses the custom receivedObject + receivedMessage callback if passed in as an option', function (t) {
const dest = split(JSON.parse)
const logger = pinoHttp({
customReceivedMessage: function (_req, _res) {
return DEFAULT_REQUEST_RECEIVED_MSG
},

customReceivedObject: function (req, val) {
return { label: req.method + ' customReceivedObject' }
}
}, dest)

setup(t, logger, function (err, server) {
t.error(err)
doGet(server)
})

dest.on('data', function (line) {
if (line.label === undefined && line.msg !== undefined) {
return
}

t.equal(line.msg, DEFAULT_REQUEST_RECEIVED_MSG)
t.equal(line.label, 'GET customReceivedObject')
t.end()
})
})

test('receve receivedMessage before successMessage', function (t) {
t.plan(3)
const dest = split(JSON.parse)
Expand Down Expand Up @@ -894,6 +964,25 @@ test('uses the custom errorMessage callback if passed in as an option', function
})
})

test('uses the custom errorObject callback if passed in as an option', function (t) {
const dest = split(JSON.parse)
const logger = pinoHttp({
customErrorObject: function (req, res, err, val) {
return { ...val, label: 'customErrorObject ' + req.method + ' ' + err.toString() }
}
}, dest)

setup(t, logger, function (err, server) {
t.error(err)
doGet(server, ERROR_URL)
})

dest.on('data', function (line) {
t.equal(line.label.indexOf('customErrorObject GET'), 0)
t.end()
})
})

test('receve receivedMessage before errorMessage', function (t) {
t.plan(3)
const dest = split(JSON.parse)
Expand Down

0 comments on commit 379932c

Please sign in to comment.