Filebeat's add_docker_metadata stop working after container restart

We use filebeat from Graylog to collect logs from services run in docker-compose.

Filebeat is not started as a linux service, but executed as this command:

sudo /usr/share/filebeat/bin/filebeat --path.home /usr/share/filebeat --path.config /etc/filebeat --path.data /var/lib/filebeat --path.logs /var/log/filebeat -c /etc/graylog/collector-sidecar/generated/filebeat.conf

Steps to reproduce

  1. Start filebeat using command provided above
  2. Start services with docker-compose (now log harvesting works perfectly and docker metadata are attached to log messages)
  3. Restart docker containers (sometimes it is necessary to restart containers twice)
  4. Since now filebeat start harvesting logs, but without docker metadata. They are completely missing

filebeat.conf file

filebeat.inputs:
  - type: filestream
    id: dockerglobal
    paths:
      - /home/commity/docker/.docker-data/containers/*/*.log
    encoding: plain
    ignore_older: 0
    processors:
      - add_docker_metadata:
          match_source_index: 5
      - rename:
          fields:
            - from: "log"
              to: "origin"
          ignore_missing: false
          fail_on_error: true
      - decode_json_fields:
          fields: ["message"]
          max_depth: 1
          target: ""
          overwrite_keys: true
          add_error_key: true

output.logstash:
  hosts: ****
  worker: 1
  ssl.enabled: false

Debug output from filebeat

Here is a part of debug logs from filebeat, which show the occasion, when docker container is restarted and the first container log is harvested. Interested is that even though container creation event is correctly registered by Watcher, a few seconds later, the container is not found in Watcher's "containers" map. You can search container e41a8620daf277:

2023-01-03T11:11:18.208+0100    DEBUG   [add_docker_metadata]   docker/watcher.go:279   Got a new docker event: {create e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96 ***:master container create {e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96 map[com.docker.compose.config-hash:06c33707e3a027a0648c1c2717a6b989ec56a554953726833424c890a38fe3b3 com.docker.compose.container-number:1 com.docker.compose.oneoff:False com.docker.compose.project:perpetualgate-test com.docker.compose.project.config_files:docker-compose.yml com.docker.compose.project.working_dir:/home/commity/docker/perpetualgate-test com.docker.compose.service:backend com.docker.compose.version:1.28.0 graylog.log.type:spring_json graylog.name:pptgate-test image:***:master name:perpetualgate-test_backend_1]} local 1672740678 1672740678207807622}
2023-01-03T11:11:18.573+0100    DEBUG   [add_docker_metadata]   docker/watcher.go:279   Got a new docker event: {start e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96 ***:master container start {e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96 map[com.docker.compose.config-hash:06c33707e3a027a0648c1c2717a6b989ec56a554953726833424c890a38fe3b3 com.docker.compose.container-number:1 com.docker.compose.oneoff:False com.docker.compose.project:perpetualgate-test com.docker.compose.project.config_files:docker-compose.yml com.docker.compose.project.working_dir:/home/commity/docker/perpetualgate-test com.docker.compose.service:backend com.docker.compose.version:1.28.0 graylog.log.type:spring_json graylog.name:pptgate-test image:***:master name:perpetualgate-test_backend_1]} local 1672740678 1672740678573112848}
2023-01-03T11:11:18.573+0100    DEBUG   [add_docker_metadata]   docker/watcher.go:375   List containers
2023-01-03T11:11:18.574+0100    DEBUG   [add_docker_metadata.bus-docker]        bus/bus.go:88   map[container:0xc000190150 start:true]  {"libbeat.bus": "docker"}
2023-01-03T11:11:18.639+0100    DEBUG   [add_docker_metadata]   docker/watcher.go:279   Got a new docker event: {create 13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68 ***:master container create {13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68 map[com.docker.compose.config-hash:239a5dc9b294f3ec18882c74dc80de896c4aa9184c37aec6f1290754ee74bce7 com.docker.compose.container-number:1 com.docker.compose.oneoff:False com.docker.compose.project:perpetualgate-test com.docker.compose.project.config_files:docker-compose.yml com.docker.compose.project.working_dir:/home/commity/docker/perpetualgate-test com.docker.compose.service:backup-nfs com.docker.compose.version:1.28.0 image:***:master name:perpetualgate-test_backup-nfs_1]} local 1672740678 1672740678639187463}
2023-01-03T11:11:19.339+0100    DEBUG   [add_docker_metadata]   docker/watcher.go:279   Got a new docker event: {start 13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68 ***:master container start {13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68 map[com.docker.compose.config-hash:239a5dc9b294f3ec18882c74dc80de896c4aa9184c37aec6f1290754ee74bce7 com.docker.compose.container-number:1 com.docker.compose.oneoff:False com.docker.compose.project:perpetualgate-test com.docker.compose.project.config_files:docker-compose.yml com.docker.compose.project.working_dir:/home/commity/docker/perpetualgate-test com.docker.compose.service:backup-nfs com.docker.compose.version:1.28.0 image:***:master name:perpetualgate-test_backup-nfs_1]} local 1672740679 1672740679338902338}
2023-01-03T11:11:19.339+0100    DEBUG   [add_docker_metadata]   docker/watcher.go:375   List containers
2023-01-03T11:11:19.343+0100    DEBUG   [add_docker_metadata.bus-docker]        bus/bus.go:88   map[container:0xc000190230 start:true]  {"libbeat.bus": "docker"}
2023-01-03T11:11:20.045+0100    DEBUG   [file_watcher]  filestream/fswatch.go:141       Start next scan
2023-01-03T11:11:20.045+0100    DEBUG   [file_watcher]  filestream/fswatch.go:212       Found 0 paths
2023-01-03T11:11:20.090+0100    DEBUG   [file_watcher]  filestream/fswatch.go:141       Start next scan
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/prospector.go:188    File /home/commity/docker/.docker-data/containers/45664b30bc43df224e95ef549fc17463321a053a91a7d1e92ec12ddd16b3579d/45664b30bc43df224e95ef549fc17463321a053a91a7d1e92ec12ddd16b3579d-json.log has been updated   {"id": "dockerlocal", "prospector": "file_prospector", "operation": "write", "source_name": "native::3933202-64768", "os_id": "3933202-64768", "new_path": "/home/commity/docker/.docker-data/containers/45664b30bc43df224e95ef549fc17463321a053a91a7d1e92ec12ddd16b3579d/45664b30bc43df224e95ef549fc17463321a053a91a7d1e92ec12ddd16b3579d-json.log", "old_path": "/home/commity/docker/.docker-data/containers/45664b30bc43df224e95ef549fc17463321a053a91a7d1e92ec12ddd16b3579d/45664b30bc43df224e95ef549fc17463321a053a91a7d1e92ec12ddd16b3579d-json.log"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3933202-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/prospector.go:188    File /home/commity/docker/.docker-data/containers/9ef29b8009fd356827ff4d09b8caa00b53031dea633c03e8f9bbba6120702fbf/9ef29b8009fd356827ff4d09b8caa00b53031dea633c03e8f9bbba6120702fbf-json.log has been updated   {"id": "dockerlocal", "prospector": "file_prospector", "operation": "write", "source_name": "native::3408205-64768", "os_id": "3408205-64768", "new_path": "/home/commity/docker/.docker-data/containers/9ef29b8009fd356827ff4d09b8caa00b53031dea633c03e8f9bbba6120702fbf/9ef29b8009fd356827ff4d09b8caa00b53031dea633c03e8f9bbba6120702fbf-json.log", "old_path": "/home/commity/docker/.docker-data/containers/9ef29b8009fd356827ff4d09b8caa00b53031dea633c03e8f9bbba6120702fbf/9ef29b8009fd356827ff4d09b8caa00b53031dea633c03e8f9bbba6120702fbf-json.log"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3408205-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:181  Stopped harvester for file      {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3408205-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:181  Stopped harvester for file      {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3933202-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/prospector.go:188    File /home/commity/docker/.docker-data/containers/74d10845428e786d18add1bda9dbafd27956dfccead504cf40fcfd5f7f83f27d/74d10845428e786d18add1bda9dbafd27956dfccead504cf40fcfd5f7f83f27d-json.log has been updated   {"id": "dockerlocal", "prospector": "file_prospector", "operation": "write", "source_name": "native::3539836-64768", "os_id": "3539836-64768", "new_path": "/home/commity/docker/.docker-data/containers/74d10845428e786d18add1bda9dbafd27956dfccead504cf40fcfd5f7f83f27d/74d10845428e786d18add1bda9dbafd27956dfccead504cf40fcfd5f7f83f27d-json.log", "old_path": "/home/commity/docker/.docker-data/containers/74d10845428e786d18add1bda9dbafd27956dfccead504cf40fcfd5f7f83f27d/74d10845428e786d18add1bda9dbafd27956dfccead504cf40fcfd5f7f83f27d-json.log"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3539836-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/prospector.go:188    File /home/commity/docker/.docker-data/containers/7afebae51b67dcdbcc6ef8d1efede58a9495c676972835bcb2fef980d445b324/7afebae51b67dcdbcc6ef8d1efede58a9495c676972835bcb2fef980d445b324-json.log has been updated   {"id": "dockerlocal", "prospector": "file_prospector", "operation": "write", "source_name": "native::3539839-64768", "os_id": "3539839-64768", "new_path": "/home/commity/docker/.docker-data/containers/7afebae51b67dcdbcc6ef8d1efede58a9495c676972835bcb2fef980d445b324/7afebae51b67dcdbcc6ef8d1efede58a9495c676972835bcb2fef980d445b324-json.log", "old_path": "/home/commity/docker/.docker-data/containers/7afebae51b67dcdbcc6ef8d1efede58a9495c676972835bcb2fef980d445b324/7afebae51b67dcdbcc6ef8d1efede58a9495c676972835bcb2fef980d445b324-json.log"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3539839-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:181  Stopped harvester for file      {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3539836-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/prospector.go:188    File /home/commity/docker/.docker-data/containers/ff7e95cda2a126931fa5d86237e88b9f44a0a3d30f57e6debdbdeecb1a4f32da/ff7e95cda2a126931fa5d86237e88b9f44a0a3d30f57e6debdbdeecb1a4f32da-json.log has been updated   {"id": "dockerlocal", "prospector": "file_prospector", "operation": "write", "source_name": "native::4207341-64768", "os_id": "4207341-64768", "new_path": "/home/commity/docker/.docker-data/containers/ff7e95cda2a126931fa5d86237e88b9f44a0a3d30f57e6debdbdeecb1a4f32da/ff7e95cda2a126931fa5d86237e88b9f44a0a3d30f57e6debdbdeecb1a4f32da-json.log", "old_path": "/home/commity/docker/.docker-data/containers/ff7e95cda2a126931fa5d86237e88b9f44a0a3d30f57e6debdbdeecb1a4f32da/ff7e95cda2a126931fa5d86237e88b9f44a0a3d30f57e6debdbdeecb1a4f32da-json.log"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4207341-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:181  Stopped harvester for file      {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4207341-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:181  Stopped harvester for file      {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3539839-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/prospector.go:188    File /home/commity/docker/.docker-data/containers/f1ee2bce0b1ed5c7d9714d0d3dd014b0c742efcca3787a69e0512f3b92cb744d/f1ee2bce0b1ed5c7d9714d0d3dd014b0c742efcca3787a69e0512f3b92cb744d-json.log has been updated   {"id": "dockerlocal", "prospector": "file_prospector", "operation": "write", "source_name": "native::3539835-64768", "os_id": "3539835-64768", "new_path": "/home/commity/docker/.docker-data/containers/f1ee2bce0b1ed5c7d9714d0d3dd014b0c742efcca3787a69e0512f3b92cb744d/f1ee2bce0b1ed5c7d9714d0d3dd014b0c742efcca3787a69e0512f3b92cb744d-json.log", "old_path": "/home/commity/docker/.docker-data/containers/f1ee2bce0b1ed5c7d9714d0d3dd014b0c742efcca3787a69e0512f3b92cb744d/f1ee2bce0b1ed5c7d9714d0d3dd014b0c742efcca3787a69e0512f3b92cb744d-json.log"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3539835-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/prospector.go:205    File /home/commity/docker/.docker-data/containers/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec-json.log has been removed   {"id": "dockerlocal", "prospector": "file_prospector", "operation": "delete", "source_name": "native::4194874-64768", "os_id": "4194874-64768", "old_path": "/home/commity/docker/.docker-data/containers/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec-json.log"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/prospector.go:236    Stopping harvester as file native::4194874-64768 has been removed and close.on_state_change.removed is enabled. {"id": "dockerlocal", "prospector": "file_prospector", "operation": "delete", "source_name": "native::4194874-64768", "os_id": "4194874-64768", "old_path": "/home/commity/docker/.docker-data/containers/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec-json.log"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/prospector.go:241    Remove state for file as file removed: /home/commity/docker/.docker-data/containers/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec-json.log  {"id": "dockerlocal", "prospector": "file_prospector", "operation": "delete", "source_name": "native::4194874-64768", "os_id": "4194874-64768", "old_path": "/home/commity/docker/.docker-data/containers/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec-json.log"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:181  Stopped harvester for file      {"id": "dockerlocal", "source": "filestream::dockerlocal::native::3539835-64768"}
2023-01-03T11:11:20.093+0100    INFO    [input.filestream]      filestream/input.go:321 Reader was closed. Closing.     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4194874-64768", "path": "/home/commity/docker/.docker-data/containers/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec-json.log", "state-id": "native::4194874-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      filestream/input.go:145 Closing reader of filestream    {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4194874-64768", "path": "/home/commity/docker/.docker-data/containers/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec/7c01ec6ec186458e9f818a82394e35245530ec537484b283b6d1a19aebf4c6ec-json.log", "state-id": "native::4194874-64768"}
2023-01-03T11:11:20.093+0100    DEBUG   [publisher]     pipeline/client.go:158  client: closing acker
2023-01-03T11:11:20.093+0100    DEBUG   [publisher]     pipeline/client.go:163  client: done closing acker
2023-01-03T11:11:20.093+0100    DEBUG   [publisher]     pipeline/client.go:165  client: unlink from queue
2023-01-03T11:11:20.093+0100    DEBUG   [publisher]     pipeline/client.go:187  client: cancelled 0 events
2023-01-03T11:11:20.093+0100    DEBUG   [publisher]     pipeline/client.go:167  client: done unlink
2023-01-03T11:11:20.093+0100    DEBUG   [publisher]     pipeline/client.go:170  client: closing processors
2023-01-03T11:11:20.093+0100    DEBUG   [publisher]     pipeline/client.go:175  client: done closing processors
2023-01-03T11:11:20.093+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:219  Stopped harvester for file      {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4194874-64768"}
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/prospector.go:205    File /home/commity/docker/.docker-data/containers/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95-json.log has been removed   {"id": "dockerlocal", "prospector": "file_prospector", "operation": "delete", "source_name": "native::4194830-64768", "os_id": "4194830-64768", "old_path": "/home/commity/docker/.docker-data/containers/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95-json.log"}
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:187  client: cancelled 0 events
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/prospector.go:236    Stopping harvester as file native::4194830-64768 has been removed and close.on_state_change.removed is enabled. {"id": "dockerlocal", "prospector": "file_prospector", "operation": "delete", "source_name": "native::4194830-64768", "os_id": "4194830-64768", "old_path": "/home/commity/docker/.docker-data/containers/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95-json.log"}
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:167  client: done unlink
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:170  client: closing processors
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/prospector.go:241    Remove state for file as file removed: /home/commity/docker/.docker-data/containers/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95-json.log  {"id": "dockerlocal", "prospector": "file_prospector", "operation": "delete", "source_name": "native::4194830-64768", "os_id": "4194830-64768", "old_path": "/home/commity/docker/.docker-data/containers/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95-json.log"}
2023-01-03T11:11:20.094+0100    INFO    [input.filestream]      filestream/input.go:321 Reader was closed. Closing.     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4194830-64768", "path": "/home/commity/docker/.docker-data/containers/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95-json.log", "state-id": "native::4194830-64768"}
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:158  client: closing acker
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:163  client: done closing acker
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:165  client: unlink from queue
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:187  client: cancelled 0 events
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:167  client: done unlink
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:175  client: done closing processors
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/input.go:145 Closing reader of filestream    {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4194830-64768", "path": "/home/commity/docker/.docker-data/containers/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95/a0085b4894f6fbc40fc863e044978d8763b45bdb7cfe539cdd8db4448144aa95-json.log", "state-id": "native::4194830-64768"}
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:170  client: closing processors
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:175  client: done closing processors
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:219  Stopped harvester for file      {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4194830-64768"}
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/prospector.go:205    File /home/commity/docker/.docker-data/containers/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e-json.log has been removed   {"id": "dockerlocal", "prospector": "file_prospector", "operation": "delete", "source_name": "native::4205639-64768", "os_id": "4205639-64768", "old_path": "/home/commity/docker/.docker-data/containers/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e-json.log"}
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/prospector.go:236    Stopping harvester as file native::4205639-64768 has been removed and close.on_state_change.removed is enabled. {"id": "dockerlocal", "prospector": "file_prospector", "operation": "delete", "source_name": "native::4205639-64768", "os_id": "4205639-64768", "old_path": "/home/commity/docker/.docker-data/containers/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e-json.log"}
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/prospector.go:241    Remove state for file as file removed: /home/commity/docker/.docker-data/containers/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e-json.log  {"id": "dockerlocal", "prospector": "file_prospector", "operation": "delete", "source_name": "native::4205639-64768", "os_id": "4205639-64768", "old_path": "/home/commity/docker/.docker-data/containers/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e-json.log"}
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:158  client: closing acker
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:163  client: done closing acker
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:165  client: unlink from queue
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:187  client: cancelled 0 events
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:167  client: done unlink
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:170  client: closing processors
2023-01-03T11:11:20.094+0100    DEBUG   [publisher]     pipeline/client.go:175  client: done closing processors
2023-01-03T11:11:20.094+0100    INFO    [input.filestream]      filestream/input.go:321 Reader was closed. Closing.     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4205639-64768", "path": "/home/commity/docker/.docker-data/containers/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e-json.log", "state-id": "native::4205639-64768"}
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:219  Stopped harvester for file      {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4205639-64768"}
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/input.go:145 Closing reader of filestream    {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4205639-64768", "path": "/home/commity/docker/.docker-data/containers/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e/611c2e267cd83722f629ca2c08828675dcfdc7554202c10cb2329e7d3ed62d1e-json.log", "state-id": "native::4205639-64768"}
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/prospector.go:180    A new file /home/commity/docker/.docker-data/containers/13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68/13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68-json.log has been found       {"id": "dockerlocal", "prospector": "file_prospector", "operation": "create", "source_name": "native::4205638-64768", "os_id": "4205638-64768", "new_path": "/home/commity/docker/.docker-data/containers/13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68/13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68-json.log"}
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4205638-64768"}
2023-01-03T11:11:20.094+0100    DEBUG   [input.filestream]      filestream/prospector.go:180    A new file /home/commity/docker/.docker-data/containers/7d4ff7349e0056c8fbebf18f8ccd4b765f87ef3ef05afc379898082886490a92/7d4ff7349e0056c8fbebf18f8ccd4b765f87ef3ef05afc379898082886490a92-json.log has been found       {"id": "dockerlocal", "prospector": "file_prospector", "operation": "create", "source_name": "native::4194832-64768", "os_id": "4194832-64768", "new_path": "/home/commity/docker/.docker-data/containers/7d4ff7349e0056c8fbebf18f8ccd4b765f87ef3ef05afc379898082886490a92/7d4ff7349e0056c8fbebf18f8ccd4b765f87ef3ef05afc379898082886490a92-json.log"}
2023-01-03T11:11:20.095+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4194832-64768"}
2023-01-03T11:11:20.095+0100    DEBUG   [input.filestream]      filestream/prospector.go:180    A new file /home/commity/docker/.docker-data/containers/e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96/e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96-json.log has been found       {"id": "dockerlocal", "prospector": "file_prospector", "operation": "create", "source_name": "native::4194878-64768", "os_id": "4194878-64768", "new_path": "/home/commity/docker/.docker-data/containers/e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96/e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96-json.log"}
2023-01-03T11:11:20.095+0100    DEBUG   [input.filestream]      input-logfile/harvester.go:145  Starting harvester for file     {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4194878-64768"}
2023-01-03T11:11:20.095+0100    DEBUG   [input.filestream]      filestream/input.go:176 newLogFileReader with config.MaxBytes:10485760  {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4205638-64768", "path": "/home/commity/docker/.docker-data/containers/13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68/13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68-json.log", "state-id": "native::4205638-64768"}
2023-01-03T11:11:20.095+0100    INFO    [detect_null_bytes]     debug/debug.go:95       Starting debug reader with a buffer size of 16384 and max failures of 100
2023-01-03T11:11:20.095+0100    DEBUG   [input.filestream]      filestream/input.go:176 newLogFileReader with config.MaxBytes:10485760  {"id": "dockerlocal", "source": "filestream::dockerlocal::native::4194878-64768", "path": "/home/commity/docker/.docker-data/containers/e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96/e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96-json.log", "state-id": "native::4194878-64768"}
2023-01-03T11:11:20.095+0100    DEBUG   [add_docker_metadata]   add_docker_metadata/add_docker_metadata.go:210  Container not found: cid=13fe24fd36147ad00c08a788a29b24306354240406cdd926c868a39ffd0aff68
2023-01-03T11:11:20.095+0100    INFO    [detect_null_bytes]     debug/debug.go:95       Starting debug reader with a buffer size of 16384 and max failures of 100
2023-01-03T11:11:20.095+0100    DEBUG   [add_docker_metadata]   add_docker_metadata/add_docker_metadata.go:210  Container not found: cid=e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96
2023-01-03T11:11:20.095+0100    DEBUG   [file_watcher]  filestream/fswatch.go:212       Found 50 paths
2023-01-03T11:11:20.095+0100    DEBUG   [processors]    processing/processors.go:203    Publish event: {
  "@timestamp": "2023-01-03T10:11:20.095Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.17.8"
  },
  "time": "2023-01-03T10:11:19.865943279Z",
  "ecs": {
    "version": "1.12.0"
  },
  "host": {
    "name": "commity-test1"
  },
  "origin": {
    "offset": 0,
    "file": {
      "path": "/home/commity/docker/.docker-data/containers/e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96/e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96-json.log"
    }
  },
  "input": {
    "type": "filestream"
  },
  "container": {
    "id": "e41a8620daf277628de0827f8a5992ad9601457ec0df49dd6e3d5febf04f2b96"
  },
  "log": "11:11:18,787 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.4\n",
  "stream": "stdout",
  "agent": {
    "name": "commity-test1",
    "type": "filebeat",
    "version": "7.17.8",
    "hostname": "commity-test1",
    "ephemeral_id": "38fcb797-886f-4732-9a88-3190fea5117b",
    "id": "89e0dbf2-474b-4524-b01f-df9b2d31d59f"
  },
  "message": "{\"log\":\"11:11:18,787 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.4.4\\n\",\"stream\":\"stdout\",\"time\":\"2023-01-03T10:11:19.865943279Z\"}"
}

Thank you for any advice how to solve this issue.

Can confirm that we have the same issue here.

  1. Start filebeat
  2. Collect docker logs with metadata (everything works fine)
  3. Restart docker container
  4. Collect docker logs, without metadata. We get the same error that the container is not found. Even though the log file exists matching the path with this container id.

If we restart filebeat the metadata is correctly collected again. However it is far from ideal to have to restart filebeat every time a container is restarted.

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