Add awslogs multiline support

[mixja]

Signed-off-by: Justin Menga justin.menga@gmail.com

- What I did

This PR adds multiline processing to the AWS CloudWatch logs driver, providing functionality similar to the native AWS CloudWatch logs agent.

The feature allows users to optionally specify multiline pattern matching logic using either a regular expression or a Python strftime expression, meaning application events that span multiple lines (e.g. application stack traces) can be published to CloudWatch logs as a single event.

The awslogs-multiline-pattern and awslogs-datetime-format log options have been added:

• awslogs-datetime-format - defines a multiline start pattern in Python strftime format. This option always takes precedence if both awslogs-datetime-format and awslogs-multiline-pattern are configured.
• awslogs-multiline-pattern - defines a multiline start pattern using a regular expression. This option is ignored if awslogs-datetime-format is also configured.

- How I did it

Implemented an event buffer that buffers log messages until a new multiline start pattern is matched. As soon as a new event is detected, the event buffer is appended/flushed to the pre-existing events slice for normal processing using the pre-existing batch publishing mechanism.

The implementation will immediately flush the event buffer if the maximum CloudWatch logs event size is reached, appending the buffer to the events slice up to the maximum event size.

The implementation also will only buffer up to the batch publishing frequency (currently 5 seconds). If a multiline event has been buffered for longer, it will be flushed to the events slice for normal processing at the next batch processing ticker. This ensures a multiline message will not be buffered for a long period of time in the scenario where no further messages are sent by the application for an extended period of time (the maximum amount of time a message can be buffered is 2 * batch publishing frequency or 10 seconds)

- How to verify it

Assuming you have AWS access key ID and secret access key with permissions to a pre-existing CloudWatch logs group called test, in the Docker development container first start up the Docker daemon with AWS permissions:

# Make sure we have accurate time
apt-get install ntp -y
service ntp start

# Compile and install Docker daemon
hack/make.sh binary install-binary 

# Replace with your AWS settings - must have permissions to write to the CloudWatch logs group
export AWS_REGION=us-west-2
export AWS_ACCESS_KEY_ID=xxxxx
export AWS_SECRET_ACCESS_KEY=xxxxx

# Start Docker daemon with AWS permissions
dockerd -D&

Next run the examples below...

Example using awslogs-multline-pattern

docker run -it --rm --log-driver=awslogs --log-opt awslogs-group=test --log-opt awslogs-multiline-pattern='^ABCD' my-container

With the following container stdout:

ABCD First event
Some more lines
Another line
ABCD Second event 

Two CloudWatch log events will be generated:

Event 1

ABCD First event
Some more lines
Another line

Event 2

ABCD Second event 

Example using awslogs-datetime-format

docker run -it --rm --log-driver=awslogs --log-opt awslogs-group=test --log-opt awslogs-datetime-format='%Y-%m-%d' my-container

With the following container stdout:

[2017-04-01 12:00:00] First event
Some more lines
Another line
[2017-04-01 12:00:05] Second event 
[2017-04-01 12:00:06] Third event 

Three CloudWatch log events will be generated:

Event 1

[2017-04-01 12:00:00] First event
Some more lines
Another line

Event 2

[2017-04-01 12:00:05] Second event

Event 3

[2017-04-01 12:00:06] Third event

- Description for the changelog

Add AWS CloudWatch Logs multiline processing

- A picture of a cute animal (not mandatory but encouraged)

[cpuguy83]

If we were to take this functionality, I'd much prefer to implement this in a way that works on any log driver as there is nothing driver specific about the implementation.

I also find the date/time format vs "specify any regex" kind of weird from a UX point of view.
This should probably error out if both are specified.
Event better to implement the regex and do time separately as it really is different.

Implementation should take into account a misbehaving application that either sends really long messages (too big to hold in a single message) or that just does not send the message delimiter.

I also expect that the regex matching will impose a significant performance cost for logging. Some benchmarks here would be helpful, and notes in the documentation on this.

[mixja]

@cpuguy83 - I would tend to agree with a more generic approach, however as per #22920 this proposal was rejected and advice was for individual logging drivers to implement this functionality themselves.

I would suggest there is a reasonably strong argument for this in the AWS CloudWatch logs driver, given the native agent supports multiline processing and the date time format processing I have implemented.

The date/time format reflects the native CloudWatch Logs agent implementation (see datetime_format and multi_line_start_pattern parameters) - and IMHO makes it easier to express a date time pattern in strftime format from an end-users perspective. The implementation compiles this one-time to a regex anyway at container startup so there is no material difference at an implementation level.

The implementation leverages the existing implementation in terms of dealing with log messages that are too long (CloudWatch logs have published limits and the existing implementation adheres to these limitations), and specifically detects if a buffered message has exceeded these limits and hands off processing to the existing implementation. The implementation also will only buffer for the batch publishing frequency (currently 5 seconds as per the existing implementation), so I think all questions around unusual log event processing are covered.

WRT benchmarking, agree there may be a performance hit and will benchmark to quantify this. Ultimately this is an opt-in feature and has been designed such that the same existing processing logic is applied if the multiline feature has not been activated, but will be useful to provide guidance on when this feature may introduce performance issues.

[danieljimenez]

👏 thanks for doing this! It's a huge addition for anyone running Java applications in Docker with Amazon CloudWatch Logs. I look forward to seeing it upstream.

[mixja]

@cpuguy83 - I have added some basic benchmarks, they just simulate pushing 10 multiline logs with 100 lines per multiline log, with a reasonably real-world multiline pattern of \d{4}-(?:0[1-9]|1[0-2])-(?:0[1-9]|[1,2][0-9]|3[0,1]) (?:[0,1][0-9]|2[0-3]):[0-5][0-9]:[0-5][0-9]

Master branch benchmark (see https://github.com/mixja/docker/tree/awslogs-benchmark):

BenchmarkCollectBatch-4            1000        1330899 ns/op

Pull request benchmark:

BenchmarkCollectBatch-4                            1000        1322489 ns/op
BenchmarkCollectBatchMultilinePattern-4            1000        2178240 ns/op

So yes as would be expected there is a performance hit with multiline pattern matching, but no performance hit with the new code base if you don't enable multiline pattern matching.

[vdemeester]

ping @cpuguy83 @thaJeztah @tonistiigi @icecrime @tiborvass what is the status for this one ?

[tiborvass]

+1 for the design. I agree with phemmer in his comment about #22920 (comment) so I wouldn't want this to be generalized in docker, but in the awslogs driver it makes sense.

[cpuguy83]

Design OK, moving to code review.

[vdemeester]

@mixja compilation errors

00:24:41 # github.com/docker/docker/daemon/logger/awslogs
00:24:41 daemon/logger/awslogs/cloudwatchlogs.go:146: not enough arguments to return

[mixja]

@tiborvass - looks like your commit broke the build?

[tiborvass]

@mixja thanks, fixing.

[mixja]

@vdemeester - can we re-run the windows tests - looks like an unrelated failure in the Jenkins job output:

Stderr:   Error response from daemon: Cannot stop container d51d40c8f721e8373cd4a8b86c00134d3b17ffededcefc21ea02f7fdc58f536e: Cannot kill container d51d40c8f721e8373cd4a8b86c00134d3b17ffededcefc21ea02f7fdc58f536e: invalid container: d51d40c8f721e8373cd4a8b86c00134d3b17ffededcefc21ea02f7fdc58f536e

[kencochrane]

I just tested it out, and it works well, here are my test files incase anyone else wants to try it out.

Dockerfile

FROM alpine:latest
ADD test*.sh /
RUN chmod 755 /test*.sh

test1.sh

#!/bin/ash
echo "ABCD First event"
echo "Some more lines"
echo "Another line"
echo "ABCD Second event"

test2.sh

#! /bin/ash
echo "[2017-04-01 12:00:00] First event"
echo "Some more lines"
echo "Another line"
echo "[2017-04-01 12:00:05] Second event"
echo "[2017-04-01 12:00:06] Third event"

docker run -t --rm --log-driver=awslogs --log-opt awslogs-group=test --log-opt awslogs-multiline-pattern='^ABCD' awslogtest:latest /test1.sh

docker run -it --rm --log-driver=awslogs --log-opt awslogs-group=test --log-opt awslogs-datetime-format='%Y-%m-%d' awslogtest:latest /test2.sh

I created a test log group in cloudformation, and made sure my AWS creds were exported, like it is described above.

[mixja]

@crosbymichael - yes I have tested both.

Attached is a screen shot of CloudWatch Logs console showing Java stack traces with the multiline support enabled.

[vdemeester]

LGTM 🐯
/cc @cpuguy83 @tiborvass

[cpuguy83]

LGTM

[cpuguy83]

Just a nit on the style here, we could flip this and return early to reduce indentation.

[cpuguy83]

parens are not needed here

[thaJeztah]

Thank you @mixja! Given that this adds new features to the AWS logging driver, can you also open a pull request in the documentation repository (probably the vnext-engine branch, because this will be in the upcoming release) to document the new feature? https://github.com/docker/docker.github.io/blob/vnext-engine/engine/admin/logging/awslogs.md

[kensaggy]

Sorry for jumping in, but when can we expect this to be released? (we've been looking forward to this feature for a long time!)

[thaJeztah]

See the milestone; it's gonna be part of the upcoming 17.06 release, targeted start of June (and release candidate 1 later this week for testing)

[mixja]

@thaJeztah - done docker/docs#3319

[thaJeztah]

@mixja thanks!

[kensaggy]

Thanks @thaJeztah :)