Filebeat's docker metadata watcher losing container from its list somehow

Elastic Stack Beats
1

After some random time, the watcher looses some(?) active containers. In the log you can see that filebeat is still reading correctly from docker logs but then says, it cannot find the container with add_docker_metadata.go:124: DBG Container not found: (last line of the log).
Also when I check in docker the container is still there and running but logs are not written to ES. Also the registry is updated. I need to restart the filebeat container and it will pickup the current time, which means I have gaps in my logs in ES.

I am running filebeats 6.0.0 in the official beats docker container.

tail_files: true
filebeat.prospectors:
  - type: log
    close_inactive: 24h
    paths:
      - '/var/lib/docker/containers/*/*.log'
    json.message_key: log
    json.keys_under_root: true
    processors:
    - add_docker_metadata: ~
    - decode_json_fields:
        fields: ["log"]
        target: ""
        when:
          equals:
            docker.container.name: nginx
output.elasticsearch:
  hosts: ["elasticsearch:9200"]

2017/12/01 08:47:53.115968 log.go:85: DBG End of file reached: /var/lib/docker/containers/41b27667b48a4b5f274479523bc4c1123af0ef27df667324cf8a15111b16f325/41b27667b48a4b5f274479523bc4c1123af0ef27df667324cf
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.129626 client.go:282: DBG PublishEvents: 1 events have been  published to elasticsearch in 13.731209ms.
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.129800 logger.go:29: DBG ackloop: receive ack [6176: 0, 1]
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.129871 logger.go:29: DBG broker ACK events: count=1, start-seq=33097, end-seq=33097
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.129978 logger.go:18: DBG ackloop: return ack to broker loop:1
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.130035 logger.go:18: DBG ackloop:  done send ack
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.130134 registrar.go:200: DBG Processing 1 events
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.130258 registrar.go:195: DBG Registrar states cleaned up. Before: 15, After: 15
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.130293 registrar.go:228: DBG Write registry file: /usr/share/filebeat/data/registry
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.169128 registrar.go:253: DBG Registry file updated. 15 states written.
Dec 01 08:47:53 hyrb dockerd[10369]: 2017/12/01 08:47:53.637285 log.go:85: DBG End of file reached: /var/lib/docker/containers/0ce25642d8009f26fe29da0ff5123b5877661e06f435e118854e344abebfaf5f/0ce25642d8009f26fe29da0ff5123b5877661e06f435e11885
Dec 01 08:47:55 hyrb dockerd[10369]: 2017/12/01 08:47:55.116342 log.go:85: DBG End of file reached: /var/lib/docker/containers/41b27667b48a4b5f274479523bc4c1123af0ef27df667324cf8a15111b16f325/41b27667b48a4b5f274479523bc4c1123af0ef27df667324cf
Dec 01 08:47:57 hyrb dockerd[10369]: 2017/12/01 08:47:57.541338 log.go:85: DBG End of file reached: /var/lib/docker/containers/d7fdf40887de244536e24112b8cdb24222f46ef9421e30024aeba85bb813e333/d7fdf40887de244536e24112b8cdb24222f46ef9421e30024a
Dec 01 08:47:59 hyrb dockerd[10369]: 2017/12/01 08:47:59.114992 prospector.go:140: DBG Run prospector
Dec 01 08:47:59 hyrb dockerd[10369]: 2017/12/01 08:47:59.115035 prospector.go:136: DBG Start next scan
Dec 01 08:47:59 hyrb dockerd[10369]: 2017/12/01 08:47:59.116727 add_docker_metadata.go:124: DBG Container not found: 41b27667b48a4b5f274479523bc4c1123af0ef27df667324cf8a15111b16f325
2

Hi @benben,

Thank you for reporting this, could you please share the output of the following command?

docker events --filter container=41b27667b48a4b5f274479523bc4c1123af0ef27df667324cf8a15111b16f325 --since 2017-01-01T10:00:00.999999999
3 
$ docker events --filter container=41b27667b48a4b5f274479523bc4c1123af0ef27df667324cf8a15111b16f325 --since 2017-01-01T10:00:00.999999999
2017-12-01T09:01:14.806436716Z container kill 41b27667b48a4b5f274479523bc4c1123af0ef27df667324cf8a15111b16f325 (com.github.jrcs.letsencrypt_nginx_proxy_companion.nginx_proxy=true, image=nginx:latest, maintainer=NGINX Docker Maintainers <docker-maint@nginx.com>, name=nginx, signal=1)
4

This looks like a bug, we should be ignoring kill events, as they carry many signals, not all of them kill the container :slight_smile:

Thanks for reporting, I just opened a PR fixing this: https://github.com/elastic/beats/pull/5788

I'm sorry for the inconvenience, once merged it will make it into the next release window, let me know if you need anything before, we can probably provide snapshot image with the patch

Best regards

5

Sounds awesome. Thank you! When is the next release scheduled? And can I use already the 6.1.x container of filebeat?

6

It should make it both to next minor and patch versions (6.1.0 and 6.0.1). I would say you can expect a new release soon, in the following days/weeks.

Best regards

7

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.