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

Cherry-pick #24318 to 7.x: Fix event time calculation on docker events #24320

Merged
merged 1 commit into from
Mar 3, 2021

Conversation

ChrsMark
Copy link
Member

@ChrsMark ChrsMark commented Mar 3, 2021

Cherry-pick of PR #24318 to 7.x branch. Original message:

What does this PR do?

This PR fixes how lastValidTimestamp is calculated based on the event's time we get from docker API.

Docker events are reported like:

{"status":"exec_die","id":"d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912","from":"busybox","Type":"container","Action":"exec_die","Actor":{"ID":"d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912","Attributes":{"execID":"820942d4d8831ed11efca865f5b7ef776244f24b05a6fb6f108b8050707cfb76","exitCode":"0","image":"busybox","name":"test42"}},"scope":"local","time":1614780249,"timeNano":1614780249008388154}

time and timeNano report the same timestamp but with different accuracy.

In this, we should only use Time or TimeNano but not together, otherwise it will result in a timestamp points to the future which will lead to not valid restarts of the watcher at

Since: lastValidTimestamp.Format(time.RFC3339Nano),
. --since flag will point to the future making it unable to catch any events from that time on.

Why is it important?

To be able to recover from restarts like when docker daemon is getting restarted.

How to manually test this PR

  1. Start filebeat with docker autodiscover enabled:
filebeat.autodiscover:
  providers:
    - type: docker
      hints.enabled: true
      hints.default_config:
        type: container
        paths:
          - /var/log/containers/*-${data.container.id}.log 

NOTE: verify that log's path is valid on your system. If not check if /var/lib/docker/containers/*/*${data.container.id}*.log is the valid path.
2. run a dummy container: docker run --restart=always --name test42 -d busybox sh -c "while true; do $(echo date); sleep 1; done"
3. Verify logs flow in ES
3. Restart the docker daemon with sudo systemctl restart docker
4. Verify that logs keep flowing in ES after the restart

Logs

2021-03-03T14:12:36.729Z	DEBUG	[docker]	docker/watcher.go:278	Got a new docker event: {kill d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 busybox container kill {d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 map[image:busybox name:test42 signal:15]} local 1614780756 1614780756729496625}


2021-03-03T14:12:46.822Z	DEBUG	[docker]	docker/watcher.go:278	Got a new docker event: {kill d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 busybox container kill {d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 map[image:busybox name:test42 signal:9]} local 1614780766 1614780766821876317}
2021-03-03T14:12:47.022Z	DEBUG	[docker]	docker/watcher.go:278	Got a new docker event: {die d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 busybox container die {d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 map[exitCode:137 image:busybox name:test42]} local 1614780767 1614780767022110976}
2021-03-03T14:12:47.483Z	DEBUG	[docker]	docker/watcher.go:278	Got a new docker event: {stop d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 busybox container stop {d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 map[image:busybox name:test42]} local 1614780767 1614780767482947600}
2021-03-03T14:12:47.495Z	ERROR	[docker]	docker/watcher.go:299	Error watching for docker events: unexpected EOF
2021-03-03T14:12:48.495Z	DEBUG	[docker]	docker/watcher.go:264	Fetching events since 2021-03-03 14:12:47.4829476 +0000 UTC
2021-03-03T14:12:48.959Z	DEBUG	[docker]	docker/watcher.go:278	Got a new docker event: {start d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 busybox container start {d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 map[image:busybox name:test42]} local 1614780768 1614780768842421505}
2021-03-03T14:12:48.959Z	DEBUG	[docker]	docker/watcher.go:370	List containers
2021-03-03T14:12:48.963Z	DEBUG	[docker]	docker/docker.go:237	Container d960ece07fde79828ba6f228a1930ff36c2bf54d363d6ed833f31eee4c0e0912 is restarting, aborting pending stop

@ChrsMark ChrsMark added [zube]: In Review backport Team:Integrations Label for the Integrations team labels Mar 3, 2021
@elasticmachine
Copy link
Collaborator

Pinging @elastic/integrations (Team:Integrations)

@botelastic botelastic bot added needs_team Indicates that the issue/PR needs a Team:* label and removed needs_team Indicates that the issue/PR needs a Team:* label labels Mar 3, 2021
@elasticmachine
Copy link
Collaborator

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS
Pipeline View Test View Changes Artifacts preview

Expand to view the summary

Build stats

  • Build Cause: Pull request #24320 opened

  • Start Time: 2021-03-03T16:51:39.631+0000

  • Duration: 107 min 58 sec

  • Commit: ecf242e

Test stats 🧪

Test Results
Failed 0
Passed 46540
Skipped 4981
Total 51521

Trends 🧪

Image of Build Times

Image of Tests

💚 Flaky test report

Tests succeeded.

Expand to view the summary

Test stats 🧪

Test Results
Failed 0
Passed 46540
Skipped 4981
Total 51521

@ChrsMark ChrsMark merged commit 7e465a6 into elastic:7.x Mar 3, 2021
@zube zube bot removed the [zube]: Done label Jun 2, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
backport Team:Integrations Label for the Integrations team
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants