Winston Logging Transports crashing

[noelbranz]

Environment details

• OS: Google App-Engine
• Node.js version: 8
• npm version: 6.7.0
• @google-cloud/logging version: 4.2.0

Steps to reproduce

1. ?
2. ?

<rejected> TypeError: Cannot read property 'length' of undefined
at BundleExecutor.schedule (/app/node_modules/@google-cloud/logging/node_modules/google-gax/build/src/bundling.js:319:43)
at status.call (/app/node_modules/@google-cloud/logging/node_modules/google-gax/build/src/bundling.js:443:30)
at Canceller.call (/app/node_modules/@google-cloud/logging/node_modules/google-gax/build/src/api_callable.js:78:27)
at Bundleable.call (/app/node_modules/@google-cloud/logging/node_modules/google-gax/build/src/bundling.js:442:20)
at funcWithAuth.then.then.apiCall (/app/node_modules/@google-cloud/logging/node_modules/google-gax/build/src/api_callable.js:312:23)
at <anonymous> at process._tickCallback (internal/process/next_tick.js:189:7)

[JustinBeckwith]

Greetings! Can you share the code you're using to get this callstack?

[noelbranz]

const { loggers, format } = require('winston');
const { LoggingWinston } = require('@google-cloud/logging-winston');
const {
  combine, label, printf, splat,
} = format;
const logFormat = printf(info => `[${info.label}] ${info.level.toUpperCase()}: ${info.message}`);
const loggingWinston = new LoggingWinston({
  serviceContext: {
    service: 'api',
    version: pjson.version,
  },
  logName: `logfile-v${pjson.version}.log`,
});
 loggers.add('api', {
    level: 'debug',
    format: combine(label({ label: 'api'}), splat(), logFormat),
    transports: [loggingWinston],
    exitOnError: false,
    silent: false,
  });

This is how I initialize the logger, the error just intermittently goes out, cannot locate which actual code.
The error trace was taken from exception trace in stackdriver logs

When the error comes out, the LoggingWinston transport is not useful anymore, Winston logger still runs but cannot properly log into Stackdriver

[JustinBeckwith]

@alexander-fenster uh... do you recognize anything in this call stack?

[alexander-fenster]

Somewhere in bundling.ts - I will take a deeper look today. Haven't seen this before.

[alexander-fenster]

This is where we create Bundleable instance:

nodejs-logging/src/v2/logging_service_v2_client.js

Lines 142 to 151 in 05edc86

	this._descriptors.batching = {
	writeLogEntries: new gax.BundleDescriptor(
	'entries',
	['logName', 'resource', 'labels'],
	null,
	gax.createByteLengthFunction(
	protoFilesRoot.lookup('google.logging.v2.LogEntry')
	)
	),
	};

Here bundledField is entries.

The call starts here:

and the sequence of nested calls eventually comes to BundleExecutor.schedule where it finds that request["entries"] is undefined:

(and we fail trying to get .length of undefined)

Now the fun part is that the Logging library does great job making sure that entries property is always defined. By looking at its code:

nodejs-logging/src/log.ts

Lines 783 to 807 in 6cf18aa

	function writeWithResource(resource: {}|null) {
	let decoratedEntries;
	try {
	decoratedEntries = self.decorateEntries_(arrify(entry));
	} catch (err) {
	// Ignore errors (the API will speak up if it has an issue).
	}
	const reqOpts = extend(
	{
	logName: self.formattedName_,
	entries: decoratedEntries,
	resource,
	},
	options);
	delete reqOpts.gaxOptions;
	self.logging.request(
	{
	client: 'LoggingServiceV2Client',
	method: 'writeLogEntries',
	reqOpts,
	gaxOpts: options.gaxOptions,
	},
	callback);
	}
	}

I can see the only way of having it undefined: it will happen if decorateEntries_ throws an exception, which will leave decoratedEntries undefined, and reqOpts.entries will become undefined as well.

Long story short... googleapis/gax-nodejs#424 to make GAX not fail in this case, and in scope of this issue, we must make sure that undefined is never passed to logging API.

[stephenplusplus]

I can see the only way of having it undefined: it will happen if decorateEntries_ throws an exception, which will leave decoratedEntries undefined, and reqOpts.entries will become undefined as well.

It kind of seems like we shouldn't let that be undefined. It actually doesn't seem like we should send the request, and we would want to give the error to the user. I think I did this error ignore because we were just doing our best to get additional information we could send with the request, but it wasn't something the user required us to do. So if it fails, it's not a big deal. But the kind of error that would be thrown in the snippet you shared is when a JSON object cannot be serialized because of circular references. The user would probably want to know that, but maybe my memory is failing me on how this all works.

[alexander-fenster]

@stephenplusplus I'm not sure what is our policy re: throwing exceptions from logging calls. I think users don't expect that regular log writes could throw 😱 Would it be OK if we make sure the decorateEntries_ never throws, and does whatever it can possibly do even for objects with circular references? (e.g. dump incomplete object, or anything else)

[seriousManual]

Hello,
I have the same issue on Google AppEngine, with the same error appearing in Error Reporting.

Have you identified any circumstances that lead to this error?
I noticed that a certain (older) version of our application has no issues with this bug. This may relate to other parameters handed to winston (we use the winston transport)? If I knew which conditions are responsible I could prevent this error from happening (for now), until this is fixed.

Would switching to another version help with this issue?

[alexander-fenster]

Hello @seriousManual,

Have you identified any circumstances that lead to this error?

Yes and no. I made a fix googleapis/gax-nodejs#424 in exactly the place where it fails so it should not fail anymore (we'll release the new version of that package today). When all the dependency chain upgrades, the error condition should stop happening.

As for what causes the error - i.e. what causes the undefined value to be passed to logging - I don't have an answer I'm confident in. One idea is that it might be doing that if it gets an object with circular references, but it makes me think there should be another explanation, given that all these bug reports started coming from several people at the same time. @stephenplusplus can I ask you to take a deeper look at what's going on (why this undefined value appears there)?

[seriousManual]

Thank you for the efforts you're putting into this.

but it makes me think there should be another explanation, given that all these bug reports started coming from several people at the same time.

I'm glad it is not only us.
I am currently trying to pinpoint the time and place in the commit history where a possible change has been introduced that may relate to the issue. But this is quite cumbersome as the only way is to redeploy and wait for the bug to happen / not to happen.

How long do you think it will take until the fix patch has been introduced at the upstream deps? (gax -> nodejs-logging -> winston-logging)

[noelbranz]

Hello,
I have the same issue on Google AppEngine, with the same error appearing in Error Reporting.

Have you identified any circumstances that lead to this error?
I noticed that a certain (older) version of our application has no issues with this bug. This may relate to other parameters handed to winston (we use the winston transport)? If I knew which conditions are responsible I could prevent this error from happening (for now), until this is fixed.

Would switching to another version help with this issue?

Hi,

I would like to share my workaround as of this time, while waiting for the fix.
I tap into the process.on('unhandledRejection') and check if it is the same error: then I use logger.configure(...) to initialize another LoggingWinston transport -- (this time another filename, it did worked for me for (although it creates another file in stackdriver, but its ok as I can still capture the logs)

[noelbranz]

To all who spent time on this issue, I would like to thank you for your dedication to solve this. I have been tracing all logging combination that we do in our code (NodeJS in App-Engine) to find what is the exact scenario this happen. But if this can be solved on your end, Thank you very much!

[alexander-fenster]

Greetings folks,

I have released google-gax v0.25.2 which should not crash in case if an undefined value is passed. From what I understand, it means you may get an incomplete / malformed log message but at least nothing will crash. Since logging uses "google-gax": "^0.25.0" the fix will be picked up automatically.

[seriousManual]

Hi,
thank you for the fix, I updated the dependencies today, redeployed and promptly got the following output on stderr:
"Request does not contain field entries that must present for bundling. Invoking immediately"

I suppose that this is directly related to the fix?
Either way, though this case occured the logs keep coming in, so far it's looking good!

[alexander-fenster]

@seriousManual Yes, it's exactly that warning message that should be printed in this case. Note that it will be only printed once per each running process (otherwise your stderr would've been spammed a lot).

[noelbranz]

Hi Guys, I also did used the fix and deployed to our staging instance. Its been there for 3 days now and I never got the error again. Hopefully this is going to be stable now. Thanks a lot.

[seriousManual]

Same here,
haven't seen the issue on our development system for a while now!

Thank you!

[la-urre]

I observe the same issue with winston 3.2.1 and google-gax 1.0.0. I get the same error "Attempt to write logs with no transports" after a while.

I can see there was a huge refactoring done recently in google-gax, so maybe there was a regression during the process ?

[ltomes]

@la-urre Did you ever get to the bottom of your issue? I am seeing the same thing currently.

[JustinBeckwith]

If you're running into issues, please open a new bug with details 🤗