Strange format being logged for request body

[lmossman]

We have set up express-winston on our API to log various pieces of the request and the response. The logs look fine for everything except the request body, which has a strange format when logged where each character of the request body is being mapped to its index of the string, and that entire map is being logged.

For example, the request curl -H "Content-Type: application/json" --request POST --data '{"ids":[1234, 5678],"action":"START"}' 'http://localhost:31701/distribute?name=bob&age=25 results in the following log:

{"meta":{"req":{"context":{"uid":"qwertyuiop","orgId":"MNBVCXZ"},"params":{},"query":{"name":"bob","age":"25"},
"body":{"0":"{","1":"\"","2":"i","3":"d","4":"s","5":"\"","6":":","7":"[","8":"1","9":"2","10":"3","11":"4",
"12":",","13":"","14":"5","15":"6","16":"7","17":"8","18":"]","19":",","20":"\"","21":"a","22":"c","23":"t",
"24":"i","25":"o","26":"n","27":"\"","28":":","29":"\"","30":"S","31":"T","32":"A","33":"R","34":"T","35":"\"",
"36":"}"}},"res":{"statusCode":200,...}}

As you can see, other fields of the request are logged normally. The only thing with the weirdly formatted log is the request body.

Does anyone know how to fix this issue so that the body is logged as a single normal string?

Here is my express-winston logger configuration:

const logger = winston.createLogger({
  transports: [new winston.transports.Console()],
  format: winston.format.combine(
    winston.format.timestamp(),
    winston.format.json()
  ),
  silent: fetchEnv("NODE_ENV") == "test" ? true : false,
});

and here is where I it is being used in a router:

this.router.use(
  expressWinston.logger({
    meta: true,
    winstonInstance: logger,
    requestWhitelist: ["context.uid", "context.orgId", "params", "query", "body"],
    responseWhitelist: ['statusCode','body'],
    expressFormat: false,
  })
);

[yinzara]

That would probably happen if the body is a Buffer and not a JSON object which would happen if you're not using the JSON parser in express.

What's your express initialization code? are you calling app.use(express.json()) ?

Also, is the "Content-Type" on your request set correctly to "application/json"?

[lmossman]

@yinzara We are currently using the following to initialize our express app: app.use(bodyParser.text({ type: "*/*" })); from the body-parser express middleware

We are not calling app.use(express.json()) anywhere. I tried replacing the above line with app.use(express.json()), but it caused the api to be unable to parse the request body (ended up with [object Object] instead).

And yes, the content-type is being set to application/json in the request

[yinzara]

Yeah that's what it's supposed to be. Why are you manually parsing the request body? That's what the body-parser is for.

[lmossman]

The [object Object] thing I mentioned was from a piece of our code that validates specific values in the request body. It first checks that the body is valid json before trying to parse it out to look at inner values, which is where it printed that out. I think that's what you mean by manual parsing.

I tried having both

app.use(bodyParser.text({ type: "*/*" }));
app.use(express.json())

in my express initialization and express-winston still printed out the body with the weird format

[yinzara]

yeah by using the text body parser before the JSON one, you've really done nothing as it will decode the body using the text parser and never get to the JSON one.

in general you shouldn't be writing your own body parsing. Just use the built in body parsing from express. If you're a JSON web service, just use the app.use(express.json) and skip the text parser or at least make it 2nd for things that aren't JSON.

[lmossman]

Ah that makes sense. I just swapped the order of those parsers and removed the part where we were doing JSON.parse() on the request body and instead just accessed the fields directly, and everything is working now with the request body being logged in the correct format. Thank you for your help!