Renaming a log file causes loss of events added after harvester was closed

[Vanav]

If log was inactive for 5 minutes, harvester is closed, then I add lines to log and rename it before new lines are harvested, then these lines are lost. This is an often case for log rotation, and harvester can't be opened for all logs all the time. Filebeat should be able to detect changes, because it correctly detects a file rename, and new file name is also tracked in paths. And documentation says that is should work correctly:

By default, Filebeat is able to track files correctly in the following strategies:

• create: new active file with a unique name is created on rotation
• rename: rotated files are renamed

Test:

1. Create log file. Data is collected correctly.

echo 'Test070 before rotation - data data data data data data data data' >> /var/log/app/app.log

2. Wait 5 minutes to close harvester.
3. Add new line to log, rename file, add another line to test. New lines before rename are never collected.

echo 'Test071 before rotation - data data data data data data data data' >> /var/log/app/app.log
mv /var/log/app/app.log /var/log/app/app.log.1
echo 'Test072 after rotation - data data data data data data data data' >> /var/log/app/app.log

Messages Test070 and Test072 are collected, message Test071 is lost.

Log:

{"log.level":"debug","@timestamp":"2024-05-24T16:17:16.360Z","message":"A new file /var/log/app/app.log has been found","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"source_name":"native::524316-2049","os_id":"524316-2049","new_path":"/var/log/app/app.log","ecs.version":"1.6.0","log.origin":{"file.line":179,"file.name":"filestream/prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*fileProspector).onFSEvent"},"operation":"create","log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","prospector":"file_prospector","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:17:16.360Z","message":"Starting harvester for file","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"source_file":"filestream::your-filestream-stream-id::native::524316-2049","log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","log.origin":{"file.line":139,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.(*defaultHarvesterGroup).Start"},"ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:17:16.361Z","message":"newLogFileReader with config.MaxBytes:10485760","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"source_file":"filestream::your-filestream-stream-id::native::524316-2049","path":"/var/log/app/app.log","ecs.version":"1.6.0","log.logger":"input.filestream","log.origin":{"file.line":185,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).open"},"service.name":"filebeat","id":"your-filestream-stream-id","state-id":"native::524316-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:17:18.342Z","message":"End of file reached: /var/log/app/app.log; Backoff now.","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"source_file":"filestream::your-filestream-stream-id::native::524316-2049","ecs.version":"1.6.0","log.logger":"input.filestream","log.origin":{"file.line":131,"file.name":"filestream/filestream.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*logFile).Read"},"service.name":"filebeat","id":"your-filestream-stream-id","path":"/var/log/app/app.log","state-id":"native::524316-2049","ecs.version":"1.6.0"}
...
{"log.level":"info","@timestamp":"2024-05-24T16:22:22.353Z","message":"Reader was closed. Closing. Path='/var/log/app/app.log'","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524316-2049","path":"/var/log/app/app.log","ecs.version":"1.6.0","log.origin":{"file.line":336,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).readFromSource"},"service.name":"filebeat","state-id":"native::524316-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:22:22.353Z","message":"Stopped harvester for file","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.origin":{"file.line":247,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.startHarvester.func1"},"ecs.version":"1.6.0","log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524316-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:22:22.354Z","message":"Closing reader of filestream","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"ecs.version":"1.6.0","log.logger":"input.filestream","log.origin":{"file.line":151,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).Run.func1"},"id":"your-filestream-stream-id","state-id":"native::524316-2049","service.name":"filebeat","source_file":"filestream::your-filestream-stream-id::native::524316-2049","path":"/var/log/app/app.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:27:36.360Z","message":"File /var/log/app/app.log has been renamed to /var/log/app/app.log.1","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"operation":"rename","source_name":"native::524316-2049","new_path":"/var/log/app/app.log.1","ecs.version":"1.6.0","log.origin":{"file.line":215,"file.name":"filestream/prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*fileProspector).onFSEvent"},"os_id":"524316-2049","service.name":"filebeat","prospector":"file_prospector","id":"your-filestream-stream-id","log.logger":"input.filestream","old_path":"/var/log/app/app.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:27:36.360Z","message":"A new file /var/log/app/app.log has been found","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.origin":{"file.line":179,"file.name":"filestream/prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*fileProspector).onFSEvent"},"service.name":"filebeat","ecs.version":"1.6.0","source_name":"native::524329-2049","log.logger":"input.filestream","id":"your-filestream-stream-id","prospector":"file_prospector","operation":"create","os_id":"524329-2049","new_path":"/var/log/app/app.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:27:36.360Z","message":"Starting harvester for file","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"source_file":"filestream::your-filestream-stream-id::native::524329-2049","log.origin":{"file.line":139,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.(*defaultHarvesterGroup).Start"},"id":"your-filestream-stream-id","ecs.version":"1.6.0","log.logger":"input.filestream","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:27:36.360Z","message":"newLogFileReader with config.MaxBytes:10485760","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"ecs.version":"1.6.0","log.logger":"input.filestream","log.origin":{"file.line":185,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).open"},"service.name":"filebeat","path":"/var/log/app/app.log","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524329-2049","state-id":"native::524329-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T16:27:36.361Z","message":"End of file reached: /var/log/app/app.log; Backoff now.","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"ecs.version":"1.6.0","log.logger":"input.filestream","log.origin":{"file.line":131,"file.name":"filestream/filestream.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*logFile).Read"},"id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524329-2049","service.name":"filebeat","path":"/var/log/app/app.log","state-id":"native::524329-2049","ecs.version":"1.6.0"}

Cursor is not moved to follow new lines. Renamed file (524316-2049) recorded "offset":66, but actually it is twice larger, with new event Test071 that is never collected. /var/lib/elastic-agent/data/elastic-agent-8.13.4-a2e31a/run/filestream-default/registry/filebeat/log.json:

{"op":"set","id":1}
{"k":"filestream::your-filestream-stream-id::native::524316-2049","v":{"ttl":0,"updated":[281470681743360,18446744011573954816],"cursor":null,"meta":{"source":"/var/log/app/app.log","identifier_name":"native"}}}
{"op":"set","id":2}
{"k":"filestream::your-filestream-stream-id::native::524316-2049","v":{"updated":[361769704,1716567436],"cursor":null,"meta":{"source":"/var/log/app/app.log","identifier_name":"native"},"ttl":1800000000000}}
{"op":"set","id":3}
{"k":"filestream::your-filestream-stream-id::native::524316-2049","v":{"ttl":1800000000000,"updated":[361911179,1716567436],"cursor":{"offset":66},"meta":{"identifier_name":"native","source":"/var/log/app/app.log"}}}
{"op":"set","id":4}
{"k":"filestream::your-filestream-stream-id::native::524316-2049","v":{"ttl":1800000000000,"updated":[361911179,1716567436],"cursor":{"offset":66},"meta":{"identifier_name":"native","source":"/var/log/app/app.log.1"}}}
{"op":"set","id":5}
{"k":"filestream::your-filestream-stream-id::native::524329-2049","v":{"ttl":0,"updated":[281470681743360,18446744011573954816],"cursor":null,"meta":{"source":"/var/log/app/app.log","identifier_name":"native"}}}
{"op":"set","id":6}
{"k":"filestream::your-filestream-stream-id::native::524329-2049","v":{"updated":[360958579,1716568056],"cursor":null,"meta":{"source":"/var/log/app/app.log","identifier_name":"native"},"ttl":1800000000000}}
{"op":"set","id":7}
{"k":"filestream::your-filestream-stream-id::native::524329-2049","v":{"ttl":1800000000000,"updated":[361037895,1716568056],"cursor":{"offset":65},"meta":{"source":"/var/log/app/app.log","identifier_name":"native"}}}

`"offset":66` - is an offset before adding first new line to file. So offset is never moved to a new line, and event "Test071" is lost.

But if I update the renamed file, then harvester will open, and all lines, old and new, will be harvested:

echo 'Test073 after rotation - data data data data data data data data' >> app.log.1

Now both events "Test071" and "Test073" will appear in one time.

/etc/elastic-agent/elastic-agent.yml:

inputs:
- type: filestream
  id: your-input-id
  streams:
  - id: your-filestream-stream-id
    data_stream:
      dataset: generic
    paths:
    - /var/log/app/app.log
    - /var/log/app/app.log*[0-9]

elastic-agent v8.13.4 deb package, Ubuntu v22 and v24, ext4 file system.

I've tried close.on_state_change.renamed: true, and I've tried fingerprint mode, but no difference.

I think that it is normal that harvesters are closed from time to time to free resources. Is there any workaround to not loss events in this case?