customProps always logs duplicate keys

[spence-s]

customProps always logs duplicate keys.

I am working with google cloud logging and it doesn't play nicely with the duplicate keys:

    customProps(req) {
      // adds a custom object to all http logs that stackdriver
      // uses to make logs more informative and visible at a glance
      // see: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#httprequest
      // for the details of the structured log messages
      return {
        httpRequest: {
          requestMethod: req.method,
          requestUrl: req.url,
          userAgent: req.headers['user-agent'],
          remoteIp:
            req.headers['x-forwarded-for']?.split(',').shift() ||
            req.socket?.remoteAddress,
        },
      };
    },

For instance:
custom props cause the following log:
"{ "httpRequest": {"method":"GET"},"httpRequest": {"method":"GET"}}"

ends up in stackdriver/google cloud logging looking like:
{httpRequest: { method: 'GETGET' }}

related to #197

[mcollina]

Can you include what you are trying to achieve? The snippet is not enough.

[spence-s]

• I want to use customProps to add the httpRequest object for google cloud logging
• I want to avoid the duplicate keys problem
• I do NOT want to use a transport to format or clean up the keys

Currently, any usage of customProps causes duplicate keys of whatever is added there because of this PR. #197 (it looks like the child bindings are always applied 2x since this PR)

Right now, as a user, I am forced to deal with duplicate keys if I want to use the customProps option.

[mcollina]

Your usecase is a bit far from mine.

Would you like to send a Pull Request to address this issue? Remember to add unit tests.

[kundkingan]

Got same issue here, want to add customProps to the last log e.g request completed

[spence-s]

I took a look at this over the weekend, and unfortunately I couldn't come up with a quick solution that doesn't cause unit tests to break. This one may require some time/care to fix correctly and maintain all current behavior.

In order to pass the correct (final) res.statusCode to the customProps bindings and have the bindings in logs on req.log and res.log we do need to have the bindings applied in both places.

[jamyouss]

I have the same issue.

Couldn't we just remove the customPropBindings on the loggingMiddleware

const customPropBindings = (typeof customProps === 'function') ? customProps(req, res) : customProps
if (customPropBindings) {
fullReqLogger = fullReqLogger.child(customPropBindings)
}

This will be done on the onResFinished function. I tested it quickly and it work.

The only question i have is, does the function onResFinished called on 100% use cases ?
Like on network failure, timeout ...

What do you think ?

[rbadr]

Hello @mcollina 👋

Here is a reproduction repository for this issue.
The customProps are defined here.

You'll see in the log output duplicate keys because customProps is called at the loggingMiddleware level and also the onResFinished level.

To reproduce :

// Start server 
yarn start

// Query server
curl --location --request GET 'http://localhost:3000'

// Response output
{
   "level":"info",
   "timestamp":"2022-09-21T07:27:38.590Z",
   "environment":"development",
   "service":"pino-customprops-bug-api",
   "req":{
      "id":1,
      "method":"GET",
      "url":"/",
      "query":{
         
      },
      "params":{
         "0":""
      },
      "headers":"[Redacted]",
      "remoteAddress":"::1",
      "remotePort":63715
   },
   "customProp":"I will be duplicated", => custom prop
   "customProp":"I will be duplicated", => custom prop duplicated
   "res":{
      "statusCode":200,
      "headers":"[Redacted]"
   },
   "duration":0.003,
   "message":"request completed"
}

[mcollina]

@rbadr can you simplify that repository by removing all traces of Nest? I'm not familiar with it and debugging something through all indirection is very hard. Could you reproduce just with pino-http?

[jose-sal-y-rosas]

Yeah. I can reproduce in pino-http.

Here an example:

File: pino-config.ts

import { Options } from 'pino-http';
import { IncomingMessage } from 'http';

export const pinoHttpConfig: Options = {
  quietReqLogger: false,
  autoLogging: true,
  base: { hostname: os.hostname },
  level: 'info',
  formatters: {
    level: (label: string) => {
      return { level: label };
    },
  },
  timestamp: () => `,"time":"${new Date(Date.now()).toISOString()}"`,
  serializers: {
    req: () => {},
  },
  customProps: function (req: IncomingMessage) {
    // Dummy message
    return { hola: 'hola' };
  },
};

Then, with pino-http:

File: logger.middleware.ts

import pino from 'pino-http';

import { pinoHttpConfig } from './pino.config';

export function LoggerMiddleware() {
  return pino(pinoHttpConfig);
}

Injecting middleware in express app:

app.use(LoggerMiddleware());

Output:

As you can see: "hola", appears twice.

[mcollina]

This is because customProps is called twice:

1. pino-http/logger.js

   Lines 107 to 110 in 3361ced

   	const customPropBindings = (typeof customProps === 'function') ? customProps(req, res) : customProps
   	if (customPropBindings) {
   	log = this.log.child(customPropBindings)
   	}

2. pino-http/logger.js

   Lines 144 to 147 in 3361ced

   	const customPropBindings = (typeof customProps === 'function') ? customProps(req, res) : customProps
   	if (customPropBindings) {
   	fullReqLogger = fullReqLogger.child(customPropBindings)
   	}

I think #197 had a bad bug we didn't see at the time.
I think we should have have

pino-http/logger.js

Lines 107 to 110 in 3361ced

	const customPropBindings = (typeof customProps === 'function') ? customProps(req, res) : customProps
	if (customPropBindings) {
	log = this.log.child(customPropBindings)
	}

removed.

Would you like to send a PR?

[jose-sal-y-rosas]

@mcollina I don't see a way to build an artifact and test all changes in my local. No information in the README.md or ci.yml, please could you provide the steps to test in my local and see the expected result? I am following these steps (https://dev.to/scooperdev/use-npm-pack-to-test-your-packages-locally-486e) to link the dependency and test.

[mpartel]

Workaround: use a WeakSet to keep track of requests that have already been through customProps.

[mcollina]

@mcollina I don't see a way to build an artifact and test all changes in my local. No information in the README.md or ci.yml, please could you provide the steps to test in my local and see the expected result? I am following these steps (https://dev.to/scooperdev/use-npm-pack-to-test-your-packages-locally-486e) to link the dependency and test.

https://www.freecodecamp.org/news/how-to-make-your-first-pull-request-on-github-3/#:~:text=Go%20to%20your%20repository%20on,Congratulations!

To make the changes, run npm install to install the dependencies, and npm test to run the tests.

[jsumners]

https://jrfom.com/posts/2017/03/08/a-primer-on-contributing-to-projects-with-git/ if you need another resource.

[spence-s]

@mcollina if I remember correctly, you can't just remove one of the bindings - it causes a lot of other things to break and then you don't have the custom bindings in normal calls to res.log.method() or if you remove the other one, you lose the bindings in the auto logging.

@mpartel had an interesting idea of using a WeakSet to conditionally apply the custom bindings in both places, but ensure that they are only applied once per response cycle.

[mpartel]

To be clear, I'm just suggesting WeakSet as a temporary workaround for users. It doesn't sound like a clean solution for the library, and it might even have some performance implications (I don't know how it affects the GC).

[spence-s]

@mpartel thanks for clarifying. I'm not well versed in the application of WeakSet. Mind sharing how you implement the workaround to avoid the issue? It's not immediately obvious to me.

[mpartel]

This seems to work:

const requestsSeen = new WeakSet();
// ...
customProps: (req) => {
  if (requestsSeen.has(req)) {
    return undefined;
  }
  requestsSeen.add(req);
  
  return { stuff };
}

[mcollina]

We should really split customProps into two functions, not one.

[ilari-makimattila]

Hello, I just bumped into this and sadly don't have the time to do a PR but I have a case where the first call will happen with a Request object that has not yet fully gone through the pipeline. I wanted to log the matched expressjs route and the current user user id, and in order to do that I had to do something like:

customProps(req) {
    if (!req['SEEN-THIS-ONE']) {
       req['SEEN-THIS-ONE'] = true;
    } else if (req['SEEN-THIS-ONE']) {
       return {
           route: req.route.path,
           userId: req.user.id,
       };
    }
}

If I used the values from the first call they would always be route: "/* and userId: null. So whichever function onResFinished or loggingMiddlware is being called the first, is called too soon.

The stack I have is express, nestjs, nestjs-pino.

[aabhasr1]

is this issue fixed? If yes then in which version. I am trying to log 'x-request-id' in the outermost json and for response logging it is appending twice.

[mcollina]

This is not fixed and a PR would be greatly appreciated, I currently have no time to work on this and I'm not really using it anywhere.

[youngkiu]

I tried to resolve it at #288.

[cat-pierrecharles]

Hey everyone, I think this issue is still happening. I'm using customProps and like everyone else it is still duplicating the values. Could anything be done to fix this?

[youngkiu]

@cat-pierrecharles
I also wrote the unit test requested by the maintainer in my fix.
Please wait a moment for it to be merged into the master branch.

[cat-pierrecharles]

Awesome, thank you @youngkiu

[rickihastings]

Has the fix in the latest release resolved this problem for everyone? I am still seeing it on the latest version unfortunately.

[cat-pierrecharles]

Has the fix in the latest release resolved this problem for everyone? I am still seeing it on the latest version, unfortunately.

@youngkiu's fix in August solved it for me, I'm currently using 8.4.0 so not sure if the latest release have introduced that issue or not

[youngkiu]

@rickihastings @cat-pierrecharles

• https://github.com/youngkiu/nestjs-kakaologin/blob/main/src/app.module.ts#L24-L31

    HTTPLoggerModule.forRoot({
      pinoHttp: {
        customProps: (req, res) => ({
          context: 'HTTP',
        }),
      },
    }),
  

• https://github.com/youngkiu/nestjs-kakaologin/blob/main/package.json#L61
  "pino-http": "^8.4.0"

This is the log generated from my repository code

[Nest] 69441  - 09/19/2023, 11:06:01 PM     LOG [NestApplication] Nest application successfully started...
{"level":30,"time":1695132407596,"pid":69441,"hostname":"youngkiu-MacBookPro.local","req":{"id":1,"method":"GET","url":"/","query":{},"params":{"0":""},"headers":{"host":"localhost:3000","user-agent":"curl/7.78.0","accept":"*/*"},"remoteAddress":"::ffff:127.0.0.1","remotePort":61640},"context":"HTTP","res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"text/html; charset=utf-8","content-length":"5537","etag":"W/\"15a1-GwH5K5Ocq58NdT/1K7JSlOJlfds\""}},"responseTime":61,"msg":"request completed"}

[rickihastings]

It seems that I can't recreate this problem locally but it's an issue when deployed to GCP Cloud Run. I'll do some further investigation to see if I can replicate it outside of GCP.

[ninthsun91]

This issue hasn't been fixed in v8.5.0.

The workaround made by @ilari-makimattila looks good to me, and those who might be using in Typescript can try this.

import express from 'express';
import pino from 'pino-http';

const app = express();
const logger = pino({
  customProps: (req, res) => {
    if (req.isLogged) return {};

    req.isLogged = true;
    return  {
      auth: decodeToken(req.headers.authorization),
    }
  },
});

declare module 'http' {
  interface IncomingMessage {
    isLogged: boolean;
  }
}

• related, fix: twice customProps #288

[henripoikonen]

I stumbled into the same issue but the workaround proposed above didn't work for me since I want to log some custom context that is not yet available when the customProps function is first called.

This worked for me to log those props only when the request is finished by checking res.writableEnded property:

customProps: function (_req, res) {
  if (!res.writableEnded) {
    return {};
  }

  return {
    context: getRequestContext()
  };
},

[clintonb]

@henripoikonen's solution works for me.

Here is more background on why pino doesn't de-duplicate: pinojs/pino#625..

[someden]

According to this: pinojs/pino#625
and this: https://getpino.io/#/docs/child-loggers?id=duplicate-keys-caveat
duplication is normal and it is better for performance to revert fix #288

@mcollina what do you think?

[mcollina]

PRs are welcome.