(Just for documentary reasons): Using cloud-pine in a Google Cloud Run service while logging extensively is not a good idea

[mindactuate]

Describe the bug

Hi. I used cloud-pine in 2 Google Cloud Run services (because I didn't know better back that day). I did some "heavy logging" for debugging reasons in my QA-environment and everytime at a certain (logging-heavy) function, my service crashed. Even 8 CPUs and 32 GB RAM wasn't enough. Then I turned cloud-pine off (Google Cloud Run works pretty fine without cloud-pine because it streams stdout and stderr to Google Cloud Logging anyway) and everything works like a charm (1 CPU, not more than 150 MB RAM).

I don't know much about the nitty gritty of cloud-pine. Perhaps its not because of your code but more because of the resource-intense API calls that are made to send the logs to Google Cloud Logging?

This issue is just for documentary reasons. I don't need this solved. Perhaps it helps you. I just wanted to share this story with you. I think you should know about it.

To Reproduce

Steps to reproduce the behavior:

1. Start a new node js project
2. Configure pino logger with cloud-pine as target
3. Do some really heavy logging
4. Deploy to GCR
5. Monitor the load
6. Turn cloud-pine off
7. Deploy again
8. Monitor the load
9. Compare

Here my logger config WITH cloud-pine activated. Perhaps I did something wrong?

import pino from 'pino';
import dotenv from 'dotenv';

dotenv.config(); // I have to init dotenv here as it isn't initialized yet

function getTransport() {
  if ('LOCAL_LOGGER' in process.env) {
    return {};
  }
  return {
    transport: {
      target: 'cloud-pine',
    },
  };
}

const logger = pino({
  ...getTransport(),
  timestamp: pino.stdTimeFunctions.isoTime,
  redact: {
    paths: ['email', 'password', 'token'],
  },
});

export default logger;

Here my logger config without cloud-pine:

import pino from 'pino';
import dotenv from 'dotenv';

dotenv.config(); // I have to init dotenv here as it isn't initialized yet

const logger = pino({
  timestamp: pino.stdTimeFunctions.isoTime,
  redact: {
    paths: ['email', 'password', 'token'],
  },
});

export default logger;

Environment

• Google Cloud Run, 1 CPU, 512 MB (but also tried with 8 CPU and 32 GB RAM)
• Docker Image: node:18-alpine (but also tried node:18)

[metcoder95]

Hey! Thanks for the report! 👋
This indeed is interesting, but somehow expected. It seems you were using cloud-pine in the async mode, which as you mention triggers calls to Google Cloud Logging; that given your workload and the fact you are running your code within Cloud Run is not strictly necessary (I would even say unnecessary at all).

Did you try using the sync mode?
See: https://cloud.google.com/nodejs/docs/reference/logging/latest#writing-to-stdout

You can enable it by just passing sync: true when adding the transport to pino.

I would really like to know your experience after that, and document it; it will be really valuable for the library. Would you like to open a PR to document that?

[mindactuate]

Hi! Thank you for your quick response. Glad that I could help somehow. :)

I tested it with sync mode and it worked pretty well. The RAM usage is with approx. 180 MB just slightly higher compared to normal stdout (155 MB) in GCR.

Oh man... I wasted so much time in investigating. Almost lost the faith in myself. 🥲

Regarding the docs PR: I really didn't contribute much. I think you can sort these discoveries into the documentation better than I could.

Thank you! :)

Here my settings:

import pino from 'pino';
import dotenv from 'dotenv';

dotenv.config(); // I have to init dotenv here as it isn't initialized yet

function getTransport() {
  if ('LOCAL_LOGGER' in process.env) {
    return {};
  }
  return {
    transport: {
      target: 'cloud-pine',
      options: {
        cloudLoggingOptions: {
          sync: true,
        },
      },
    },
  };
}

const logger = pino({
  ...getTransport(),
  timestamp: pino.stdTimeFunctions.isoTime,
  redact: {
    paths: ['email', 'password', 'token'],
  },
});

export default logger;

[metcoder95]

I tested it with sync mode and it worked pretty well. The RAM usage is with approx. 180 MB just slightly higher compared to normal stdout (155 MB) in GCR.

Nice! Yeah, it is somehow expected, given that pino forwards the logs to cloud-pine and the latter has to deserialize and parse into GCP format once more

Oh man... I wasted so much time in investigating. Almost lost the faith in myself. 🥲

haha, hey you brought something that will be useful which is highlighting why not use the sync: false mode when running on a GCP runtime.

Regarding the docs PR: I really didn't contribute much. I think you can sort these discoveries into the documentation better than I could.

Thanks! But I'd say that those system performance issues you faced are worth highlighting, as it can help to have them within the documentation so users have a better understanding of what happens under the hood and why you might want to avoid it 👍

Thanks for all the discoveries and feedback!