Pino: logging large JSON content causes cutting off the log payload

[nodify-at]

We log request and response bodies in our development stages for debugging purposes. If content of a log message/payload is bigger then 64 KB, we don't get entire message/payload. Somehow either node.js via stdout or pino somewhere cuts off this payload.

Reproducable script:

const P = require("pino");
const fs = require("fs");
const content = fs.readFileSync('./data.txt').toString('utf-8');
const logger = P({ level: 'debug' });
logger.debug(content);

Please download JSON file below (generated using an online tool):
data.txt

We use latest Version of Pino.

[mcollina]

Which operating system are you experiencing this with?

[davidmarkclements]

I can confirm this is working fine on MacOS:

[nodify-at]

centos.x86_64 in our servers.
I've also tried in Windows 10. same issue.

[nodify-at]

@davidmarkclements If I pipe to file using '>' it works for me too. But if I try to log directly to console, it is getting cut off.

[davidmarkclements]

For me it doesn't:

but that sounds like a terminal issue - can you try

const fs = require("fs");
process.stdout.write(fs.readFileSync('./data.txt').toString('utf-8'));

[mcollina]

I cannot reproduce even in console on a Linux system.

[davidmarkclements]

What terminal are you using? Are you doing this over SSH? Are there any details that are missing here?

[nodify-at]

Ok, it works if I use Powershell in Windows. There might be a limitation in windows - CMD.
But I don't know why are our logs getting cut off in dev-servers, We use ELK stack and and we create a logger similar as above.

May be I need to focus on ELK stack or operating system related limitations (in our case cent OS)

[davidmarkclements]

yeah I think so - closing as this isn't an issue with pino, good luck!

[mcollina]

Can you produce a repro? How are you sending your logs to ELK?

[nodify-at]

@mcollina I can't reproduce it in my local environment. I'm trying to analyse ELK Stack, if I find something, I will let you know

[nodify-at]

@mcollina We can reproduce this issue only in docker, docker tries to split the log entries. After some tries we can see that some of log entries are mixed. Not sure yet if it is in pino, sonic boom, node.js or a docker issue :)
Did you experience such an issue before?

p.s: This condition happens if we have log payload > 16KB or much more..

[davidmarkclements]

interesting - can you simulate the same payload sizes in the containers with process.stdout.write to produce the same scenario?

It might be an issue between node core and Docker, when doing fs.write to a std handle, e.g. https://github.com/mcollina/sonic-boom/blob/master/index.js#L78

I don't believe we've had this come up before

[nodify-at]

@davidmarkclements Thanks for your response. But we don't use extreme mode and if sync is true, sonic boom calls writeSync and comment of the author in this code:

This error code should not happen in sync mode, because it is not using the underlining operating system asynchronous functions.

We don't have such an issue in our Java components and it appears only in node.js components. We believe there must be some leak/error in somewhere while logging. Is it possible to replace sonic boom in Pino so we can try different possibilities like console.log?

[mcollina]

Have you got a way to reproduce? I'd like to fix it in sonic-boom if possible. In theory, this is handled.

I'll work on a quick fix to bypass this tomorrow.

[mcollina]

If you are able to run a patched version of sonic-boom, would you mind to try changing https://github.com/mcollina/sonic-boom/blob/c241e88997597cf2bba08265e9b4404293f38830/index.js#L13 to 64KB?

[nodify-at]

@mcollina We can reproduce this issue if we run node.js component in docker. In local environments we can not reproduce it.
I will clone and modify sonic boom to log more details in our dev. stage to see what happens exactly. I will also reduce the size to 64 KB but it won't help too much because you defined 16MB and I tried with a payload size ~2 MB

[mcollina]

I will clone and modify sonic boom to log more details in our dev. stage to see what happens exactly. I will also reduce the size to 64 KB but it won't help too much because you defined 16MB and I tried with a payload size ~2 MB

It _should_ help because it will chunk the size of the max payload to 64KB.

[nodify-at]

@mcollina Thanks, I will try to reduce it before using console.log :) I will let you know.

[nodify-at]

I cloned the Pino repository. I did the following changes:

• Changed Chunk Size to 64 KB , didn't help, we still get the logs not in order as we expect, causes corrupted/cut off payload
• Changed Chunk Size to 2MB , didn't help, we get the logs not in order as we expect, causes corrupted/cut off payload
• Replaced sonic boom write call with console.log in pino, it helped us so the error did not appear any more

I can't reproduce this on my local environment so it is hard to tell the cause of this error.

[mcollina]

That is helpful. I'll take a look asap.

[mcollina]

I can't reproduce this on my local environment so it is hard to tell the cause of this error.

Would you be able to produce a dockerfile that reproduce the problem?

[nodify-at]

I'm trying to reproduce via a simple docker file. But I see that there is a PR in sonic-boom. #32
I will take this change to retest in our environment.

[mcollina]

Can you also try https://github.com/mcollina/sonic-boom/tree/protect-against-sync and see if it crashes the process?

[mcollina]

@nodify-at how do you see that the logs are scrambled? Do you see it inside a terminal (docker logs) or in some other tools?

What I have seen is that if I convert your JSON file into unix end line, the terminal visualize it correctly. This looks a lot like a terminal issue and not a real bug.

[mcollina]

On further check, pino is handling the escaping of \r correctly, so that's been a false errand (see https://github.com/pinojs/pino/blob/master/lib/tools.js#L43-L71).

We cannot be of any more help without a way to reliably reproduce the problem.

[nodify-at]

I created a repository with reproducable code. Please checkout this: https://github.com/nodify-at/nestjs-pino-large-json and run in a Docker Container.

Important: Configure docker daemon to use json-logger:

  "log-driver": "json-file",
  "log-opts": {
    "max-size": "10m",
    "max-file": "3",
    "labels": "production_status",
    "env": "os,customer"
  }

Steps:

docker build -t nodify/pino .
docker run -p 3000:3000 -d nodify/pino

Send a request to http://localhost:3000 using payload provided in attachment.

After you get an error from server, check the logs:

docker logs #container_id > server.log

You will see that the logs are mixed. (Search "invalid request" one of this log is somewhere between large json payload, which causes to corrupted json logs.

payload.txt

[nodify-at]

See my screenshot, In logs, Log Paylod cut off and other log has been started and then payload continues to log.

[mcollina]

Can you confirm this only happens with those json-file settings?

After reading https://github.com/moby/moby/issues/36777, it seems that json-file has an internal buffer of 16KB, and for some obscure reasons it does not notify the caller that not all bytes have been written. Note that it seems not really capable of handling messages over 16KB, so the problem might be there instead.

My bet is that console.log is working on because it puts your messages on multiple lines.

Given it has a 16KB buffer, could you try modifying the chunking size to 16 or 8 KB?

(We’ll try your example asap).

[nodify-at]

@mcollina I tried 'local' as log configuration, same issue. It didn't help to reduce buffer size. If I set log configuration to local and put an extra \n in actualWrite, it seems good.
But if I set to json-file and put extra \n, it didn't work. Strange.

[nodify-at]

@mcollina I tried your branch: https://github.com/mcollina/sonic-boom/tree/protect-against-sync and I see that the application crashes because it lands to EAGAIN error. In master Branch you have setTimeout in this case and it casuses to write the part of log async so this log-message is then broken.

[mcollina]

That's really helpful. According to all possible docs, that error code _should not happen_. That's what is causing the logs to be scrambled.

You might want to try pino.extreme(). That handles that case properly.

[mcollina]

I've pushed a fix to that branch. In theory it should work as expected. Let us know.

[nodify-at]

@mcollina Thanks for your fix but the entire log disappears after using your changes. I'm trying to find out why they disappear and let you know

[mcollina]

@nodify-at did you test with the latest commit? The previous one had a few bugs.

[mcollina]

Thanks for your fix but the entire log disappears after using your changes. I'm trying to find out why they disappear and let you know

Fixes to that code are highly welcome. The logic should be roughly there.

[nodify-at]

Sure, I can reproduce this issue easily using docker and verify if I find a fix. I will inform you after finding a possible solution for it.

[nodify-at]

@mcollina I can verify that your change works with an improvement which forces to write again after sleep.

[mcollina]

I can verify that your change works with an improvement which forces to write again after sleep.

Can you include a diff? That should already be the case because the call to this.release() should effectively cause a write again.

[nodify-at]

In sonic-boom.js I've only two changes. Is it enough for you? Otherwise I can fork sonic-boom and create a diff using git.

[jsumners]

Are you using Node 6? That is very unsupported at this point.

[mcollina]

It should not use _buf because that's not what it is currently being written, _writingBuf is.

The node 6 part there does not really work because the require statement does not throw an error.

If you'd like to open a PR against my PR in sonic-boom, we can iron out the changes.

[nodify-at]

@mcollina thanks. I copied this condition from one of your commit I think but you have fixed it anyway :)
I will check your recent changes and if necessary I can create a new PR

[nodify-at]

@mcollina Your recent changes on https://github.com/mcollina/sonic-boom/tree/protect-against-sync works great. I see in Docker -> ELK Stack, that all entries (>150 requests with large JSON files) have been saved successfully.

[nodify-at]

@mcollina when can we expect a new version? Many thanks for your support! :)

[mcollina]

@nodify-at as soon as you confirm that the branch is working as expected. There is still an outstanding comment about _buf.

[nodify-at]

It should not use _buf because that's not what it is currently being written, _writingBuf is.
The node 6 part there does not really work because the require statement does not throw an error.
If you'd like to open a PR against my PR in sonic-boom, we can iron out the changes.

It was my mistake to use _buf. You don't need to wait for my PR because your PR looks good and I can verify that it works as expected. I tried with over 150 Entries with very large JSON payloads and ELK Stack can parse them as expected. Your solution with sleep looks fine !

[mcollina]

Fixed in [email protected]. Update your dependencies.

[nodify-at]

@mcollina Can we get an update on pino too?

[mcollina]

It's not needed, just update your dependencies.

[davidmarkclements]

@nodify-at don't forget package-lock can lock in your deps.