Watchtower fails to log empty line (since Cloudwatch rejects them)

[o-nikolas]

It appears the closed issue #43 is still present. I took some time today to investigate and try some fixes:

Given this example logging code:

import watchtower, logging
from subprocess import run, PIPE, STDOUT
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)
logger.addHandler(watchtower.CloudWatchLogHandler(log_group='test_empty_msg',
                                                  use_queues=True))
logger.info("foo")
logger.info("")
logger.info("bar")

Upon execution with current Watchtower I see:

INFO:botocore.credentials:Found credentials in environment variables.
INFO:__main__:foo
INFO:__main__:
INFO:__main__:bar
/home/ANT.AMAZON.COM/onikolas/.virtualenvs/watchtower_testing/lib/python3.7/site-packages/watchtower/__init__.py:237: WatchtowerWarning: Failed to deliver logs: Parameter validation failed:
Invalid length for parameter logEvents[1].message, value: 0, valid min length: 1
  warnings.warn("Failed to deliver logs: {}".format(e), WatchtowerWarning)
/home/ANT.AMAZON.COM/onikolas/.virtualenvs/watchtower_testing/lib/python3.7/site-packages/watchtower/__init__.py:241: WatchtowerWarning: Failed to deliver logs: None
  warnings.warn("Failed to deliver logs: {}".format(response), WatchtowerWarning)

The cloudwatch local validation fails and the whole batch of messages are not delivered to cloudwatch logs.

I've wrote a new Filter and tested some approaches.

Replaces empty messages with newline

The error case is no longer hit, but since the record is modified to now contain a newline rather than empty string, both the downstream loggers and cloudwatch logs show an extra newline:

INFO:botocore.credentials:Found credentials in environment variables.
INFO:__main__:foo
INFO:__main__:

INFO:__main__:bar

Also the cloudwatch logging text itself contains a new line, so when it is downloaded the formatting is a bit odd (CSV format):

imestamp,message
1635289000573,foo
1635289000574,"
"
1635289000574,bar

Replace empty message with space

The error case is no longer hit, but since the record is modified to now contain a whitespace rather than empty string, downstream loggers and Cloudwatch contain en extra space, but this is less noticeable than an extra newline IMHO:
(Note you can highlight the line to see the errant whitespace)

INFO:botocore.credentials:Found credentials in environment variables.
INFO:__main__:foo
INFO:__main__: 
INFO:__main__:bar

Cloudwatch CSV:

1635289572740,foo
1635289572745, 
1635289572746,bar

Filter empty messages entirely

The error case is no longer hit. Since this does not modify the record only the cloudwatch logs are affected. So the CW logs do not have the same formatting, but other downstream loggers show the correct logging:

INFO:botocore.credentials:Found credentials in environment variables.
INFO:__main__:foo
INFO:__main__:
INFO:__main__:bar

Cloudwatch CSV, note the missing empty line:

1635290287875,foo
1635290287876,bar

@kislyuk do you have a preference for which approach we take? Shall we make it configurable? Is there another approach that I haven't listed that you think is better?

[o-nikolas]

Hey @kislyuk
Any thoughts on these approaches? I'd like to submit a PR if you deem any of them acceptable.

[kislyuk]

Hello, thank you for reporting this issue. I have implemented a solution in #158 and will be releasing it as v2.0.0. The solution is to never send empty messages to CloudWatch Logs and to print a warning when this happens.

[o-nikolas]

Hello, thank you for reporting this issue. I have implemented a solution in #158 and will be releasing it as v2.0.0. The solution is to never send empty messages to CloudWatch Logs and to print a warning when this happens.

Awesome, so basically the third proposal. Glad to hear it's already in place.

What is the timeline for the release of 2.0.0 @kislyuk?

Let me know if I can help with anything to speed that up (testing, remaining dev tasks, etc).

Cheers

[kislyuk]

@o-nikolas v2.0.0 has been released.

[o-nikolas]

@kislyuk I was still seeing this issue in 2.0, and I found the cause, here is a PR to fix it #162