Revert "Revert "Add structured logging on top of seelog"" #2797
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
shubham2892
previously approved these changes
Jan 20, 2021
angelcar
force-pushed
the
angelcar_structured_logs
branch
from
9a6d2ac to
c292abb
Compare
Realmonia
previously approved these changes
Jan 20, 2021
shubham2892
previously approved these changes
Jan 20, 2021
This reverts commit 35b12f0.
angelcar
force-pushed
the
angelcar_structured_logs
branch
from
f91829a to
8fe20a1
Compare
fierlion
approved these changes
Jan 22, 2021
sparrc
approved these changes
Jan 22, 2021
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Summary
Logs in agent are very challenging to work with. This refactor aims to bring structured logs on top of seelong (for both, json and logfmt formats) for easier reading when debugging.
This PR only changes logs for task_manager.go as a PoC.
here's a sample of how the structured logs look like:
logfmt:
json:
{"level":"info","time":"2020-11-06T22:25:01Z","msg":"Waiting for any previous stops to complete","Seq":64,"taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:01Z","msg":"Waiting for task event","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:01Z","msg":"Wait over; ready to move towards desired status","desiredStatus":"RUNNING","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:01Z","msg":"Task not steady state or terminal; progressing it","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:01Z","msg":"Waiting for task event","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:01Z","msg": "Creating cgroup /ecs/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:01Z","msg":"Transitioned resource","resource":"cgroup","FailedStatus":"CREATED","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:01Z","msg":"Managed task got resource","ResourceStatus":"CREATED","resource":"cgroup","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:01Z","msg":"Task not steady state or terminal; progressing it","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:01Z","msg":"Waiting for task event","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Handling container change event","container":"ecs-exec-alpine","runtimeID":"","status":"PULLED","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"error","time":"2020-11-06T22:25:22Z","msg":"Error while pulling image; will try to run anyway","container":"ecs-exec-alpine","error":{"FromError":{}},"image":"ecs-exec-test-alpine:latest","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Task not steady state or terminal; progressing it","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Waiting for task event","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Handling container change event","container":"ecs-exec-alpine","runtimeID":"042d40635129ab72b858ecc2fe39929f7e90c0f7a01180b5a9a012f9a82f911f","status":"CREATED","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Task not steady state or terminal; progressing it","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Waiting for task event","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Handling container change event","container":"ecs-exec-alpine","runtimeID":"042d40635129ab72b858ecc2fe39929f7e90c0f7a01180b5a9a012f9a82f911f","status":"RUNNING","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Sending container change event","ContainerName":"ecs-exec-alpine","KnownSent":"NONE","Reason":"CannotPullContainerError: Error response from daemon: pull access denied for ecs-exec-test-alpine, repository does not exist or may require 'docker login': denied: requested access to the resource is denied","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Sent container change event","ContainerName":"ecs-exec-alpine","KnownSent":"NONE","Reason":"CannotPullContainerError: Error response from daemon: pull access denied for ecs-exec-test-alpine, repository does not exist or may require 'docker login': denied: requested access to the resource is denied","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Task not steady state or terminal; progressing it","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Waiting for task event","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Handling container change event","container":"ecs-exec-alpine","runtimeID":"042d40635129ab72b858ecc2fe39929f7e90c0f7a01180b5a9a012f9a82f911f","status":"RUNNING","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"} {"level":"info","time":"2020-11-06T22:25:22Z","msg":"Container change is redundant","container":"ecs-exec-alpine","knownStatus":"RUNNING","runtimeID":"042d40635129ab72b858ecc2fe39929f7e90c0f7a01180b5a9a012f9a82f911f","status":"RUNNING","taskARN":"arn:aws:ecs:us-west-2:901447253822:task/B85D1C69-774E-4779-8258-054137F597C7/84f7be9bde55426cb65325a9e8fbfa13"}Implementation details
The best course of action I found was to wrap seelog with a custom logger designed to just format the
messagepart of seelog logger. The API had to change in order to add structured fields since seelog doesn't support those (it's possible through custom contexts, but this approach is too expensive and leaks file descriptors).To see how the new wrapper would be used, see task_manager.go in this PR.
Testing
New tests cover the changes:
Description for the changelog
A log in
logfmtformat that looked like this:level=info time=2020-11-17T23:37:53Z msg="Managed task [arn:aws:ecs:us-west-2:901447253822:task/ecs-exec-gamma/776f36ce708c4701b196779d125d5104]: Container [name=ecs-exec-alpine runtimeID=0d2799a853ebf2bd4bff7c2620c31d836ef457f31ff96fc9730e52633e536a35]: handling container change event [CREATED]" module=task_manager.goWill now look like:
and for
jsonformat, it will change from:{"level":"info", "time":"2020-11-06T22:25:01Z", "msg":"Managed task [arn:aws:ecs:us-west-2:901447253822:task/ecs-exec-gamma/776f36ce708c4701b196779d125d5104]: Container [name=ecs-exec-alpine runtimeID=0d2799a853ebf2bd4bff7c2620c31d836ef457f31ff96fc9730e52633e536a35]: handling container change event [CREATED]", "module":"task_manager.go"}to:
{"level":"info","time":"2020-11-06T22:25:01Z","msg":"handling container change event","taskArn":"arn:aws:ecs:us-west-2:901447253822:task/ecs-exec-gamma/776f36ce708c4701b196779d125d5104","container":"ecs-exec-alpine","runtimeID":"0d2799a853ebf2bd4bff7c2620c31d836ef457f31ff96fc9730e52633e536a35","status":"CREATED" }Licensing
By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.