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

Fix multiple handlers causing duplicate messages #43

Merged
merged 3 commits into from
Feb 15, 2022

Conversation

michaeljb
Copy link
Contributor

@michaeljb michaeljb commented Dec 21, 2021

  • test_logger setup: allow kwargs to be forwarded to CumulusLogger constructor
  • add test asserting each CumulusLogger instance for a given name should only have one handler
  • CumulusLogger constructor: only create new handler if one is not present
    • code style: whitespace added and lines rearranged so that the 'Avoid duplicate message' comment makes the most sense

Before this change, multiple calls to CumulusLogger(name) would construct a
CumulusLogger instance with the same underlying Logger instance, but each
construction would also create and attach a new handler, resulting in duplicate
messages, e.g.:

> python
>>> from cumulus_logger import CumulusLogger
>>> logger = CumulusLogger('test')
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:18:09.315309", "level": "info"}
>>>
>>> logger2 = CumulusLogger('test')
>>> logger2.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:18:16.845070", "level": "info"}
{"message": "hello there", "timestamp": "2021-12-21T16:18:16.845070", "level": "info"}
>>>
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:18:18.165564", "level": "info"}
{"message": "hello there", "timestamp": "2021-12-21T16:18:18.165564", "level": "info"}

See also the screenshots on ghrcdaac/dmrpp-file-generator-docker#25 to see duplicates in
CloudWatch. The dmrpp-generator code isn't doing anything out of the ordinary when
creating its CumulusLogger instance
, which is what lead me to search here to find the
cause of the duplication.

With this change, a new handler is only constructed if the underlying Logger
does not already have any handlers, preventing messages from being handled more
than once:

> python
>>> from cumulus_logger import CumulusLogger
>>> logger  = CumulusLogger('test')
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:33:56.735453", "level": "info"}
>>>
>>> logger2 = CumulusLogger('test')
>>> logger2.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:34:03.887972", "level": "info"}
>>>
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:34:07.808415", "level": "info"}

This fixes the test added in the previous commit

Before this change, multiple calls to `CumulusLogger(name)` would construct a
`CumulusLogger` instance with the same underlying `Logger` instance, but each
construction would also create and attach a new handler, resulting in duplicate
messages, e.g.:

```
> python
>>> from cumulus_logger import CumulusLogger
>>> logger = CumulusLogger('test')
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:18:09.315309", "level": "info"}
>>>
>>> logger2 = CumulusLogger('test')
>>> logger2.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:18:16.845070", "level": "info"}
{"message": "hello there", "timestamp": "2021-12-21T16:18:16.845070", "level": "info"}
>>>
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:18:18.165564", "level": "info"}
{"message": "hello there", "timestamp": "2021-12-21T16:18:18.165564", "level": "info"}
```

See also the screenshots on
ghrcdaac/dmrpp-file-generator-docker#25

With this change, a new handler is only constructed if the underlying `Logger`
does not already have any handlers, preventing messages from being handled more
than once:

```
> python
>>> from cumulus_logger import CumulusLogger
>>> logger  = CumulusLogger('test')
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:33:56.735453", "level": "info"}
>>>
>>> logger2 = CumulusLogger('test')
>>> logger2.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:34:03.887972", "level": "info"}
>>>
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:34:07.808415", "level": "info"}
```
@markdboyd markdboyd changed the base branch from master to merge-nsidc-handlers-fix February 15, 2022 21:24
@markdboyd markdboyd merged commit 643eb8a into nasa:merge-nsidc-handlers-fix Feb 15, 2022
markdboyd added a commit that referenced this pull request Feb 15, 2022
* test_logger setup: allow kwargs to be forwarded to CumulusLogger constructor

* add failing test, each logger should only have one handler

* CumulusLogger: only create new handler if one is not present

This fixes the test added in the previous commit

Before this change, multiple calls to `CumulusLogger(name)` would construct a
`CumulusLogger` instance with the same underlying `Logger` instance, but each
construction would also create and attach a new handler, resulting in duplicate
messages, e.g.:

```
> python
>>> from cumulus_logger import CumulusLogger
>>> logger = CumulusLogger('test')
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:18:09.315309", "level": "info"}
>>>
>>> logger2 = CumulusLogger('test')
>>> logger2.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:18:16.845070", "level": "info"}
{"message": "hello there", "timestamp": "2021-12-21T16:18:16.845070", "level": "info"}
>>>
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:18:18.165564", "level": "info"}
{"message": "hello there", "timestamp": "2021-12-21T16:18:18.165564", "level": "info"}
```

See also the screenshots on
ghrcdaac/dmrpp-file-generator-docker#25

With this change, a new handler is only constructed if the underlying `Logger`
does not already have any handlers, preventing messages from being handled more
than once:

```
> python
>>> from cumulus_logger import CumulusLogger
>>> logger  = CumulusLogger('test')
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:33:56.735453", "level": "info"}
>>>
>>> logger2 = CumulusLogger('test')
>>> logger2.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:34:03.887972", "level": "info"}
>>>
>>> logger.info('hello there')
{"message": "hello there", "timestamp": "2021-12-21T16:34:07.808415", "level": "info"}
```

Co-authored-by: Michael Brandt <michaelbrandt5@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants