feat: add optional debug logs

[vancouverwill]

31

WIP

todo:

• log other endpoints
• update readme to show how to use debugger

[codecov[bot]]

Codecov Report

Merging #130 into master will decrease coverage by 0.24%. The diff coverage is 93.75%.

@@            Coverage Diff             @@
##           master     #130      +/-   ##
==========================================
- Coverage     100%   99.75%   -0.25%     
==========================================
  Files          17       17              
  Lines         795      813      +18     
==========================================
+ Hits          795      811      +16     
- Misses          0        2       +2

[panva]

I’m not fond of the logger option, sorry. “debug” module at most

[vancouverwill]

I’m not fond of the logger option, sorry. “debug” module at most

Thanks for looking and fair enough. Would you mind explaining why you don't like the logger option? debug library only supports one style of log format and we need json formatted logs in production for log search. I looked and thought about using debug as the only logger for a while this weekend as we do need some transparency around what is going on within node-openid-client but using debug is an rigid approach to logs and will only suit certain use cases. This seemed a good compromise, to default to debug but to allow clients of node-openid-client to use their own logging system. Anyway that's our use case and I imagine quite a few other peoples. Thanks for looking and all the hard work on your pr so far 👍

[panva]

Hi @vancouverwill

Thank you for taking the time and engaging with openid-client, here are my thoughts on the topic.

First, debug capabilities must not be confused with logging, i believe none of the request/response objects should ever reach a log entry unmodified, there's PII, bearer tokens and client secret credentials all over the place.

In terms of request/response debugging this has so far served that purpose and if ever was a built in DEBUG=openid-client:* support it would only focus something like that.

const { Issuer } = require('openid-client');
const request = require('request');
require('request-debug')(request);
Issuer.useRequest();

Logging must not be confused with debugging and is something every developer must be able to tailor for his/her environment. There's simply no "one way" to do it and that's why I will not accept a "logger" as I do not wish to impose a singular way of logging on everyone. Furthermore, who's to say which log entry falls under which log level? Again, context matters.

Looking at the changes you've pushed to your branch.

• changes you're making to the httpClient, those aren't necessary and aren't backwards compatible, if you need http in/out logging just provide your own httpClient wrapped. And you don't even have to care about the internals, wrap the defaults that Issuer.httpClient returns to you and wrap them.
• id_token not present in TokenSet if the IdP you're using isn't consistent with returning ID Tokens i.e. after refreshes, they ought to let you know and you shouldn't blindly call tokenset claims. It is, afterall, a really stupid helper that you can do yourself IF you have an id token.

The one and only way I came to think I'll support logging is events, emitted at specific points with a useful context. The work I'm doing on browser support in the other branch/issue is easily a v3.x now so i'll try and include that in there.

[vancouverwill]

First, debug capabilities must not be confused with logging, i believe none of the request/response objects should ever reach a log entry unmodified, there's PII, bearer tokens and client secret credentials all over the place.

Yeah good point, the logs I put in would certainly not be safe in a production environment. Creating events would be a lotpre flexible solution for most people.

id_token not present in TokenSet if the IdP you're using isn't consistent with returning ID Tokens i.e. after refreshes, they ought to let you know and you shouldn't blindly call tokenset claims. It is, afterall, a really stupid helper that you can do yourself IF you have an id token.

The reason I updated these error messages is each one had sent content so made it hard to see error came from. Unique errors do help, and in authorize callback the grant and token validation errors are all caught with same catch so still bit ambiguous as to what happened. What do you think about an error getting thrown in the grant request so you at least know that is what went wrong ? Thanks for your time 👌

[panva]

The reason I updated these error messages is each one had sent content so made it hard to see error came from. Unique errors do help, and in authorize callback the grant and token validation errors are all caught with same catch so still bit ambiguous as to what happened. What do you think about an error getting thrown in the grant request so you at least know that is what went wrong ?

I'm sorry I don't follow, the problem is?

[vancouverwill]

The reason I updated these error messages is each one had sent content so made it hard to see error came from. Unique errors do help, and in authorize callback the grant and token validation errors are all caught with same catch so still bit ambiguous as to what happened. What do you think about an error getting thrown in the grant request so you at least know that is what went wrong ?

I'm sorry I don't follow, the problem is?

ahh sorry, I guess that is two different ideas 1 - the same error message id_token not present in TokenSet is used as an error message in several places so it is hard to know the source of the error 2 - inside the authorizeCallback() there is a lot of stuff going on with grant(), decryptIdToken() and validateIdToken() which is why I needed to update the grant function so I could see where the failure has happened. Would you be open to consider to having a different error getting thrown if the grant fails?