Fix event time calculation on docker events

[ChrsMark]

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

beats/libbeat/common/docker/watcher.go

Line 267 in ce0b159

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

[jsoriano]

Good catch, thanks for the fix!

[jsoriano]

Good one 👍

[elasticmachine]

Pinging @elastic/integrations (Team:Integrations)

[elasticmachine]

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

• Build Cause: Pull request #24318 updated

• Start Time: 2021-03-03T15:53:04.475+0000

• Duration: 53 min 32 sec

• Commit: 2b43301

Test stats 🧪

Test	Results
Failed	0
Passed	46636
Skipped	4939
Total	51575

Trends 🧪

💚 Flaky test report

Tests succeeded.

Expand to view the summary

Test stats 🧪

Test	Results
Failed	0
Passed	46636
Skipped	4939
Total	51575