Fix condition when no handlers have been defined

[JohnPreston]

• Adding exception message to return to CFN #171
• No logging in cloudwatch groups at all #181

Description of changes:

Lack of validation that there are handlers set at all leads to trying to access at invalid index for the handlers.
So, if there are handlers, we can indeed at least access 0 and then add the filter.

I won't pretend to understand why this is here / what's the use-case for it, given that's not documented, but at least with that simple fix my code that works in sam local, in cfn test resource, and now in actually using it in CFN.

I also then now get logs into CloudWatch logs.

Sad note:

Not sure how, if at all, this passed real life tests when working on the new version release.
So that begs the question, for me and anyone who wants to use this library: is it at all tested in CFN or just with cfn test on local lambda ? :/
And especially if not at all, I'd recommend to have beta versions, users notified of these new beta versions for us to test with (which won't affect current working published resource versions either) so that can be tested, and very happy to part take in that.

[mrinaudo-aws]

lgtm

[darrylabbate]

Latest GitHub Action workflow run fails due to missing test coverage: https://github.com/aws-cloudformation/cloudformation-cli-python-plugin/runs/5875423952?check_suite_focus=true#step:6:93

[JohnPreston]

Rebased from the #183

[darrylabbate]

It's not the pre-commit dependency - it's just missing a single branch for test coverage. Probably just needs a simple test added here.

[jaymccon]

Thanks for this contribution John, I was over-eager approving this and didn't notice the failing checks. Are you able to add a test for the case where no logging is defined ? This project has a requirement for 100% branch test coverage 🥃 .

As Darryl mentioned, current tests for this function are here: https://github.com/aws-cloudformation/cloudformation-cli-python-plugin/blob/master/tests/lib/log_delivery_test.py#L147-L230 haven't looked in great depth, but you should be able to re-use the pattern used in those.

missing test

Hi John - thanks for your contribution. I did not initially realize a test for the corresponding change is missing. Please see comments above - thank you!

[JohnPreston]

Sure, let me add a test for this
PS: If I can understand how the existing ones work :p

[JohnPreston]

First time I used this lib I worked on a py3.9 machine and all the tests passed fine. Now on a py 3.10 the local tests with pylint and pytest won't work. Will try to create a new venv with the python versions of this lib.
Might be worth setting a max python version compatibility in the setup.py?

[darrylabbate]

Now on a py 3.10 the local tests with pylint and pytest won't work. [...] Might be worth setting a max python version compatibility in the setup.py?

John, would you mind opening a new issue with the full pylint/pytest output so we can properly debug this? If it's an issue for you, it may be an issue for others as well. Thanks!

[JohnPreston]

So just a couple things

• I tried with python3.7 -> python3.10 and pylint gives me the same errors consistently. So maybe tests used a different pylint version/config ? Might be worth setting something up in setup.cfg for rules. Happy to do another PR to fix the following

************* Module src.cloudformation_cli_python_lib.resource                                                                                                                                                      
src/cloudformation_cli_python_lib/resource.py:224:25: C0209: Formatting a regular string which could be a f-string (consider-using-f-string)
src/cloudformation_cli_python_lib/resource.py:227:25: C0209: Formatting a regular string which could be a f-string (consider-using-f-string)
************* Module src.cloudformation_cli_python_lib.metrics
src/cloudformation_cli_python_lib/metrics.py:145:4: W0237: Parameter 'action' has been renamed to 'invocation_point' in overridden 'HookMetricsPublisher.publish_exception_metric' method (arguments-renamed)
src/cloudformation_cli_python_lib/metrics.py:165:4: W0237: Parameter 'action' has been renamed to 'invocation_point' in overridden 'HookMetricsPublisher.publish_invocation_metric' method (arguments-renamed)
src/cloudformation_cli_python_lib/metrics.py:181:4: W0237: Parameter 'action' has been renamed to 'invocation_point' in overridden 'HookMetricsPublisher.publish_duration_metric' method (arguments-renamed)
************* Module src.cloudformation_cli_python_lib.hook
src/cloudformation_cli_python_lib/hook.py:278:25: C0209: Formatting a regular string which could be a f-string (consider-using-f-string)
src/cloudformation_cli_python_lib/hook.py:281:25: C0209: Formatting a regular string which could be a f-string (consider-using-f-string)
************* Module python.rpdk.python.parser
python/rpdk/python/parser.py:4:20: C0209: Formatting a regular string which could be a f-string (consider-using-f-string)
************* Module tests.lib.metrics_test
tests/lib/metrics_test.py:373:11: C1803: 'proxy._publishers == []' can be simplified to 'not proxy._publishers' as an empty sequence is falsey (use-implicit-booleaness-not-comparison)

------------------------------------------------------------------
Your code has been rated at 9.97/10 (previous run: 9.89/10, +0.08)

• I cannot for the love of trying add the catch case for the log delivery, mostly because I don't get how

    @classmethod
    def _get_existing_logger(cls) -> Optional["ProviderLogHandler"]:

works. My python is mid-level at best considering the wizardry going on. So any input on that would be great

[darrylabbate]

I can confirm the change passes the actual tests on my setup (Python 3.9.12)

============================= test session starts ==============================
platform darwin -- Python 3.9.12, pytest-7.1.1, pluggy-1.0.0
Test order randomisation NOT enabled. Enable with --random-order or --random-order-bucket=<bucket_type>
rootdir: /Users/drl/w/cloudformation-cli-python-plugin, configfile: setup.cfg
plugins: localserver-0.5.1.post0, random-order-1.0.4, hypothesis-6.42.3, cov-3.0.0
collected 232 items

tests/lib/boto3_proxy_test.py ....                                       [  1%]
tests/lib/cipher_test.py ..........                                      [  6%]
tests/lib/exceptions_test.py ...................                         [ 14%]
tests/lib/hook_test.py .........................                         [ 25%]
tests/lib/identifier_utils_test.py .....                                 [ 27%]
tests/lib/interface_test.py ............                                 [ 32%]
tests/lib/log_delivery_test.py ....................................      [ 47%]
tests/lib/metrics_test.py ............                                   [ 53%]
tests/lib/recast_test.py .........                                       [ 56%]
tests/lib/resource_test.py ........................                      [ 67%]
tests/lib/utils_test.py ...........                                      [ 71%]
tests/plugin/codegen_test.py .............................               [ 84%]
tests/plugin/parser_test.py ..                                           [ 85%]
tests/plugin/resolver_test.py ..................................         [100%]

=============================== warnings summary ===============================
env/lib/python3.9/site-packages/aws_encryption_sdk/internal/crypto/elliptic_curve.py:21
  /Users/drl/w/cloudformation-cli-python-plugin/env/lib/python3.9/site-packages/aws_encryption_sdk/internal/crypto/elliptic_curve.py:21: CryptographyDeprecationWarning: int_from_bytes is deprecated, use int.from_bytes instead
    from cryptography.utils import InterfaceNotImplemented, int_from_bytes, int_to_bytes, verify_interface

...

FAIL Required test coverage of 100.0% not reached. Total coverage: 99.88%

...

======================= 232 passed, 1 warning in 11.72s ========================

Though we still need to address the test coverage complaint. Note that I can't merge the PR even with the necessary approvals.

[darrylabbate]

In the coverage report, the condition never evaluates to true in any of the tests.

            if logging.getLogger().handlers:
                logging.getLogger().handlers[0].addFilter(ProviderFilter(provider))

Alternatively, the following never evaluates to false:

            if logging.getLogger().hasHandlers():
                logging.getLogger().handlers[0].addFilter(ProviderFilter(provider))

Ref: hasHandlers() documentation

[darrylabbate]

Admittedly, I'm not well-versed enough in this library/code base to know the impact of this change, but I'm curious if this would resolve the issue:

            # filter provider messages from platform
            provider = request.resourceType.replace("::", "_").lower()
-           logging.getLogger().handlers[0].addFilter(ProviderFilter(provider))
            log_handler = cls(
                group=log_group, stream=stream_name, session=provider_sess
            )
            # add log handler to root, so that provider gets plugin logs too
            logging.getLogger().addHandler(log_handler)
+           logging.getLogger().handlers[0].addFilter(ProviderFilter(provider))

This passes all tests, including 100% coverage. @JohnPreston does this solve your issue?

[darrylabbate]

For context, #36 is where this particular logging.getLogger().handlers[0] reference was originally added.

[JohnPreston]

Admittedly, I'm not well-versed enough in this library/code base to know the impact of this change, but I'm curious if this would resolve the issue:

            # filter provider messages from platform
            provider = request.resourceType.replace("::", "_").lower()
-           logging.getLogger().handlers[0].addFilter(ProviderFilter(provider))
            log_handler = cls(
                group=log_group, stream=stream_name, session=provider_sess
            )
            # add log handler to root, so that provider gets plugin logs too
            logging.getLogger().addHandler(log_handler)
+           logging.getLogger().handlers[0].addFilter(ProviderFilter(provider))

This passes all tests, including 100% coverage. @JohnPreston does this solve your issue?

Your tests pass 100%, but did it work when trying with a new CFN resource type in "actual" CFN ?

[darrylabbate]

Your tests pass 100%, but did it work when trying with a new CFN resource type in "actual" CFN ?

I didn't manually test this against CFN yet. I can carve out time to do that, but I want to make sure the change I proposed actually works for your use-case first.

As it stands, I'm a little skeptical of the conditional expression in front of the addFilter() call. It makes sense on the surface, but the fact that logging.getLogger().handlers and logging.getLogger().hasHandlers() evaluate differently for the same tests is a little... interesting.

That's why I'm curious if simply moving the addFilter() call after the addHandler() call also results in you seeing CloudWatch logs for your use-case. We would avoid the interesting conditional expression while also preventing the invalid handler subscripting - but it's pointless unless it actually resolves your issue 🙂.

[JohnPreston]

The problem is accessing handlers[0] directly as it assumes there is at least one handler, which proved to be wrong for me and results in IndexError

edit: I did not originally get your change until I pulled it @darrylabbate
Happy to try that

[darrylabbate]

@JohnPreston I went ahead and submitted the change (#184) to make it a little more convenient for you to pull and test the change on your end.

[JohnPreston]

@JohnPreston I went ahead and submitted the change (#184) to make it a little more convenient for you to pull and test the change on your end.

Hi @darrylabbate
Tested and it seems to have worked properly. So I suppose we can close this one and proceed with #184

[darrylabbate]

Great! I'll close this in favor of #184. (CC: #181)