(CLI): Allow some level of control about the verbosity output of CLI commands

[nomike]

Describe the feature

Over the past couple of years, the cdk CLI tool started printing more and more messages to the screen. Most of them I don't care about in most situations.

I propose adding options which allow what or how much is printed to the screen.

For this I have two proposals, each with their own pros and cons:

Simple verbosity

As with all modern logging frameworks, severity levels could be introduced. Common categories are "Error", "Warning", "Info", "Debug". Sometimes above and below that scale additional "Fatal" and "Trace" levels are available as well.

When the application wants to log something, it needs to specify the severity (e.g. logging.debug("start: Building 86a60ae7e6d79c710784bb96d99805a0cca7efa7814a6b83a770717b53228511:289230003688-eu-west-1")).

Logs which are below the current severity level will not be printed to the terminal.

Per default, the log-level could be set to "Info", so the message above would not be shown.
Command line flags could be introduced, to change the default severity level.

Common ways of doing that are -v or --verbose to increase the log level and -q or --quiet to decrease it.
Another option would be to use a flag like --log-level= with the options "ERROR", "WARNING", etc. (as there is no general consensus about this, both "WARN" and "WARNING" should be accepted here).

Specifying a config variable (something like @aws-cdk/cli:log-level) would also be advised.

Yet another way would be to use environment variables (e.g. `CDK_LOGLEVEL="WARNING" cdk diff"). Environment variables have another huge benefit: They are passed down to the user-written code, so they can be used there as well.

Of course this methods could and probably should be combined.

Log categories

Alternatively to the verbosity-levels, or better in addition to that, logs could be put in separate categories. This could be an additional parameter to the call of the logging function (e.g. logging.debug("start: Building 86a60ae7e6d79c710784bb96d99805a0cca7efa7814a6b83a770717b53228511:289230003688-eu-west-1", module="deployer") or it could be as simple as using the class-name of the calling object (using reflection).

This would allow even more fine grained control of error messages. Though I'm currently not sure how a user-interface for this could look like without being too complicated.

Pros and cons of these solutions

Simple verbosity

(+) Relatively easy to implement.

(+) Easy to use. Users are very likely to already be familiar with the whole concept.

(-) Less flexible. Users could only suppress certain categories. So if for example the messages "Consider making this CfnMapping a lazy mapping by providing..." and "No routeTableId was provided to the subnet at..." are both on level "WARNING", there is no way of getting rid of one of these. And if I set the severity threshold to a level which suppresses both of these warnings, I might miss another one which pops up a few months later (e.g. due to a deprecated feature). So in the long run, this might not be enough.

Log categories

(+) Allows for great flexibility and fine grained control.

(-) Probably more complicated to use and understand.

(-) More effort to implement.

Use Case

We're using a ci/cd pipeline (gitlab) for deploying changes to the cloud.

The pipeline has two main steps: "diff" and "deploy"

Users are supposed to change config/code in the automation, push their changes to a branch on the gitlab sever. There cdk diff --all is executed. The user is then supposed to review the diff to see if their change is changing things as intended, with no side effects.

Once they are done, they create a merge request, which triggers another run of cdk diff. The merge request is reviewed by the CloudOps team. They review the config/code change and also the diff. If everything looks OK, the request is approved and merged.

Right before the production deployment cdk diff is run again to verify that everything is still alright and not interfering with other changes which have been deployed recently.

With all the stuff cdk diff is printing out to the console, the output is very long and hard to read. This leads to people not really reading it anymore, and important things being drowned by and getting lost in between the other messages.

There are a number of messages I'm not interested in as there is nothing I can or want to do about them.
For example the message "[Warning at /euc1-dv-rest-alb-alb/subnet-0] No routeTableId was provided to the subnet at 'euc1-dv-rest-alb-alb/subnet-0'. Attempting to read its .routeTable.routeTableId will return null/undefined. (More info: #3171)" (see #19786 I filed 2½ years ago).
In this case IMHO the warning is completely pointless as it's a tautology. Of course, if I don't specify a route table ID, it will be empty when I try to read it later. And even if it's not tautology: When I'm reading the variable, I get None as a result. So what?

There is nothing I can do to address this, but it's also not an issue for me. So I need a way to get rid of the message.

Proposed Solution

Introduce a new log class which allows the specification of the log-level. The class should also read the context (e.g. class name) of the calling class to categorize logs. This could also be an optional parameter which defaults to the calling class name, to allow coders to override this.

New CLI flags, a config setting and an environment variable should be added to allow control of the log level.

Optionally more fine grained control using the categories should be added. Though I think it's better to just implement the verbosity levels first to not make the change too complicated. Categories should still be added internally to be prepared for the moment when someone really wants to implement these more fine-grained controls in the future.

Probably some already existing logging framework should be used for all of this (e.g. https://github.com/vauxite-org/typescript-logging/blob/HEAD/category-style/README.MD).

Other Information

Currently there is no internal way to control verbosity of the output of the cdk CLI tool.
I filed a feature request a while back about being able to suppress unchanged stacks in the output of cdk diff (#26526) which was implemented by means of a --quiet flag having been added (#26652). There was a bug with the initial implementation in that it didn't show stack names at all when the flag was used, even for stacks with changes.

I filed a bug report (#27128) for this which got implemented with #30186.

This whole process took quite some time and in the meantime the CLI got more verbose printing for example stuff like this to the screen:

[Info at /use1-pr-customer-api-public-route53-aliasrecord/MappingCopy-AWSCloudFrontPartitionHostedZoneIdMap-c88b0307188360f6083c72a2a857503f8678fb10e7] Consider making this CfnMapping a lazy mapping by providing `lazy: true`: either no findInMap was called or every findInMap could be immediately resolved without using Fn::FindInMap
start: Building 57a500ec68beab2278a65b4d30898ace70eb2e0fe52439e6646780f898020e4e:289230003688-eu-central-1
success: Built 57a500ec68beab2278a65b4d30898ace70eb2e0fe52439e6646780f898020e4e:289230003688-eu-central-1
start: Publishing 57a500ec68beab2278a65b4d30898ace70eb2e0fe52439e6646780f898020e4e:289230003688-eu-central-1
success: Published 57a500ec68beab2278a65b4d30898ace70eb2e0fe52439e6646780f898020e4e:289230003688-eu-central-1
Hold on while we create a read-only change set to get a diff with accurate replacement information (use --no-change-set to use a less accurate but faster template-only diff)

So this renders the --quiet flag useless.

The way I workarounded this for our use case at the moment is this:

Some years back, I wrote a CLI tool in python called pcdk, which allowed cdk deploy and cdk diff calls to be parallelized. This was before parallel deployments where introduced in aws-cdk.
This tool uses subprocess.Popen() in a sub-thread to run cdk deploy for a single stack and the function looks like this:

def run_process(
        command: List[str]
) -> int:
    """
    run a process and print stdout and stderr to console as it goes.
    """
    global arguments
    global block_output

    logging.debug(f'Running {" ".join(command)}...')
    process = subprocess.Popen(command,
                               universal_newlines=True,
                               stdout=subprocess.PIPE,
                               stderr=subprocess.PIPE,
                               bufsize=1)
    q = Queue()
    output = []

    def reader(pipe, queue):
        try:
            with pipe:
                for line in iter(pipe.readline, ''):
                    queue.put((pipe, line))
        finally:
            queue.put(None)

    threading.Thread(target=reader, args=[process.stdout, q]).start()
    threading.Thread(target=reader, args=[process.stderr, q]).start()

    for _ in range(2):
        for reader, line in iter(q.get, None):
            if reader.fileno() == process.stderr.fileno():
                if block_output:
                    output.append((line, '2'))
                else:
                    print(line, file=sys.stderr, end='')
            else:
                if block_output:
                    output.append((line, '1'))
                else:
                    print(line, end='')

    process.stdout.close()
    process.stderr.close()
    if block_output:
        if (not arguments['--suppress-unchanged-stacks']) or ('There were no differences' not in '\n'.join([i[0] for i in output])):
            for (line, file) in output:
                ignore = False
                for ign in ignore_cdk_output:
                    if ign in line:
                        ignore = True
                if not ignore:
                    print(line, file=sys.stderr if file == 2 else sys.stdout, end='')
    return process.wait()

block_output is True for pcdk diff and false for pcdk deploy. The rationale is that I want to know immediately when there are issues during deployment. I also need to be able to interfere.

But for cdk diff I need the output to be blocked to keep it readable.

As aws-cdk now supports parallelization in a way much better than I could ever do with an outside wrapper script, I would like to get rid of it, but the only thing which prevents me from doing that, is the lack of control over the output.

Acknowledgements

• I may be able to implement this feature request
• This feature might incur a breaking change

CDK version used

2.165.0 (build 00f70f1)

Environment details (OS name and version, etc.)

Ubuntu 24.04 LTS on Linux VIE-NOMPOS-AP 5.15.153.1-microsoft-standard-WSL2 #1 SMP Fri Mar 29 23:14:13 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux on WSL2 (2.3.24.0) on Windows 11 (32H2)

[nomike]

While I found a way of acknowledging the warnings about empty subnet IDs, I'm still looking for a way to get rid of those "start: Building", "start: Publishing", etc. messages to check in the source whether there is any way to get rid of them as well.

[ashishdhingra]

Severity levels are supported in other high-level libraries that offer logging support. So it makes sense to control some logging behavior at verbose level, with default as off/all (current behavior).