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

Feature request: Silent mode for all testing environments #1198

Closed
2 tasks done
jamesmhaley opened this issue Dec 20, 2022 · 19 comments · Fixed by #1347
Closed
2 tasks done

Feature request: Silent mode for all testing environments #1198

jamesmhaley opened this issue Dec 20, 2022 · 19 comments · Fixed by #1347
Assignees
Labels
completed This item is complete and has been merged/shipped feature-request This item refers to a feature request for an existing or new utility logger This item relates to the Logger Utility

Comments

@jamesmhaley
Copy link

jamesmhaley commented Dec 20, 2022

Use case

I'm a huge fan of the logger, thanks for all your hard work on it!! One side affect of it though is it can be super noisy when testing. It's useful to have the POWERTOOLS_DEV env variable, this is helpful. However, the problem with this is that there is no option of less noise, just silence.

I often debug with my IDE, but on occasion i'll add a console.log and find it useful to see that output. With my previous favourite logger (winston) you could silence within tests and that would stop the winston logger from outputting when explicitly silenced.

Solution/User Experience

It would be great to be able to set the logger to silent when a certain condition is met, like in a test or dev environment. This could be using NODE_ENV or another conditional.

A good solution would be to add an optional parameter of silent to the logger on invocation:

const logger = new Logger({
  silent: process.env.NODE_ENV === 'test',
  serviceName: 'AWS-SERVICE',
  persistentLogAttributes: {
    awsRegion: process.env.AWS_REGION || 'N/A',
  },
})

This would allow for console.log to still make it's way through to the terminal, while reducing the noise from Logger.

Alternative solutions

No response

Acknowledgment

@jamesmhaley jamesmhaley added triage This item has not been triaged by a maintainer, please wait feature-request This item refers to a feature request for an existing or new utility labels Dec 20, 2022
@dreamorosi
Copy link
Contributor

Hi @jamesmhaley thank you for opening this issue and for your support to the project!

I understand that you'd like to mute/silence the logs in certain situations i.e. debugging and/or testing but to further the discussion I'd like to better understand a couple of things:

  • When using jest, you can silence logs both via the --silent flag or by providing a mock implementation to the console object itself (example). Would these be enough or do you see other cases in which these two don't cover your needs?
  • You also mention the usage of console.log alongside Logger. Could you elaborate a little more on how you'd like the two to interact and in which situation?

Also, could you share an example of the docs from Winston where this behavior is shown? I think it'd help me better frame this feature request since I'm not familiar with that logger.

@dreamorosi dreamorosi added logger This item relates to the Logger Utility need-customer-feedback Requires more customers feedback before making or revisiting a decision discussing The issue needs to be discussed, elaborated, or refined and removed triage This item has not been triaged by a maintainer, please wait labels Dec 21, 2022
@jamesmhaley
Copy link
Author

jamesmhaley commented Dec 22, 2022

The --silent flag is helpful for muting all logs (including console.log), as is mocking console.log to have a custom implementation and in this way I could add the ability to turn on/off logs with a conditional, however both either result with no logs at all or mocking console.log still results with the Powertools logger logging out.

My suggestion is to mimic what winston does, as it would limit/suppress logs coming from Powertools logger but wouldn't require any env vars, the mocking of anything and would still allow use of console.log.

This is what the silent parameter in winston does: https://github.com/winstonjs/winston/blob/2489a3d13b20797d3dbc55d3daf560cf52c2e6a3/lib/winston/logger.js#L276

It's added as a param when you set up the logger, allow for a conditional to define it's state.
https://github.com/winstonjs/winston#creating-your-own-logger.

Both solutions currently in place are not perfect in my view, for example:

option outcome
Env var and --silent Stops all logging - including any ad-hoc console logs with console.log
Mocking console.log Allows control over console.log, but does not silent Powertools logger
proposed silent param Suppresses Powertools logger, leaves console.log untouched

I hope this makes sense, thanks again for all the hard work.

@jamesmhaley
Copy link
Author

Again, to clarify my use-case:

My code uses Powertools logger to log out within my codebase. I log out a lot.

I write some tests, when running these I don't want the noise of the Powertools logs, so I would like to suppress them.

While writing my tests, to quickly check something like the data returned from a function call, I might add a console.log to output it's return data. I would want to see this in the console, so I can continue to write my tests, in particular the expect part. This would then be removed, so not to leave any console.logs in my code.

Obviously I can attach a debugger in my IDE, but when writing a quick test, this can be cumbersome and (as we all know) sometimes slow things down a bit.

I also don't like the idea of mocking console as it's something that in my view should be immutable, being a core part of JavaScript and could have unexpected side affects.

@dreamorosi
Copy link
Contributor

Thank you for clarifying the use case, I now have a better understanding of what you're suggesting.

To begin, I want to contextualize the current Logger behavior and its interaction with jest specifically. Generally speaking, as stated in our tenets, we optimize first and foremost for running on Lambda. This allows us to make certain assumptions over the execution environment and the way people will use the libraries. With that said, developer experience is a close second and so I recognize that a feature like the one you're suggesting might have merits.

With the above in mind, Logger default behavior is to emit directly to stdout using a custom Console object (see code). The reason why we don't use the global console object is that the Lambda runtime applies its own patching to it so that it can append things like the request id and timestamp. In our case, we want to emit JSON-compliant logs only, so we couldn't use the global object and instead use our own (more context here).

In another feature request, customers have asked us to be able to disable logs when testing with jest. Jest also patches the global console object. This is what allows Jest to silence it (--silent) without requiring the user to change its code, and it's also the reason why the logs emitted by Logger were not silenced. To allow for this feature request, when customers explicitly tell us that they are running not on Lambda (or are developing) via the POWERTOOLS_DEV environment variable, we temporarily emit logs to the global console object, which allows jest or other modules/libraries to influence its behavior.

As a stop-gap solution, if you want to emit logs out of band, you could use this solution that I have tested and that works without having to mock the console while also having full control over your logs and have all others silenced:

Sample function that has logging in it (index.ts):

import { Logger, injectLambdaContext } from "@aws-lambda-powertools/logger";
import middy from "@middy/core";

const logger = new Logger({});

export const handler = middy(async () => {
  logger.info("Hello from the playground");
})
  .use(injectLambdaContext(logger));

Test file using jest (index.test.ts):

import { Console } from "console";
import { Context } from "aws-lambda";
import { handler } from "../lib/powertools-playground.function";

const console = new Console(process.stdout, process.stderr); // Create your own console object

describe("Sample Test", () => {
  test("does stuff", async () => {
    console.log('test'); // Use the newly created console object, this will always log regardless of Jest & Powertools flags/configs
    await handler({ test: "ok " }, {} as unknown as Context);
  });
});

Execute with export POWERTOOLS_DEV=true && jest --silent:
image


Before deciding on whether to introduce a new flag, or a new non-standard log level (i.e. SILENT), I think it'd be great to hear also from other customers who might have other use cases. I would also like to hear from the maintainers of the other runtimes to hear if they have ways of dealing with a similar requirement and/or have heard the same feature request from their users.

@dreamorosi dreamorosi added need-more-information Requires more information before making any calls and removed need-customer-feedback Requires more customers feedback before making or revisiting a decision labels Dec 23, 2022
@saragerion
Copy link
Contributor

saragerion commented Jan 10, 2023

I like Andrea's workaround, but I also do like the idea of a "silent" option.
To make it consistent with other powertools utilities, the silent logging behaviour could be enabled via for example an env variable POWERTOOLS_LOGS_ENABLED (defaults to true) or an enabled constructor parameter.

I don't have a strong opinion, happy to hear other people's perspectives.

@alexburley
Copy link

Having an enabled constructor parameter would be great for my use case

@danrivett
Copy link

danrivett commented Feb 17, 2023

I also would like to be able to selectively disable all log emissions in scenarios including but wider than just in Jest tests.

Use Case

My current scenario is I'd like as much of our ecosystem to switch over to using this Logger and so possibly reference a global Logger instance that they can create child Logger instances from.

Then we could disable logging either at the root Logger or most likely certain child loggers (and below) and those modules can log there as they wish but the log entries wouldn't be omitted.

We could set the logLevel to error of course, but sometimes even for errors we don't want to log from certain modules (perhaps because the error is handled by a fallback higher up, and the logged error adds noise and confusion because we actually successfully processed the request even if an underlying call failed. This was a real-life scenario for us).

We could of course ask that module writer to not log an error when they receive one, and instead log a warning, and then set the Logger's logLevel to ERROR, but I think that's working around the problem.

Possible Solutions

To that end, adding anenabled constructor parameter as suggested above would be fine. In the past I've used log4j2 which has an OFF value in their LogLevel enum (see here).

That would also be fine for configuring the logger. It has a possible drawback though if a generic log(level: LogLevel, messsage: string) method etc., is ever implemented (which would be a nice option to have to allow for dynamic log level determination in certain edge cases - for reference log4j2 supports this, though slf4j doesn't - so I'd also recommend possibly considering that in the future).

LogLevel Tangent

One question I do have related to LogLevel though is why it's supports any arbitrary string being passed in as it makes typos possible at compile time, and then seems to silently ignore it at runtime and use the default log level?:

const logger = new Logger({ logLevel: 'DEBG' });

Either way, I'm thrilled that this logger was implemented for the TypeScript ecosystem, and was really excited to move over to using it, so thank you, I really appreciate it.

@dreamorosi
Copy link
Contributor

Thank you for the comprehensive post, I really appreciate the added context and you flashing out the use case. I definitely see the value and acknowledge that we should seriously consider adding this feature.

Before moving forward however I'd like to discuss a bit more the specifics. At the moment I'm leaning towards following log4j2 and have an OFF or SILENT level. This would probably require less changes to the logic that decides whether to log or not.

Side notes

which would be a nice option to have to allow for dynamic log level determination in certain edge cases

You can technically already do this, for example:

const myDynamicLogType = resolveLogType(); // returns one of `info`, `error`, `warn`, `debug`

logger[myDynamicLogType]('I\'m a dynamic log entry');

LogLevel Tangent

Good point. If I recall correctly, this is the case because the log level can also come from the environment variables, which is always a string. With that said, I agree we could definitely be more strict about the accepted types and handle this internally. May I ask you to please open another feature request - referencing this message - so that we can address this?

@dreamorosi
Copy link
Contributor

Writing here a recap of the discussion so far:

Current situation

Currently Logger accepts a logLevel that can have as value one of DEBUG, INFO, WARN, ERROR.

In some executions environments like CI, it's possible to suppress logging by patching one between the logger or the global console object (see here for more info). In Lambda however it's not possible to disable logs completely.

This behavior is desirable for those customers who would like to have the ability to instrument their code with logs, but optionally have the chance to suppress them based on their requirements (see this comment for example).

Expected behavior

Logger should accept a new logLevel with name SILENT. When this level is set, either via constructor or via environment variable, the utility does not emit any log regardless of where it's running.

const logger = new Logger({ logLevel: 'SILENT' });
// OR
process.env.LOG_LEVEL = 'SILENT';
const logger = new Logger();

Other notes

The following (but not limited to) files/methods will have be touched to implement the feature:


I'm also moving the issue to our backlog and marking it with help-wanted. If anyone is interested in picking this up, please leave a comment here to finalize scope before opening a PR - while doing that feel free to ask any clarification / question.

@dreamorosi dreamorosi added confirmed The scope is clear, ready for implementation and removed discussing The issue needs to be discussed, elaborated, or refined need-more-information Requires more information before making any calls labels Feb 20, 2023
@dreamorosi dreamorosi moved this from Ideas to Backlog in AWS Lambda Powertools for TypeScript Feb 20, 2023
@dreamorosi dreamorosi added the help-wanted We would really appreciate some support from community for this one label Feb 20, 2023
@shdq
Copy link
Contributor

shdq commented Feb 27, 2023

@dreamorosi assign me, I read the discussion and I would like to help with this feature.

@dreamorosi dreamorosi removed the help-wanted We would really appreciate some support from community for this one label Feb 27, 2023
@dreamorosi dreamorosi moved this from Backlog to Working on it in AWS Lambda Powertools for TypeScript Feb 27, 2023
@dreamorosi
Copy link
Contributor

Thank you for offering to work on this Sergei!

As usual, happy to collaborate on the PR once is up 👍

@shdq
Copy link
Contributor

shdq commented Feb 28, 2023

New log level threshold equal to 0

Hey Andrea 👋

It seems like the log-level threshold scale is inverted, and following the current implementation, the SILENT value should be 24 since the grade uses 4 points for each step.

Current scale is:

DEBUG: 8,
INFO: 12,
WARN: 16,
ERROR: 20,

Because you proposed 0 for the silence mode and I think it is logical (zero = nothing), it makes sense reverting the scale from SILENT0 to maximum verbose DEBUG20. Since the end users can't use actual values for log-level it only matters for the code readability/logic.

So new scale would be:

SILENT: 0,
ERROR: 8,
WARN: 12,
INFO: 16,
DEBUG: 20,

It would require one additional change here:

private shouldPrint(logLevel: Uppercase<LogLevel>): boolean {
  if (
-    this.logLevelThresholds[logLevel] >=
+    this.logLevelThresholds[logLevel] <=
    this.logLevelThresholds[this.getLogLevel()]
  ) {
    return true;
  }
  return this.getLogsSampled();
}

What do you think?

@dreamorosi
Copy link
Contributor

Good observation, the proposed value wouldn't fit with the current scale.

While I agree that intuitively inverting the scale sounds correct, I think we should keep the current scale and make the new value fit into it.

My understanding (that I just got now after your comment) is that the scale conveys severity, so that the number that you set as logLevel is a threshold. Logs with a lower severity than your threshold are never emitted, while others with one above are. This is the same meaning/approach that it's used in other languages or libraries, i.e. Python logging module.

With this in mind, I think the new level should probably be 24 considering an increment of 4 from the previous threshold.

What do you think?

@shdq
Copy link
Contributor

shdq commented Feb 28, 2023

Yes, that would be 24.

The scale depends on the convention. I followed this discussion where you mentioned log4j and assumed that we will follow that scale. But it's only my assumption.

I did research on the history, syslog introduced log levels order described in RFC 5424. Basically, the severity of all levels is assumed to be numerically ascending from most important to least important.

I'm ok with both, let's make fewer changes, and as I mentioned before numbers are not important and are only in use internally. I can add a comment above the threshold levels to clarify the order of importance.

@danrivett
Copy link

danrivett commented Feb 28, 2023

Just to add to this discussion, (but I'm not sure what the best option is as I don't know the codebase well enough for that):

The current scale does also seem inverted to me too, and is supported for example by how log4j2 defines their log levels as:

Log Level Int Value
OFF 0
FATAL 100
ERROR 200
WARN 300
INFO 400
DEBUG 500
TRACE 600
ALL Integer.MAX_VALUE

I'm not sure the impact on inverting the scale now whilst making the change is, but depending on that answer it may introduce less technical debt to do that at this moment. Or it may cause too much impact.

I am hopeful that the use of the numeric value would be encapsulated enough to allow for such a refactoring if desired, but as I mentioned above, I don't know the code well enough to have an opinion on this.

Side note: SILENT vs OFF

Both slf4j and log4j2 use OFF as their nomenclature, rather than SILENT. So may be worth reconsidering to use a more standard term.

Not a big deal either way, but thought being a bit more conventional is advantageous. I haven't checked other logging libraries outside the Java ecosystem however, so this may not be fully representative.

@danrivett
Copy link

danrivett commented Feb 28, 2023

A counter point to the SILENT vs OFF discussion:

It seems that a very popular JavaScript logging library loglevel (with over 9m weekly downloads) uses SILENT so that's also a good precedent.

Regarding the numeric values, trying to find other data points, I see Python uses NOTSET with a value of 0 that ascends.

I'm not advocating for any changes, I just wanted to add some data points before anything was implemented to validate the current intention or point to possible improvements.

Update:
For clarity, Python uses the following values internally, which actually has the highest severity log level as the highest numerical value, similar to the suggestion above, so I was mistaken because I saw that NOTSET is 0. However I don't believe NOTSET is analogous to SILENT/OFF, so I apologise for the distraction. (Sorry Andrea, you already mentioned this above, but it didn't register in my brain the first time I read through).

Level Numeric value
CRITICAL 50
ERROR 40
WARNING 30
INFO 20
DEBUG 10
NOTSET 0

@dreamorosi
Copy link
Contributor

It's all good @danrivett, thank you for the inputs, I think they are valuable and further the discussion.

Allow me to answer to both topics:

Level scale

As already touched upon in previous comments, the numeric values of the scale are not exposed to users. Users can only pass string values for INFO, WARN, ERROR, and DEBUG, as well as their lowercase versions. As such, we don't consider this portion of code a contract and could change or be removed entirely (unlikely) at any time and without any prior warning.

When I initially brought the scale into the conversation (albeit with a wrong value) it was purely to aid a potential resolver.
With that said, I think we should move forward with adding the feature with the current scale and defer the discussion on whether we should change the scale to a later moment. This could potentially be if and when we decide to allow users to set the logLevel using a numeric value, which is a feature request that will require its own discussion.

A note on NOTSET: in Python it means the opposite of silent/no logging (source)

Silent mode name/label

I don't have a strong preference either, however I'm more inclined towards SILENT because of these points:

  • It's already used by other popular libraries in the JS/TS ecosystem, with loglevel being one and Pino being another.
  • From a semantic perspective, I read OFF as referring to the Logger instance, whereas I read SILENT as a characterisation of the log level, as in: "the Logger is off / switched off" vs "the current log level is silent".

@github-project-automation github-project-automation bot moved this from Working on it to Coming soon in AWS Lambda Powertools for TypeScript Mar 3, 2023
@github-actions
Copy link
Contributor

github-actions bot commented Mar 3, 2023

⚠️ COMMENT VISIBILITY WARNING ⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.

@github-actions github-actions bot added the pending-release This item has been merged and will be released soon label Mar 3, 2023
@dreamorosi dreamorosi removed the confirmed The scope is clear, ready for implementation label Mar 3, 2023
@dreamorosi dreamorosi added completed This item is complete and has been merged/shipped and removed pending-release This item has been merged and will be released soon labels Mar 20, 2023
@dreamorosi dreamorosi moved this from Coming soon to Shipped in AWS Lambda Powertools for TypeScript Mar 20, 2023
@dreamorosi
Copy link
Contributor

The new SILENT log level is available in the latest release. You can try it out by installing @aws-lambda-powertools/logger@latest (v1.7.0).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
completed This item is complete and has been merged/shipped feature-request This item refers to a feature request for an existing or new utility logger This item relates to the Logger Utility
Projects
None yet
6 participants