Repository: pinojs/hapi-pino (js)

Issue:
Logging non 5xx error details
Hapi-pino should log the error details for any uncaught error regardless of what status code the response is mapped to. For example, if a route handler throws `Boom.forbidden('Some Reason')` then the log for the response should include the error details just as it does when an unknown error is thrown such as `throw Error('Some Reason')`.

The Hapi request event docs state that any uncaught error response will be emitted with "handler" and "error" tags along with the error so maybe this gap is due to a bug in Hapi. The Hapi response event for these non-5xx error responses does make the uncaught error available via the "response._error" property though so  hapi-pino could implement a workaround.

I also posted this as a question in the general Hapi Slack channel but as yet have not had an answer.

Pull request:
add option to log 4xx error details in request logs
Fixes #111 

This PR adds a new option `log4xxResponseErrors` that, when true, will add the error details to the response log under the key `err` (chosen to match 500 error logging).

For example:

```
{"level":30,"time":1683229159104,"pid":92186,"hostname":"jeff-MacBook-Pro","req":{"id":"1683229159103:jeff-MacBook-Pro:92186:lh9j6jej:10000","method":"get","url":"/","query":{},"headers":{"user-agent":"shot","host":"jeff-MacBook-Pro:0"},"remoteAddress":"127.0.0.1","remotePort":""},"err":{"type":"Object","message":"invalid request","stack":"","statusCode":400,"error":"Bad Request"},"res":{"statusCode":400,"headers":{"content-type":"application/json; charset=utf-8","cache-control":"no-cache","content-length":68}},"responseTime":1,"msg":"[response] get / 400 (1ms)"}
```

This pulls the response from the `request.response.source` object, which is the [value returned by the lifecycle method](https://hapi.dev/api/?v=19.2.1#-responsesource).

Patch:
diff --git a/README.md b/README.md
index 31d1c0d..f56d47b 100644
--- a/README.md
+++ b/README.md
@@ -114,6 +114,12 @@ events"](#hapievents) section.
 
   When enabled, add the request route tags (as configured in hapi `route.options.tags`) `tags` to the `response` event log.
 
+### `options.log4xxResponseErrors: boolean`
+
+  **Default**: `false`
+
+  When enabled, responses with status codes in the 400-500 range will have the value returned by the hapi lifecycle method added to the `response` event log as `err`.
+
 ### `options.logRequestStart: boolean | (Request) => boolean`
 
   **Default**: false
diff --git a/index.d.ts b/index.d.ts
index 8732a3b..9a9fc03 100644
--- a/index.d.ts
+++ b/index.d.ts
@@ -21,6 +21,7 @@ declare namespace HapiPino {
     logPathParams?: boolean | undefined;
     logPayload?: boolean | undefined;
     logRouteTags?: boolean | undefined;
+    log4xxResponseErrors?: boolean | undefined;
     logRequestStart?: boolean | ((req: Request) => boolean) | undefined;
     logRequestComplete?: boolean | ((req: Request) => boolean) | undefined;
     customRequestStartMessage?: ((req: Request) => string) | undefined;
diff --git a/index.js b/index.js
index d0f120d..f98f250 100644
--- a/index.js
+++ b/index.js
@@ -171,6 +171,7 @@ async function register (server, options) {
 
     if (shouldLogRequestComplete(request)) {
       const info = request.info
+      const statusCode = request.response.statusCode
       if (!request.logger) {
         const childBindings = getChildBindings(request)
         request.logger = logger.child(childBindings)
@@ -184,6 +185,7 @@ async function register (server, options) {
           queryParams: options.logQueryParams ? request.query : undefined,
           pathParams: options.logPathParams ? request.params : undefined,
           tags: options.logRouteTags ? request.route.settings.tags : undefined,
+          err: options.log4xxResponseErrors && (statusCode >= 400 && statusCode < 500) ? request.response.source : undefined,
           res: request.raw.res,
           responseTime
         },
diff --git a/package.json b/package.json
index b41cbfc..a0beab6 100644
--- a/package.json
+++ b/package.json
@@ -20,6 +20,7 @@
   ],
   "license": "MIT",
   "devDependencies": {
+    "@hapi/boom": "^10.0.1",
     "@hapi/code": "^9.0.0",
     "@hapi/hapi": "^21.0.0",
     "@hapi/lab": "^25.0.0",


Test patch:
diff --git a/test.js b/test.js
index 0d47809..d72a136 100644
--- a/test.js
+++ b/test.js
@@ -20,6 +20,7 @@ const afterEach = lab.afterEach
 const expect = Code.expect
 
 const Hapi = require('@hapi/hapi')
+const Boom = require('@hapi/boom')
 const Pino = require('.')
 
 function getServer () {
@@ -61,31 +62,25 @@ function sink (func) {
   return result
 }
 
-async function registerWithSink (server, level, func) {
+async function registerWithOptionsSink (server, options, func) {
   const stream = sink(func)
   const plugin = {
     plugin: Pino,
     options: {
-      stream,
-      level
+      ...options,
+      stream
     }
   }
 
   await server.register(plugin)
 }
 
-async function tagsWithSink (server, tags, func) {
-  const stream = sink(func)
-  const plugin = {
-    plugin: Pino,
-    options: {
-      stream,
-      level: 'trace',
-      tags
-    }
-  }
+async function registerWithSink (server, level, func) {
+  await registerWithOptionsSink(server, { level }, func)
+}
 
-  await server.register(plugin)
+async function tagsWithSink (server, tags, func) {
+  await registerWithOptionsSink(server, { level: 'trace', tags }, func)
 }
 
 function onHelloWorld (data) {
@@ -549,6 +544,36 @@ experiment('logs each request', () => {
     await server.inject('/')
     await finish
   })
+
+  test('logs 4xx level error details', async () => {
+    const server = getServer()
+
+    let done
+
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+
+    server.route({
+      path: '/',
+      method: 'GET',
+      handler: async (req, h) => {
+        return Boom.badRequest('invalid request')
+      }
+    })
+
+    await registerWithOptionsSink(server, { level: 'info', log4xxResponseErrors: true }, data => {
+      expect(data.res.statusCode).to.equal(400)
+      expect(data.err.stack).to.not.be.undefined()
+      expect(data.err.error).to.match(/Bad Request/)
+      expect(data.err.statusCode).to.equal(400)
+      expect(data.err.message).to.match(/invalid request/)
+      done()
+    })
+
+    await server.inject('/')
+    await finish
+  })
 })
 
 experiment('logs through server.log', () => {