Req element twitce with hapi.

[indreek]

Any ideas why im getting req twice in logged json?

	"level": 30,
	"time": 1573488495601,
	"pid": 6012,
	"hostname": "nodejs",
	"req": {
		"id": "1573488495579:nodejs:6012:k2umf1vz:10000",
		"method": "get",
		"url": "http://192.168.0.128:4010/hello/world/",
		"headers": {
			"content-type": "application/json",
			"user-agent": "PostmanRuntime/7.19.0",
			"accept": "*/*",
			"cache-control": "no-cache",
			"postman-token": "ae33203b-1dc5-4f93-998f-f450ba43279f",
			"host": "192.168.0.128:4010",
			"accept-encoding": "gzip, deflate",
			"connection": "keep-alive"
		},
		"remoteAddress": "192.168.0.1",
		"remotePort": 60046
	},
	"req": {
		"id": "1573488495579:nodejs:6012:k2umf1vz:10000",
		"method": "get",
		"url": "http://192.168.0.128:4010/hello/world/",
		"headers": {
			"content-type": "application/json",
			"user-agent": "PostmanRuntime/7.19.0",
			"accept": "*/*",
			"cache-control": "no-cache",
			"postman-token": "ae33203b-1dc5-4f93-998f-f450ba43279f",
			"host": "192.168.0.128:4010",
			"accept-encoding": "gzip, deflate",
			"connection": "keep-alive"
		},
		"remoteAddress": "192.168.0.1",
		"remotePort": 60046
	},
	"res": {
		"statusCode": 200,
		"headers": {
			"content-type": "application/json; charset=utf-8",
			"vary": "origin,accept-encoding",
			"access-control-expose-headers": "WWW-Authenticate,Server-Authorization",
			"cache-control": "no-cache",
			"content-encoding": "gzip"
		}
	},
	"responseTime": 22,
	"msg": "request completed",
	"v": 1
}

[indreek]

'use strict'

const Hapi = require('@hapi/hapi')

async function start () {
    // Create a server with a host and port
    const server = Hapi.server({
        // host: 0.0.0.0,
        port: 3000
    })

    // Add the route
    server.route({
        method: 'GET',
        path: '/',
        handler: async function (request, h) {
            return 'hello world'
        }
    })

    await server.register({
        plugin: require('hapi-pino'),
        options: {}
    })

    // also as a decorated API
    server.logger().info('another way for accessing it')

    // and through Hapi standard logging system
    server.log(['subsystem'], 'third way for accessing it')

    await server.start()

    return server
}

start().catch((err) => {
    console.log(err)
    process.exit(1)
})

[indreek]

Probably it comes from Pino https://getpino.io/#/docs/child-loggers?id=duplicate-keys-caveat

[indreek]

Hi

It was still bothering me.

const getChildBindings = options.getChildBindings ? options.getChildBindings : (request) => ({ req: request })
//....
const childBindings = getChildBindings(request)
request.logger = logger.child(childBindings) // You are adding child req: here, 

// Although you are 
// 1) adding it here when logRequestStart === true or 
if (logRequestStart) {  
  request.logger.info({
    req: request
  }, 'request start')
}

tryAddEvent(server, options, 'on', 'response', function (request) {
//...
request.logger.info(
  {
    payload: options.logPayload ? request.payload : undefined,
    tags: options.logRouteTags ? request.route.settings.tags : undefined,
    // note: pino doesnt support unsetting a key, so this next line
    // has the effect of setting it or "leaving it as it was" if it was already added via child bindings
    req: logRequestStart ? undefined : request, // 2) adding it here when logRequestStart === false
    res: request.raw.res,
    responseTime: (info.completed !== undefined ? info.completed : info.responded) - info.received
  },
  'request completed'
)

quick fix for this in my opinion is to change options:

getChildBindings: () => ({})

[aorinevo]

We are seeing the same error as well.

@indreek, have you been able to identify the root cause?

[aorinevo]

Well, looks like the link right above says it all.

Thanks for sharing this :)

[antonsamper]

I'm using version 6.5.0 and I'm seeing duplicate values in the req object in my logs:

x-appengine-country: "GBGB"     
x-appengine-default-namespace: "gmail.comgmail.com"      
x-appengine-https: "onon"     
x-appengine-region: "engeng" 

[mdenushev]

Hello it seems to be here and req: shouldLogRequestStart(request) || options.serializers.req ? undefined : request does the trick

[AdriVanHoudt]

Setting getChildBindings: () => ({}) solves the issue for response logs but also gets rid of request data for request.log logs (being done here https://github.com/pinojs/hapi-pino/blob/master/index.js#L140).

Not sure what the right solution is to get both 🤔

• getChildBindings: () => ({}) gets rid of doubles in response logs
• getChildBindings: (request) => ({ req: request}) adds the request info of request.log but causes doubles in response logs
• I don't think there is a way for the plugin to know whether req was added already
• An option might be to pass event here https://github.com/pinojs/hapi-pino/blob/master/index.js#L140 which would allow the implementer to add the request only when event is passed?

[AdriVanHoudt]

I'm using version 6.5.0 and I'm seeing duplicate values in the req object in my logs:

x-appengine-country: "GBGB"     
x-appengine-default-namespace: "gmail.comgmail.com"      
x-appengine-https: "onon"     
x-appengine-region: "engeng" 

I'm actually seeing the same thing.
Due to the double req props, Google Cloud logging seems to resolve this by adding the value twice 😅

[AdriVanHoudt]

I think I've found a way to better handle this.
Please take a look at #157