NodeJS 10: Async bunyan logging crashes the cloud function if await is not used while logging

[Laksh47]

Issue:

• nodeJS 10 Cloud function runs but results in a crash while using bunyan logs and publishing to another topic!

Environment details

• OS: Google cloud function
• Node.js version: v10.14.2
• npm version: 6.4.1
• @google-cloud/logging-bunyan version: 2.0.0

Steps to reproduce

1. Create a cloud function using nodeJS 10 runtime with pubsub as trigger
2. use bunyan logging and redirect logs to cloud functions.
3. Try and publish to a sample topic and use bunyan logs right after publish

Error reported:

Ignoring extra callback call

Function execution took 1852 ms, finished with status: 'crash'

{
 insertId: "000000-811aac99-2369-4f5b-801f-19364c10437c"  
 labels: {…}  
 logName: "projects/some-project/logs/cloudfunctions.googleapis.com%2Fcloud-functions"  
 receiveTimestamp: "2019-12-03T18:22:41.491846254Z"  
 resource: {
  labels: {
   function_name: "test-logger-lib-publish-duplicate"    
   project_id: "some-project"    
   region: "us-central1"    
  }
  type: "cloud_function"   
 }
 severity: "ERROR"  
 textPayload: "Error: Could not load the default credentials. Browse to https://cloud.google.com/docs/authentication/getting-started for more information.
    at GoogleAuth.getApplicationDefaultAsync (/srv/functions/node_modules/google-auth-library/build/src/auth/googleauth.js:161:19)
    at process._tickCallback (internal/process/next_tick.js:68:7)"  
 timestamp: "2019-12-03T18:22:40.664Z"  
 trace: "projects/some-project/traces/ce459298d8da7569d7fb40b07785d594"  
}

Sample Code:
index.js

const bunyan = require('bunyan');
const { LoggingBunyan } = require('@google-cloud/logging-bunyan');

const loggingBunyan = new LoggingBunyan({
  logName: process.env.LOG_NAME
});

function getLogger(logginglevel) {
  let logger = bunyan.createLogger({
    name: process.env.FUNCTION_TARGET,
    level: logginglevel,

    streams: [
      loggingBunyan.stream()
    ]
  });
  logger.debug(`${process.env.FUNCTION_TARGET} :: ${process.env.LOG_NAME}`);
  return logger;
}

const pubsub = new PubSub({
  projectId: 'some-project'
});


exports.helloPubSub = async(event, context) => {
  console.log('I am in!');
  const logger = getLogger('debug');

  const test_topic = pubsub.topic('logger-topic');
  logger.debug('debug level test');

  const data = Buffer.from('interesting', 'utf8');
  await test_topic.publish(data);
  logger.error('error level test');
  logger.info('I am out');
};

package.json

  "name": "sample-pubsub",
  "version": "0.0.1",
  "dependencies": {
    "@google-cloud/pubsub": "^1.0.0",
    "bunyan": "^1.8.12",
    "@google-cloud/logging-bunyan": "^2.0.0"
  }
}

Note:

• The same code works fine for nodejs 8 runtime! This issue is only with nodejs 10 runtime.
• In the above index.js file, if I use await on the last logger.info('I am out') or all the logger calls, the function works like a charm!

Could anyone help me with what's wrong here?

Reference issues:

• Async logging nodeJS 10
• Redirect logs explicitly to cloud functions nodeJS 10

[soldair]

in a sense this is by design. You must await the calls to log if expect them to finish running.
If you don't await the call to log the log message will likely not be sent to the logging api before the function terminates. Resulting in a completely lost log message.

The question here is if we should fail silently. or fail loudly with a better error message.
I haven't traced the code to determine why it fails to find the application default credential during function shutdown but this is probably a race 🏎️ i can imagine this error varies based on which async call its handling when things start to shutdown.

[soldair]

changing to p2 because there is a workaround.

[anandnimkar]

I don't understand the workaround. logger.info, logger.error, and logger.debug do not return Promises. Why would awaiting them work?

[soldair]

the logging instance is a nodejs writable stream. Because bunyan doesn't provide a way to end all attached streams in its exposed logger api you'll have to wrap end/finished on the logging-bunyan writable stream itself to await it.
something like.

end = ()=>{
  if(loggingBunyanStream.writableFinished) return;
  return new Promise((res,rej)=>{
    loggingBunyanStream.once('finished',res)
    loggingBunyan.end();
  })
}

then when you're done with the function await end();

[rymnc]

The event emitted on closure is now 'finish', just discovered this by going through issues on Google's winston logging repo.