Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unexpected behaviour with transport 'level' option #33

Closed
kendallroth opened this issue Sep 20, 2021 · 16 comments · Fixed by #35
Closed

Unexpected behaviour with transport 'level' option #33

kendallroth opened this issue Sep 20, 2021 · 16 comments · Fixed by #35
Labels

Comments

@kendallroth
Copy link

We recently noticed some unexpected behaviour with the level option provided as an option to the logdna-winston transport. The current behaviour seems to be that the level provided will be used for two (occasionally conflicting) purposes:

  1. Determine the minimum log level sent to LogDNA (because of inherited WinstonJS transport)
  2. Provide a default value for log levels that are undefined/missing

This leads to unexpected behaviour in some cases, such as when attempting to send debug level logs to LogDNA but wanting the default level to be something like info (or warn to "pop out").

In our case, we had the LogDNA transport options set to debug originally, which meant that debug logs were being sent to LogDNA but the the default level being used for undefined log levels was also debug. We didn't want this behaviour, so we modified the transport options to use info; however, this caused WinstonJS to no longer send debug level logs (since this tranport inherits from Winston transport, which also defines a level option).

As every transport inherits from winston-transport, it's possible to set a custom format and a custom log level on each transport separately.

TL;DR: The underlying Winston transport uses the level option to define the minimum log level for a transport (docs, but LogDNA uses the same level option to define a default log level if missing/invalid (docs).

@kendallroth
Copy link
Author

P.S. While this probably affects the logger-node library as well, I created the issue here as this is the transport library.

@kendallroth
Copy link
Author

kendallroth commented Sep 20, 2021

Here is an example where fatal is a log level that is not listed in the custom log levels, which means it takes the "default" provided in the LogDNA transport options (which is set to level: debug). This same level config is what sets the minimum log level sent through this transport. In this case though, I would likely want the "default" level to be something else to indicate a problem, as debug logs are often overlooked.

image

@darinspivey
Copy link
Contributor

Yes, I noticed this as well when writing tests for the last change. I feel that the Winston name of level is more at fault for not being descriptive, and to avoid a breaking change in the logdna logger, we can change the instantiation options here because it's really a winston-specific problem. Since logdna does not have this "max log level" concept, this makes sense.

I'll propose that the constructor here gets 2 "new" parameters:

maxLogLevel: 'fatal' // "level" for winston--it will not log above this level
logdnaDefaultLevel: 'info' // the current "level" param for the logger

@kendallroth
Copy link
Author

kendallroth commented Sep 20, 2021

I definitely agree that the WinstonJS level option should be better named... However, I believe that it is more of a minLogLevel, in that it will only log events above the provided log level?

@darinspivey
Copy link
Contributor

Ugh, you're right, so confusing. level is a terrible name. Ok, same proposal, but going with minLogLevel instead. Sound good?

@darinspivey
Copy link
Contributor

I'm wondering if we put "winston" in the name? We don't want people to think that minLogLevel also applies to LogDNA. Perhaps minLogLevelWinston? Naming is hard :)

@kendallroth
Copy link
Author

Heh, yeah, "naming" is definitely one of the hardest things in computer science 😉. On one hand, would it be bad if people do think minLogLevel is associated with LogDNA? Since it would effectively be doing what the name represents anyway, would it be an acceptable tradeoff (especially with documentation)?

@kendallroth
Copy link
Author

Similarly, does the defaultLevel need a LogDNA prefix, or would it be sufficient without 🤷 ?

@darinspivey
Copy link
Contributor

Well yes, that's a fair point. Lines won't go to LogDNA without first going through that level filter, so I think you're right in that, perceptually, it does apply to LogDNA :)

For the default, it feels like the same situation where Winston doesn't use a default. If you're level isn't supported, it throws. I think most developers (including us) would frown on proper names being in var names, so I think that should be avoided. I think we can disambiguate with the README.md updates.

@darinspivey
Copy link
Contributor

Re-reading the winston docs, they say this for level:

Log only if info.level less than or equal to this level

So the initial suggestion for the parameter name was correct. maxLogLevel means "do not log anything above this level", which is the same as "log only if info.level less than or equal to this level".

Thus, the name will be maxLogLevel

@kendallroth
Copy link
Author

kendallroth commented Sep 21, 2021

Whoah, that's interesting, and definitely hasn't been my understanding/experience (at least, not that I can remember)... But now that I think about it, this is because of the different ways to view ordering of log levels (numeric vs effect). For example, consider the following log level mapping:

// log level: "info"
{
  critical: 0,
  error: 1,
  warn: 2,
  info: 3,
  debug: 4
}

In this case, warn (2) is technically "less" than info (3) on a numeric level, so it will be included. However, on an "effect" level it is "higher"... It probably comes down to however the developer is thinking of the log levels, whether as numeric levels or named. I do not think about the numberic levels at all after assigning them, but that would definitely be a per-developer preference.

@darinspivey
Copy link
Contributor

yes, exactly. The numerical (ordinal?) values representing the "levels" is really what matters, so they can be configured in a variety of ways.

This will come down to proper documentation to make clear. maxLogLevel feels right since adding this parameter is an exception rather than the norm, and an exclusive wording makes sense (rather than an inclusive saying what the levels we WANT are. If this parameter is used, it's because you DON'T want certain ones).

darinspivey added a commit that referenced this issue Sep 21, 2021
Both Winston and LogDNA have a "level" parameter, but they
mean different things. In Winston, it represents a "max"
level wherein anything logged above that level's rank will
not be logged (and thus sent to LogDNA). To disambiguate
this logger transport, the parameter will be called `maxLevel`,
and will only apply to Winston. LogDNA's `level` parameter is
actually not usable with the implementation of this transport
since all logs will be specifying a level value.

Fixes: #33
@darinspivey
Copy link
Contributor

@kendallroth, after diving into the code, it became clear that the LogDNA level parameter is not usable since winston will always define a level for each log entry. The docs have been made clear to reflect this. We settled on maxLevel to address this current issue--it's shorter and makes sense. Again, docs have been made clear.

This effort also exposed a bug wherein, if levels is not used, the npm default levels that Winston uses need to be set up as custom levels in LogDNA. This was added. You're welcome to view the attached PR as it goes through code review.

darinspivey added a commit that referenced this issue Sep 21, 2021
Both Winston and LogDNA have a "level" parameter, but they
mean different things. In Winston, it represents a "max"
level wherein anything logged above that level's rank will
not be logged (and thus sent to LogDNA). To disambiguate
this logger transport, the parameter will be called `maxLevel`,
and will only apply to Winston. LogDNA's `level` parameter is
actually not usable with the implementation of this transport
since all logs will be specifying a level value.

Fixes: #33
@logdnabot
Copy link
Member

🎉 This issue has been resolved in version 4.0.1 🎉

The release is available on:

Your semantic-release bot 📦🚀

@kendallroth
Copy link
Author

@darinspivey I did not previously "realize" that WinstonJS is actually what is responsible for setting a level for each log entry (makes sense in hindsight though). As long as maxLevel could still override the default WinstonJS transport level (ie. to send a different level of logs to LogDNA than other WInston transports), I think this neatly resolves the issue.

Good point about the missing levels bug though, a default of some sort was definitely needed (since not everyone will use custom maps). Thanks again for looking into this!

@darinspivey
Copy link
Contributor

As long as maxLevel could still override the default WinstonJS transport level

Yes, I think that'd be the case if maxLevel is used in the transport--it should override the overall level setting, although that wasn't tested here.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants