nodejs-logging-winston: Using LoggingWinston object with no project id causes nodejs to crash in node >16

Is this a client library issue or a product issue? I’m not sure, but this might be an issue with https://github.com/googleapis/nodejs-common. I encountered it using this package.
Did someone already solve this? no
Do you have a support contract? no

Environment details

OS: tested on macos big sur (intel) and nodejs-16-alpine docker container on google cloud run
Node.js version: 16 and above
npm version: 7.21.0
@google-cloud/logging-winston version: 4.1.0

Steps to reproduce

Run the following sample

const express = require('express')
const winston = require('winston');
const {LoggingWinston} = require('@google-cloud/logging-winston');
const app = express()
const port = 3000

const loggingWinston = new LoggingWinston();
const logger = winston.createLogger({
  level: 'info',
  transports: [
    new winston.transports.Console(),
    loggingWinston,
  ],
});


app.get('/', (req, res) => {
  logger.info('get');
  res.send('Hello World!')
})

app.listen(port, () => {
  console.log(`Example app listening at http://localhost:${port}`)
})

make a GET request
after a short delay the app will crash

/Users/eamonnmcevoy/gcloud-try-catch/node_modules/google-auth-library/build/src/auth/googleauth.js:95
                        throw new Error('Unable to detect a Project Id in the current environment. \n' +
                              ^

Error: Unable to detect a Project Id in the current environment. 
To learn more about authentication and Google APIs, visit: 
https://cloud.google.com/docs/authentication/getting-started
    at /Users/eamonnmcevoy//gcloud-try-catch/node_modules/google-auth-library/build/src/auth/googleauth.js:95:31
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
Emitted 'error' event on DerivedLogger instance at:
    at DerivedLogger.transportEvent (/Users/eamonnmcevoy//gcloud-try-catch/node_modules/winston/lib/winston/logger.js:630:12)
    at LoggingWinston.emit (node:events:406:35)
    at onwriteError (/Users/eamonnmcevoy//gcloud-try-catch/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:449:12)
    at onwrite (/Users/eamonnmcevoy//gcloud-try-catch/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:470:11)
    at WritableState.onwrite (/Users/eamonnmcevoy//gcloud-try-catch/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:180:5)
    at /Users/eamonnmcevoy//gcloud-try-catch/node_modules/@google-cloud/promisify/build/src/index.js:114:21
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

This error cannot be caught and always crashes the app.

On node 14 (i tested 14.15.4 specifically), it behaves differently. The same error is thrown but the app will not crash.

If I include this transport do I need to be authenticated to gcloud when running locally? It should work (or at least be silent) when running locally without authentication.

About this issue

Original URL
State: closed
Created 3 years ago
Comments: 19

Most upvoted comments

Thank you for opening the issue

eamonnmcevoy on Sep 16, 2021

the tests show the designed behavior and no sign for a problem with authentication flow.

minherz on Sep 13, 2021

@eamonnmcevoy thank you for putting your time to provide this information. there are few discrepancies in the provided info:

the Dockerfile does not copy application itself
the source file differs from one you provided in the issue description

before to continue, i would like to confirm that the reported issue is that the application that you provided crash when sending it GET / request in the local environment.

after testing your report, i can confirm that if you use a code with INVALID project id the application crashes in the local environment (i did not test its behavior in Cloud Run). however, if you run this code without initializing project id (neither in the environment nor in the LoggingWinston constructor) the application operates as expected.

i’d like to address your claim about authentication failure as well. the authentication takes place at creation of the logger and not when the code calls it to write a log entry. the fact that you see google-auth-library in the callstack means only that a code from the google-auth-library module is called and not that the authentication process fails.

summarizing the above, the module works as expected. please, do not define invalid project id to avoid receiving an error.

the test that failed was launched using the code you provided in the previous comment. the test that worked used the code in the issue description.

i had to modify Dockerfile in order to have the running container:

FROM node:16.4
WORKDIR /app
COPY package.json package-lock.json index.js /app/
CMD npm install && node index.js
EXPOSE 3000

I ran docker using the following command to reproduce the error:

docker run -d \
--it \
--name test-623 \
--mount type=bind,source="/home/user/test_sa.key",target="/etc/test_sa.key"
--env GOOGLE_APPLICATION_CREDENTIALS="/etc/test_sa.key" \
gcr.io/minherz/test-623:invalid-project-id

and the similar command with the image gcr.io/minherz/test-623:no-project-id to have it working.

minherz on Sep 13, 2021

I’m surprised that the issue has been closed, please consider reopening.

Perhaps I haven’t been clear on what the issue is. There are various conditions during authentication that trigger an internal error in the package. These errors force the host application to crash. If the logger must throw an error, I should be able to catch that error and handle gracefully in my application.

Is this an unreasonable expectation?

Could you comment on my suggestion here: https://github.com/googleapis/nodejs-logging-winston/issues/623#issuecomment-915863719

I don’t know how much more detail or examples I can provide. Please let me know if you need anything further.

To address your specific points:

“the Dockerfile does not copy application itself”

It isn’t required, if you look at the attached docker compose file the source folder is mounted into the container. You can use the commands docker-compose build and docker-compose up to run it.

Copying the files in is also fine if you are unfamiliar with this method.

the source file differs from one you provided in the issue description

Yes, I added projectId and some additional logs to print events emitted from the logger. This is a minor change and demonstrates the same issues.

if you run this code without initializing project id (neither in the environment nor in the LoggingWinston constructor) the application operates as expected.

Is the application expected to crash?

You can see from my multiple descriptions, screen recording, and the attached output samples that this is not the case. The application crashes if projectId is missing or invalid.

if you use a code with INVALID project id the application crashes… the module works as expected.

This is obviously not reasonable behaviour from an npm package. A logging package should not crash the host application under any circumstances.

i’d like to address your claim about authentication failure as well. the authentication takes place at creation of the logger and not when the code calls it to write a log entry. the fact that you see google-auth-library in the callstack means only that a code from the google-auth-library module is called and not that the authentication process fails.

It is not really my business to know the details of the authentication stack, I am trying to make a bug report about the logging package crashing the host application.

If you tested the example, you will see from the example that the crash occurs asynchronously after the line logger.info('get'); is executed.

please, do not define invalid project id to avoid receiving an error.

We cannot tell if the projectId is valid before running the app, if it is invalid the app will crash. There is no way to handle the error. This is not acceptable behaviour from a logging package (or any package for that matter).

the tests show the designed behavior and no sign for a problem with authentication flow.

Clearly there is a problem. You even acknowledged that if the projectId is invalid the package will crash the host app, is this the designed behaviour?

It doesn’t seem reasonable to me that the package cannot handle an ‘unhappy’ flow. As you are no doubt aware, it should not be assumed the happy path will always occur.

Here is another error flow I didn’t include in the previous post. If the SA does not have the necessary permission to log to the given project, it crashes.

eamonnmcevoy on Sep 13, 2021

The libraries are intended to write logs into Google Cloud Logging service. Google client libraries do not support “local” mode of work. If your application should support “local” and “connected” modes of work, use a mock or configure your logging setup in a way it prints logs to STDOUT instead of using @google-cloud/logging-winston.

minherz on Sep 8, 2021

We already know how to authenticate locally. Indeed I can authenticate with the service account and provide a valid projectId and everything will work. My issue is that the npm package should not cause node to crash because it can’t authenticate to google cloud.

I also don’t want to see developers logs in google cloud if they are developing locally, so I should be able to leave projectId blank and still run my app.

Thanks for your help so far!

Should I move the issue to https://github.com/googleapis/nodejs-common ? I suspect this is where the problem really is.

eamonnmcevoy on Sep 8, 2021