Inconsistent behavior when log entry exceeds maximum log entry size

[mickdekkers]

When any log entry exceeds the maximum log entry size, no log entries appear in the log viewer for that function invocation. This can make the offending log entry difficult to track down, because the other log entries that would normally provide context are missing. Additionally, when a log entry exceeds the maximum log entry size, an error like this should be logged:

Error: 3 INVALID_ARGUMENT: Log entry with size 200.2K exceeds maximum size of 110.0K

But this does not always happen.

Environment details

• OS: N/A
• Node.js version: 8
• npm version: N/A
• @google-cloud/logging-winston version: 0.11.1
• winston version: 3.2.1

Steps to reproduce

1. Create a new Google Cloud Function and select the Node.js 8 runtime
2. Copy the following code into the index.js of the function:

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

const loggingWinston = new LoggingWinston();

const logger = winston.createLogger({
  level: 'debug',
  transports: [
    new winston.transports.Console(),
    // Add Stackdriver Logging
    loggingWinston,
  ]
});

const MAX_LOG_ENTRY_SIZE = 100 * 1024; // 100 KB

/**
 * Responds to any HTTP request.
 *
 * @param {!express:Request} req HTTP request context.
 * @param {!express:Response} res HTTP response context.
 */
exports.helloWorld = (req, res) => {
  let message = req.query.message || req.body.message || 'Hello World!';
  res.status(200).send(message);
  
  // Log some entries
  logger.error('warp nacelles offline');
  logger.info('shields at 90%');
  logger.info('shields at 80%');
  logger.info('shields at 70%');
  
  // Log an entry that exceeds the Stackdriver log entry size limit
  const hugeMessage = 'a'.repeat(Math.round(MAX_LOG_ENTRY_SIZE * 2.0));
  logger.debug(hugeMessage);

  // Log an entry through STDOUT (part of this example, but not required to trigger the issue)
  console.log('STDOUT log');

  // Log some more entries
  logger.info('shields at 60%');
  logger.info('shields at 50%');
  logger.info('shields at 40%');
};

3. Add dependencies to package.json:

{
  "name": "sample-http",
  "version": "0.0.1",
  "dependencies": {
    "winston": "3.2.1",
    "@google-cloud/logging-winston": "0.11.1"
  }
}

4. Trigger the cloud function through an HTTP GET request
5. View the logs

Expected result

All winston log entries appear in the log viewer, except for an error in place of the log entry that exceeds the maximum log entry size. The console.log entry always appears.

Actual result

No winston log entries appear in the log viewer. The console.log entry always appears. An error is sometimes logged in place of the log entry that exceeds the maximum log entry size, but not consistently (that is, I have not been able to get it to appear consistenly, but if you trigger the function enough times it should appear eventually.)

Additional information

Potentially related to #190

[DominicKramer]

This looks like a duplicate of @google-cloud/logging issue #427.

The following code shows a similar problem directly using the logging library:

// Imports the Google Cloud client library
const {Logging} = require('@google-cloud/logging');

// Your Google Cloud Platform project ID
const projectId = 'dk-nodejs';

// Creates a client
const logging = new Logging({
  projectId: projectId,
});

async function log(text) {
  // The name of the log to write to
  const logName = 'my-log';
  // Selects the log to write to
  const log = logging.log(logName);

  // The metadata associated with the entry
  const metadata = {resource: {type: 'global'}};
  // Prepares a log entry
  const entry = log.entry(metadata, 'PLAIN LOGGING: ' + text);

  // Writes the log entry
  await log.info(entry);
  console.log(`1:  Logged: ${text}`);
}

async function main() {
  const MAX_LOG_ENTRY_SIZE = 100 * 1024; // 100 KB

  const hugeText =  'a'.repeat(Math.round(MAX_LOG_ENTRY_SIZE * 2.0));

  log('message 1 before huge text');
  log('message 2 before huge text');
  log(hugeText);
  log('message 1 after huge text');
  log('message 2 after huge text');
}

main().catch(console.error);

Logging a huge message throws an error and causes the app to crash. I suspect what is happening is that because logging winston is not waiting for a log to complete before proceeding to the next line of code, when the app crashes, any pending promises for writing logs do not resolve.

Depending on whether those promises have or have not resolved when the app crashed will give variable results of whether or not some of the log messages appear in the Log Viewer.

@JustinBeckwith I think this should be moved to the @google-cloud/logging repo, marked as a duplicate of @google-cloud/logging issue #427, and closed. However, I don't have permission to do the move. Can you help me out? Thanks

[bcoe]

closing as duplicate 👍 @mickdekkers thanks for the report.

[bcoe]

duplicate of #427