Removal of Winston #190

briancullen · 2019-09-22T18:41:18Z

Issue #, if available:
#10 #48 #103

Description of changes:
Alternative approach to upgrading the logging to that proposed in #188 - both requests aren't needed, it's one or the other.

Instead of upgrading the Winston library this change creates a simple logger that can be used instead. This change also standardises the logging format for in all environments and ensures that the specified logging level is honoured in lambda environments.

As far as I can tell the meta (or second argument to the logging functions) is only used in two places, both of which log out err.stack. As previously implemented this was converted into a JSON string which made it hard to read. The logger was changed so that strings (such as the stack trace) are printed out without being stringified.

Additionally the ability to change the log level was added whereas previously this could only be done via environmental variables before the module is loaded.

Some additional error checking may be required before merging this request and I'm making this initial submission to show the alternative mentioned in #188 is feasible.

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

Test was written on the assumption that all paths conformed to the unix format and line separators. This caused it to fail on Windows. This change normalises the path to Unix format so that the tests will work in both environments.

Old versions of node don't have console.debug. This change defaults to console.log if a level method doesn't exist and then to a noop function if console.log doesn't exist.

willarmiros · 2019-09-24T00:23:17Z

Hi @briancullen,
Thank you for yet another contribution. I would like to request that you make this PR against the 2.x branch instead of master. See #192 for more details. We have been discussing removing winston for some time since it is overkill for our relatively simple use case, so I think we'd go with this PR instead of #188, so this action isn't necessary on your other PR.

Sorry for this inconvenience, you can close this PR and we'll follow up on the new one once it's created.

briancullen · 2019-09-24T08:09:36Z

As requested by @willarmiros this pull request is being closed and replaced by #193 which is against the 2.x branch rather than master.

briancullen · 2019-10-30T22:38:51Z

Hi @willarmiros

Given the comments made about breaking changes on the associated commit in the 2.x branch I’m surprised this has been reopened. Do we no longer have to wait for the major release?

willarmiros · 2019-10-31T01:32:48Z

Hi @briancullen,

We have come to a release plan for a 3.0.0-alpha version of the SDK that will be released from the master branch. Since many of our customers want this and other 3.x changes ASAP, we want to expedite the release process even though we have more breaking changes coming. I am currently reviewing this PR and after giving some feedback hope to have it merged very soon.

We can't merge #193 since we want to keep the 2.x branch completely clear of breaking changes, since it still represents major version 2.x of the SDK. Stay tuned for a post on #157 that will explain the whole 3.0.0 release process.

Very sorry for the confusion, but we thank you very much for your continued contributions and look forward to releasing this soon.

willarmiros

Overall great work, just some nitpicks and need for corresponding documentation. Thank you again for your contribution.

willarmiros · 2019-10-30T22:12:47Z

packages/core/lib/logger.js

+  info: createLoggerForLevel('info'),
+  warn: createLoggerForLevel('warn'),
+  debug: createLoggerForLevel('debug'),
+  setLevel: (level) => logLevel = calculateLogLevel(level),


It is convention in this SDK for environment variables to take precedence over properties set programmatically, so setLevel() should only modify the logging level if AWS_XRAY_DEBUG_MODE and AWS_XRAY_LOG_LEVEL are not set.

To take a step back, immediately after writing that set level method I kind of regretted it because I’m not entirely sure what the use case for it is. Particularly as the other methods are fairly comply implemented (take the winston logger for example) but setLevel isn’t.

So I suppose I’m asking do you think it is worth keeping?

I agree that I can't really imagine a use case of needing to set the log level programmatically instead of with an EV. I have no issues with scrapping it.

Thanks for the feedback. Given how late it is here I’ll update the code as requested and push up a new version on or before Monday morning. Have a nice weekend.

Have removed the setLevel method as discussed so the environment variables are the only way to set the level of the logger.

willarmiros · 2019-10-30T22:19:25Z

packages/core/lib/logger.js

-      var result = [], prop, i;
+function formatLogMessage(level, message, meta) {
+  return createTimestamp() +' [' + level.toUpperCase() + '] ' +
+    (message !== undefined ? message : '') +


Check for truthiness of message instead of explicitly being equal to undefined. For example, with the current logger, logger.info(null) prints no message, whereas this logger prints out the string null.

Changed as requested.

willarmiros · 2019-10-30T23:35:03Z

packages/core/lib/logger.js

-var logger;
-var xrayLogLevel = process.env.AWS_XRAY_LOG_LEVEL;
+var validLogLevels = [ 'trace', 'debug', 'info', 'warn', 'error'  ];
+var logLevel = calculateLogLevel(process.env.AWS_XRAY_DEBUG_MODE ? 'debug' : process.env.AWS_XRAY_LOG_LEVEL);


Could you include the following changes to the readme in the core package:

Clarify in environment variables section that LOG_LEVEL is overridden by DEBUG_MODE

Include documentation for AWSXRay.getLogger().getLevel() and AWSXRay.getLogger().setLevel(level) APIs in the logging configuration section

Update the documentation for AWSXRay.setLogger(logger) to mention that using a third party logger can be incompatible with the SDK's logging environment variables (because, for example, setting a default winston logger will not print debug messages, even if AWS_XRAY_DEBUG_MODE is set)

Admittedly, some of these should already be in the docs but no better time than now to include them!

Have updated the readme to reflect the logging changes. As the getLevel and setLevel methods have been removed they are not mentioned.

willarmiros · 2019-10-30T23:59:18Z

packages/core/test/unit/logger.test.js

+      assert.equal(logger.getLogger().getLevel(), 'error');
+    });
+
+    it('Should set logging level after initialisation', function() {


This test and below one should be changed to ensure programmatic changes to level do NOT override the values set by environment variables, once the change I suggested above is implemented.

As setLevel, and it's associated tests, has been removed this change no longer applies.

willarmiros · 2019-10-31T01:24:18Z

packages/core/lib/logger.js

+  debug: createLoggerForLevel('debug'),
+  setLevel: (level) => logLevel = calculateLogLevel(level),
+  getLevel: () => validLogLevels[logLevel]
+};

 /* eslint-disable no-console */


This and the other eslint comment at line 25 can be removed, seeing as the logger will now exclusively be performing logging with console methods. To prevent IDEs from complaining about console usage, please add the following line to the rules object (starting at line 8) in .eslintrc.json at the root of the package:

"no-console": "off",

Changed as requested.

willarmiros · 2019-11-01T17:58:04Z

packages/core/lib/logger.js

 var format = require('date-fns/format');

-var logger;
-var xrayLogLevel = process.env.AWS_XRAY_LOG_LEVEL;
+var validLogLevels = [ 'trace', 'debug', 'info', 'warn', 'error'  ];


Why is trace included as a valid log level? It's not a method for logger and hasn't been in the past, so I'd recommend removing it.

Not sure why I put trace there either. It has been removed.

willarmiros · 2019-11-01T20:58:54Z

packages/core/lib/logger.js


-      var result = [], prop, i;
+function formatLogMessage(level, message, meta) {


Lambda functions already include a timestamp and log level (assuming you use the appropriate console method) in their logging messages, so it is redundant to include that information again. For example, the code

AWSXRay.getLogger().error("This is an error msg");

would produce

2019-11-01T20:52:52.654Z d143da11-ec2e-4253-a561-8489348b442a ERROR 2019-11-01 20:52:52.595 +00:00 [ERROR] This is an error msg

I would recommend checking for the LAMBDA_TASK_ROOT environment variable and including a timestamp and log level based on that.

The fact that the time stamp is repeated for lambda did occur to me when I was writing this but won’t it be repeated for other things that write to cloudwatch as well? Say an ECS container for example?

At the time of writing I think I decided it was better to have a consistent log format that is produced regardless of the environment rather than trying to customise it for each different environment.

I’m happy to change it if that is the recommendation but, as I said, I don’t think this will avoid repeated timestamps in every situation.

An alternative could be to allow the user of the library to control the message format (either in total or just the inclusion of the time stamp) via another environment variable or api. I’m happy to prototype something along those lines if you want.

What do you think is the best approach?

I think repeating the timestamp in CloudWatch is acceptable since CW treats their timestamp as a separate entity from the logging message, whereas Lambda actually interpolates the timestamp and log level into the logging message. I believe that is why the original author of the SDK special-cased logging in Lambda but not other environments.

If a user really cares about the logging format, they can always use the setLogger() API with their own logging object. So overall, I think omitting the timestamp and level in lambda environments is the best approach.

Changed so that if the LAMBDA_TASK_ROOT environment variable is set then the timestamp and logging level is not included in the outputted log line.

This change removes the setLevel method so now only environment variables can be used to set the log level. It also changes how the log message is formatted so that if the message is a falsey value it is replaced by an empty string. Updated README to reflect the logging changes being made. Finally a log level of silent is added which prevents all logging.

Change to check an environment variable to determine if the code is running within the context of an AWS lambda. If it is then the standard logger will not add the timestamp or the logging level to the logging output, rather this is left to the lambda runtime.

briancullen · 2019-11-03T19:52:30Z

Hello @willarmiros,

Think I addressed all the issues that you raised but let me know if I missed anything.

Apart from that if you do consider changing the log format to be a breaking change I suppose the last thin I'd like to check is that you are happy with the format of the logs produced particularly those that have metadata? Currently in the sdk code I think it is only stack traces you pass as metadata.

Filter so that only lines with a message or metadata are actually output from the logger. Without this you could end up with lines that only consist of a timestamp or, in the case of Lambda, nothing at all.

willarmiros

All necessary changes have been made. The metadata is being formatted in the same way as it was previously except with some more validation, so that is fine. Approving this PR.

Brian Cullen added 2 commits September 17, 2019 10:43

Fix Test To Deal With Windows Paths

ce0cbd9

Test was written on the assumption that all paths conformed to the unix format and line separators. This caused it to fail on Windows. This change normalises the path to Unix format so that the tests will work in both environments.

Create Internal Logging Object

0c11fbe

briancullen mentioned this pull request Sep 22, 2019

Upgrade of Winston library from version 2.4.4 to 3.2.1 #188

Closed

briancullen changed the title ~~Remove of Winston~~ Removal of Winston Sep 22, 2019

Brian Cullen added 4 commits September 22, 2019 19:51

Add Error Handling for Console Methods

4f0770f

Old versions of node don't have console.debug. This change defaults to console.log if a level method doesn't exist and then to a noop function if console.log doesn't exist.

Fix Tests for Spying on Console Methods

890c651

Fix Typo From Linting Fix

7f765c6

Additional Test Fix For Node v6

ee2f340

willarmiros mentioned this pull request Sep 23, 2019

package is un-necessarily large #186

Closed

briancullen mentioned this pull request Sep 24, 2019

Removal of Winston #193

Closed

briancullen closed this Sep 24, 2019

willarmiros mentioned this pull request Oct 4, 2019

Lazily create socket in SegmentEmitter #198

Closed

willarmiros reopened this Oct 30, 2019

yogiraj07 mentioned this pull request Oct 31, 2019

Node SDK release V3.0.0 #157

Closed

willarmiros suggested changes Nov 1, 2019

View reviewed changes

Brian Cullen added 4 commits November 3, 2019 16:33

Remove eslint ignore statements

f7563f2

Merge branch 'master' into internallogger

c8e1433

Prevent Logging Blank Lines

0af2412

Filter so that only lines with a message or metadata are actually output from the logger. Without this you could end up with lines that only consist of a timestamp or, in the case of Lambda, nothing at all.

willarmiros approved these changes Nov 4, 2019

View reviewed changes

willarmiros merged commit a65cd3c into aws:master Nov 4, 2019

briancullen deleted the internallogger branch November 4, 2019 19:59

xtheshumanator mentioned this pull request Dec 18, 2019

Critical dependency warning when bundling XRay SDK with webpack #103

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Removal of Winston #190

Removal of Winston #190

briancullen commented Sep 22, 2019

willarmiros commented Sep 24, 2019 •

edited

Loading

briancullen commented Sep 24, 2019

briancullen commented Oct 30, 2019

willarmiros commented Oct 31, 2019

willarmiros left a comment

willarmiros Oct 30, 2019

briancullen Nov 1, 2019

willarmiros Nov 1, 2019

briancullen Nov 1, 2019

briancullen Nov 3, 2019

willarmiros Oct 30, 2019

briancullen Nov 3, 2019

willarmiros Oct 30, 2019

briancullen Nov 3, 2019

willarmiros Oct 30, 2019

briancullen Nov 3, 2019

willarmiros Oct 31, 2019

briancullen Nov 3, 2019

willarmiros Nov 1, 2019

briancullen Nov 3, 2019

willarmiros Nov 1, 2019

briancullen Nov 1, 2019

willarmiros Nov 1, 2019 •

edited

Loading

briancullen Nov 3, 2019 •

edited

Loading

briancullen commented Nov 3, 2019

willarmiros left a comment


		var result = [], prop, i;
		function formatLogMessage(level, message, meta) {

Removal of Winston #190

Removal of Winston #190

Conversation

briancullen commented Sep 22, 2019

willarmiros commented Sep 24, 2019 • edited Loading

briancullen commented Sep 24, 2019

briancullen commented Oct 30, 2019

willarmiros commented Oct 31, 2019

willarmiros left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

willarmiros Nov 1, 2019 • edited Loading

Choose a reason for hiding this comment

briancullen Nov 3, 2019 • edited Loading

Choose a reason for hiding this comment

briancullen commented Nov 3, 2019

willarmiros left a comment

Choose a reason for hiding this comment

willarmiros commented Sep 24, 2019 •

edited

Loading

willarmiros Nov 1, 2019 •

edited

Loading

briancullen Nov 3, 2019 •

edited

Loading