feat: adding debug logger #64

jorge-ibm · 2019-10-08T18:22:19Z

Based on feedback I have added logging through the debug module. Log messages are suppressed by default unless the specified environment variables in the README are set. I've gone ahead and updated some unit tests that broke after this change, added unit tests for the logger itself, and replaced all console.log references throughout the code.

Checklist

npm test passes (tip: npm run lint-fix can correct most style issues)
tests are included
documentation is changed or added

mkistler

We need to work out how/whether we continue to support NODE_DEBUG=axios.

mkistler · 2019-10-09T12:46:44Z

lib/helper.ts

@@ -129,6 +130,7 @@ export function getMissingParams(
 * @returns {boolean} true if 'text' has html tags
 */
 export function isHTML(text: string): boolean {
+  logger.debug(`Determining if the text ${text} is HTLML.`);


Typo here. "HTLML" -> "HTML"

mkistler · 2019-10-09T12:56:07Z

README.md

+To see the output from all of the debugging scopes you can use:
+
+```DEBUG=node-sdk-core*```
+


You should add a note here about how DEBUG can be set for more than one library, using comma-separated debug strings. E.g.:

DEBUG=node-sdk-core:debug,other-lib:debug

So the way I set the logger up is for all the logger instances to be under node-sdk-core. So the user can only enable/disable loggers under one library DEBUG=node-sdk-core:debug,node-sdk-core:error. I originally did have a logger for each library but I moved towards the simpler approach of just having one for each log scope. Do we want to have my original approach instead? One for baseservice, helper, etc.. ?

@mkistler - please see the changes I made to the README. Let me know if this doesn't work.

What's the difference between verbose and debug?

Debug level includes all the logs, and verbose does as well excluding logs that are logged debug. This mimics winston's log levels based on the standard https://tools.ietf.org/html/rfc5424

mkistler · 2019-10-09T14:26:19Z

lib/request-wrapper.ts

        } catch {
-          console.debug(config)
+          logger.error(config)
        }


There's something still not quite right here. If someone sets NODE_DEBUG=axios but does not set DEBUG=node-sdk-core:debug, then they will get no debug output (if I'm reading this correctly).

It appears that we don't actually document the behavior of NODE_DEBUG=axios, so I guess we need to decide how we want this to work. We could just drop support for NODE_DEBUG=axios now that we have this new logging support.

Ah yes you're right. Was that flag initially added just to log the request and response being intercepted?

@mkistler - I removed the DEBUG flag from here and I just enabled all the loggers if the axios flag is set. Please take a look at logger.ts

~~@mkistler - I removed the DEBUG flag from here and I just enabled all the loggers if the axios flag is set. Please take a look at logger.ts~~ I just realized removing DEBUG flag was a mistake. Since removing made that block dependent on the axios flag being set now. Re-adding it back in.

Okay I see what @mkistler was saying about removing this "if" statement but I actually think it is fine to leave it there. Only because if this code executes, it will add these interceptors that will get run every time a request is made. This isn't a big performance hit or anything but since it's easily avoidable, I don't think we need to force the user through this pattern every time. Just a thought

germanattanasio · 2019-10-10T15:36:45Z

This is looking good @jorge-ibm Buen trabajo

dpopp07

Leaving a few comments, mostly just to make sure we are consistent about logging strings rather than error objects

dpopp07 · 2019-10-10T17:38:48Z

auth/token-managers/jwt-token-manager.ts

-    const err = new Error('`requestToken` MUST be overridden by a subclass of JwtTokenManagerV1.');
+    const errMsg = '`requestToken` MUST be overridden by a subclass of JwtTokenManagerV1.';
+    const err = new Error(errMsg);
+    logger.error(err);


The other error logs in this file log the message but this is logging the entire Error object, which includes the stack trace, etc. This should probably be changed to

Suggested change

logger.error(err);

logger.error(errMsg);

dpopp07 · 2019-10-10T17:40:37Z

lib/base-service.ts

@@ -85,6 +87,7 @@ export class BaseService {
    // check serviceUrl for common user errors
    const credentialProblems = checkCredentials(options, ['serviceUrl']);
    if (credentialProblems) {
+      logger.error(credentialProblems);


Similar to my other comment, if we don't want to include the stack trace in these logs, we don't need to log the whole error (checkCredentials returns an error object). This can be:

Suggested change

logger.error(credentialProblems);

logger.error(credentialProblems.message);

dpopp07 · 2019-10-10T17:54:13Z

lib/request-wrapper.ts

        } catch {
-          console.debug(config)
+          logger.error(config)
        }


Okay I see what @mkistler was saying about removing this "if" statement but I actually think it is fine to leave it there. Only because if this code executes, it will add these interceptors that will get run every time a request is made. This isn't a big performance hit or anything but since it's easily avoidable, I don't think we need to force the user through this pattern every time. Just a thought

dpopp07 · 2019-10-10T19:11:00Z

README.md

+  - ```DEBUG=ibm-cloud-sdk-core:info``` enables info logs
+  - ```DEBUG=ibm-cloud-sdk-core:debug``` enables debug logs
+  - ```DEBUG=ibm-cloud-sdk-core:verbose``` enables verbose logs
+  - ```DEBUG=ibm-cloud-sdk-core:warning``` enables warning logs


I suppose this is fine but I feel like the typical idea in loggers is that you set one level and then you get the logs from that level and also everything "under" that level in terms of decreasing verbosity. For example, if I set the level "verbose", I would also expect to get error and warnings and info, etc.

This seems like a limitation of debug and not your implementation so I'm not sure there's anything we can do here but I hope we aren't creating an experience that's less than ideal

This wasn't specified in the documentation, and yes it's a limitation of using debug. We can manually force this ourselves by enabling each log level through some conditions, but something to keep in mind is that I noticed debug was being used by other packages in our code. So that might make our version of log levels different than what the other packages do if they did not manually enforce that.

I noticed the same thing and would like to put in my vote for making the levels "additive", with a clear indication of the order of inclusion.

Sounds good. I've gone ahead and implemented log levels

mkistler · 2019-10-11T02:55:02Z

lib/request-wrapper.ts

        try {
-          console.debug(JSON.stringify(error, null, 2));
+          logger.error(JSON.stringify(error, null, 2));


If the error logged here does not include the original request, it would be really nice if we could find a way to log the request here as well.

So I ran a test and it looks like the error object returned does in fact contain the original request (under error.config), so as long as the stringify has been doing its job then that should have been logged as well

mkistler

Looks good! 👍

Left one minor comment -- does not affect functionality, just code simplification

mkistler · 2019-10-13T14:09:54Z

lib/logger.ts

+  verbose.enabled = true;
+  info.enabled = true;
+  warn.enabled = true;
+  error.enabled = true;


You don't need these four lines. The logic below handles this.

germanattanasio · 2019-10-14T13:46:38Z

auth/utils/read-credentials-file.ts


 const filename: string = 'ibm-credentials.env';

 export function readCredentialsFile() {
  if (!fs.existsSync) {
+    logger.warn('Unable to find the library fs.existsSync');


This usually happen when running in a browser and it's not a warning. I can't come up with a better message but I see this from a browser developer perspective and that person will be getting a warning that is not a problem

I'll add a +1 here, we can probably just remove that log

germanattanasio

I left 2 comments but this looks good

dpopp07

Looks good after addressing Mike and German's comments!

dpopp07 · 2019-10-14T14:27:56Z

lib/base-service.ts

@@ -65,6 +66,7 @@ export class BaseService {
   */
  constructor(userOptions: UserOptions) {
    if (!(this instanceof BaseService)) {
+      logger.error('Error creating an instance of BaseService: the "new" keyword is required to create service instances');
      throw new Error(
        'the "new" keyword is required to create service instances'


This is picky but the string the "new" keyword is required to create service instances could be assigned to a variable since it is used twice here. Not a required change

# [1.1.0](v1.0.0...v1.1.0) (2019-10-14) ### Features * adding debug logger ([#64](#64)) ([6079ca0](6079ca0))

ibm-devx-automation · 2019-10-14T15:22:53Z

🎉 This PR is included in version 1.1.0 🎉

The release is available on:

Your semantic-release bot 📦🚀

jorge-ibm requested review from germanattanasio, mkistler and dpopp07 October 8, 2019 18:22

mkistler suggested changes Oct 9, 2019

View reviewed changes

jorge-ibm force-pushed the add-debug-logger branch 3 times, most recently from 598789c to 035392a Compare October 9, 2019 20:16

dpopp07 requested changes Oct 10, 2019

View reviewed changes

jorge-ibm force-pushed the add-debug-logger branch from 035392a to 425e419 Compare October 10, 2019 19:42

mkistler reviewed Oct 11, 2019

View reviewed changes

jorge-ibm force-pushed the add-debug-logger branch 2 times, most recently from 7ecfd3e to f40401a Compare October 11, 2019 22:30

mkistler approved these changes Oct 13, 2019

View reviewed changes

germanattanasio reviewed Oct 14, 2019

View reviewed changes

germanattanasio approved these changes Oct 14, 2019

View reviewed changes

dpopp07 approved these changes Oct 14, 2019

View reviewed changes

jorge-ibm force-pushed the add-debug-logger branch from f40401a to 9259c95 Compare October 14, 2019 14:52

feat: adding debug logger

0b09654

jorge-ibm force-pushed the add-debug-logger branch from 9259c95 to 0b09654 Compare October 14, 2019 15:16

jorge-ibm merged commit 6079ca0 into master Oct 14, 2019

ibm-devx-automation pushed a commit that referenced this pull request Oct 14, 2019

chore(release): 1.1.0 [skip ci]

e395024

# [1.1.0](v1.0.0...v1.1.0) (2019-10-14) ### Features * adding debug logger ([#64](#64)) ([6079ca0](6079ca0))

ibm-devx-automation added the released label Oct 14, 2019

jorge-ibm deleted the add-debug-logger branch October 20, 2019 17:45

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: adding debug logger #64

feat: adding debug logger #64

jorge-ibm commented Oct 8, 2019

mkistler left a comment

mkistler Oct 9, 2019

mkistler Oct 9, 2019

jorge-ibm Oct 9, 2019 •

edited

Loading

jorge-ibm Oct 9, 2019

germanattanasio Oct 14, 2019

jorge-ibm Oct 14, 2019 •

edited

Loading

mkistler Oct 9, 2019

jorge-ibm Oct 9, 2019

jorge-ibm Oct 9, 2019 •

edited

Loading

jorge-ibm Oct 9, 2019

dpopp07 Oct 10, 2019

germanattanasio commented Oct 10, 2019

dpopp07 left a comment

dpopp07 Oct 10, 2019

dpopp07 Oct 10, 2019

dpopp07 Oct 10, 2019

dpopp07 Oct 10, 2019 •

edited

Loading

jorge-ibm Oct 10, 2019

mkistler Oct 11, 2019

jorge-ibm Oct 11, 2019

mkistler Oct 11, 2019

jorge-ibm Oct 11, 2019

mkistler left a comment

mkistler Oct 13, 2019

germanattanasio Oct 14, 2019

dpopp07 Oct 14, 2019

germanattanasio left a comment

dpopp07 left a comment

dpopp07 Oct 14, 2019

ibm-devx-automation commented Oct 14, 2019

		To see the output from all of the debugging scopes you can use:

		```DEBUG=node-sdk-core*```

	logger.error(credentialProblems);
	logger.error(credentialProblems.message);

feat: adding debug logger #64

feat: adding debug logger #64

Conversation

jorge-ibm commented Oct 8, 2019

Checklist

mkistler left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jorge-ibm Oct 9, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jorge-ibm Oct 14, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jorge-ibm Oct 9, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

germanattanasio commented Oct 10, 2019

dpopp07 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

dpopp07 Oct 10, 2019 • edited Loading

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

mkistler 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

germanattanasio left a comment

Choose a reason for hiding this comment

dpopp07 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ibm-devx-automation commented Oct 14, 2019

jorge-ibm Oct 9, 2019 •

edited

Loading

jorge-ibm Oct 14, 2019 •

edited

Loading

jorge-ibm Oct 9, 2019 •

edited

Loading

dpopp07 Oct 10, 2019 •

edited

Loading