Filebeat does not handle the OS open file limit correctly

[rdner]

I tried to ingest 250 files (1000 lines each) on Mac 13.2.1 with the following configuration:

First run: log input

filebeat.inputs:
  - type: log
    paths:
      - "{{ROOT}}/logs/file*.log"
path.data: "{{ROOT}}/data-log"
# logging:
#   level: debug
output.file:
  rotate_every_kb: 10485760 # 10GB
  path: "{{ROOT}}/out/log"
  filename: output.json

Second run: filestream input

filebeat.inputs:
  - type: filestream
    id: my-filestream-id
    enabled: true
    paths:
      - "{{ROOT}}/logs/file*.log"
path.data: "{{ROOT}}/data-fs"
output.file:
  rotate_every_kb: 10485760 # 10GB
  path: "{{ROOT}}/out/fs"
  filename: output.json

I found that for this file count neither log input nor filestream can finish ingesting the files. However, they fail to do so differently:

The log input starts logging these messages and drops the files completely, which leads to data loss.

{
  "log.level": "error",
  "@timestamp": "2023-03-06T11:18:45.840+0100",
  "log.logger": "input",
  "log.origin": {
    "file.name": "log/input.go",
    "file.line": 556
  },
  "message": "Harvester could not be started on new file: /Users/rdner/Projects/es_confs/load-log-vs-fs/logs/file777.log, Err: error setting up harvester: Harvester setup failed. Unexpected file opening error: Failed opening /Users/rdner/Projects/es_confs/load-log-vs-fs/logs/file777.log: open /Users/rdner/Projects/es_confs/load-log-vs-fs/logs/file777.log: too many open files",
  "service.name": "filebeat",
  "input_id": "d9d6ec66-5381-4f4c-adba-e5221ed3ad6c",
  "source_file": "/Users/rdner/Projects/es_confs/load-log-vs-fs/logs/file777.log",
  "state_id": "native::102548165-16777230",
  "finished": false,
  "os_id": "102548165-16777230",
  "ecs.version": "1.6.0"
}

The filestream input logs this error:

{
  "log.level": "error",
  "@timestamp": "2023-03-06T15:37:54.647+0100",
  "log.logger": "input.filestream",
  "log.origin": {
    "file.name": "filestream/input.go",
    "file.line": 140
  },
  "message": "File could not be opened for reading: failed opening /Users/rdner/Projects/es_confs/load-log-vs-fs/logs/file58.log: open /Users/rdner/Projects/es_confs/load-log-vs-fs/logs/file58.log: too many open files",
  "service.name": "filebeat",
  "id": "my-filestream-id",
  "source_file": "filestream::my-filestream-id::native::102589522-16777232",
  "path": "/Users/rdner/Projects/es_confs/load-log-vs-fs/logs/file58.log",
  "state-id": "native::102589522-16777232",
  "ecs.version": "1.6.0"
}

and it gets stuck in this loop of re-ingesting already sent data. Which leads to data duplication and I believe filestream would not recover from this unless restarted and will keep re-sending all the data again and again. I left it running for 30 minutes on my machine and it duplicated the same message thousands of times.

This happens only when the amount of files being ingested exceeds the OS open file limit, which happens to be only 256 for Mac OS.

The expected behaviour would be that Filebeat queues the files perhaps based on the modified date. In this case we have to periodically close the files we already ingest to decrease the open file counter.

It's not trivial to come up with the right strategy but we need to handle this OS limit better than we do now.

[elasticmachine]

Pinging @elastic/elastic-agent-data-plane (Team:Elastic-Agent-Data-Plane)

[botelastic]

Hi!
We just realized that we haven't looked into this issue in a while. We're sorry!

We're labeling this issue as Stale to make it hit our filters and make sure we get back to it as soon as possible. In the meantime, it'd be extremely helpful if you could take a look at it as well and confirm its relevance. A simple comment with a nice emoji will be enough :+1.
Thank you for your contribution!