search

elastic / beats

:tropical_fish: Beats - Lightweight shippers for Elasticsearch & Logstash
https://www.elastic.co/products/beats
Other
12.13k stars 4.91k forks source link

copytruncate strategy causes full log duplication on rotation #39731

Open Vanav opened 3 months ago

Vanav commented 3 months ago

When I use copytruncate strategy, then on rotation full log file is duplicated and events are sent again.

Test 1

  1. No log files, create one file, data will be collected correctly: 
    echo 'Test001 log rotation - data data data data data data data data' >> app.log
  2. Rotate log with copythuncate method: 
    logrotate -f /etc/logrotate.conf
  3. Now full log file content will be collected second time.

Log:

{"log.level":"debug","@timestamp":"2024-05-24T19:49:42.642Z","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":249,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"operation":"create","ecs.version":"1.6.0","service.name":"filebeat","prospector":"copy_truncate_file_prospector","log.logger":"input.filestream","id":"your-filestream-stream-id","source_name":"native::524336-2049","os_id":"524336-2049","new_path":"/var/log/app/app.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:49:42.642Z","message":"File /var/log/app/app.log is original","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"service.name":"filebeat","prospector":"copy_truncate_file_prospector","operation":"create","log.origin":{"file.line":272,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"id":"your-filestream-stream-id","log.logger":"input.filestream","source_name":"native::524336-2049","os_id":"524336-2049","new_path":"/var/log/app/app.log","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:49:42.642Z","message":"Starting harvester for file","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524336-2049","ecs.version":"1.6.0","log.logger":"input.filestream","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"},"service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:49:42.643Z","message":"newLogFileReader with config.MaxBytes:10485760","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524336-2049","state-id":"native::524336-2049","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","ecs.version":"1.6.0","log.logger":"input.filestream","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:49:42.643Z","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"},"path":"/var/log/app/app.log","ecs.version":"1.6.0","service.name":"filebeat","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524336-2049","state-id":"native::524336-2049","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"},"ecs.version":"1.6.0"}

Here log file is collected and sent for the first time:

log.file.inode = 524336
log.file.path = /var/log/app/app.log
message = Test001 log rotation - data data data data data data data data

Continue of log:

{"log.level":"debug","@timestamp":"2024-05-24T19:50:16.645Z","message":"File was truncated as offset (65) > size (0): /var/log/app/app.log","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"ecs.version":"1.6.0","log.origin":{"file.line":259,"file.name":"filestream/filestream.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*logFile).handleEOF"},"service.name":"filebeat","id":"your-filestream-stream-id","path":"/var/log/app/app.log","log.logger":"input.filestream","source_file":"filestream::your-filestream-stream-id::native::524336-2049","state-id":"native::524336-2049","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2024-05-24T19:50:16.646Z","message":"File was truncated, nothing to read. Path='/var/log/app/app.log'","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"service.name":"filebeat","path":"/var/log/app/app.log","ecs.version":"1.6.0","source_file":"filestream::your-filestream-stream-id::native::524336-2049","state-id":"native::524336-2049","log.logger":"input.filestream","log.origin":{"file.line":334,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).readFromSource"},"id":"your-filestream-stream-id","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:16.646Z","message":"Stopped harvester for file","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","service.name":"filebeat","source_file":"filestream::your-filestream-stream-id::native::524336-2049","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"},"id":"your-filestream-stream-id","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:16.646Z","message":"Closing reader of filestream","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"path":"/var/log/app/app.log","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","source_file":"filestream::your-filestream-stream-id::native::524336-2049","state-id":"native::524336-2049","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:22.642Z","message":"File /var/log/app/app.log has been truncated","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"source_name":"native::524336-2049","os_id":"524336-2049","prospector":"copy_truncate_file_prospector","old_path":"/var/log/app/app.log","ecs.version":"1.6.0","id":"your-filestream-stream-id","operation":"truncate","new_path":"/var/log/app/app.log","log.logger":"input.filestream","log.origin":{"file.line":280,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:22.642Z","message":"Restarting harvester for file","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","log.origin":{"file.line":156,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.(*defaultHarvesterGroup).Restart"},"service.name":"filebeat","ecs.version":"1.6.0","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524336-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:22.642Z","message":"A new file /var/log/app/app.log.1 has been found","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","service.name":"filebeat","id":"your-filestream-stream-id","os_id":"524337-2049","log.origin":{"file.line":249,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"prospector":"copy_truncate_file_prospector","operation":"create","source_name":"native::524337-2049","new_path":"/var/log/app/app.log.1","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:22.642Z","message":"File /var/log/app/app.log.1 is rotated","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"prospector":"copy_truncate_file_prospector","source_name":"native::524337-2049","id":"your-filestream-stream-id","operation":"create","os_id":"524337-2049","log.logger":"input.filestream","new_path":"/var/log/app/app.log.1","log.origin":{"file.line":267,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"service.name":"filebeat","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:22.642Z","message":"Continue harvester for file prev=native::524336-2049, next=native::524337-2049","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","log.origin":{"file.line":253,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.(*defaultHarvesterGroup).Continue"},"service.name":"filebeat","id":"your-filestream-stream-id","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:22.642Z","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::524337-2049","ecs.version":"1.6.0","id":"your-filestream-stream-id","log.logger":"input.filestream","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"},"service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:22.642Z","message":"newLogFileReader with config.MaxBytes:10485760","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"service.name":"filebeat","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524337-2049","path":"/var/log/app/app.log.1","state-id":"native::524337-2049","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"},"ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:22.643Z","message":"newLogFileReader with config.MaxBytes:10485760","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"state-id":"native::524336-2049","log.origin":{"file.line":185,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).open"},"service.name":"filebeat","source_file":"filestream::your-filestream-stream-id::native::524336-2049","path":"/var/log/app/app.log","log.logger":"input.filestream","id":"your-filestream-stream-id","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:50:22.643Z","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"},"log.logger":"input.filestream","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524336-2049","path":"/var/log/app/app.log","ecs.version":"1.6.0","service.name":"filebeat","state-id":"native::524336-2049","log.origin":{"file.line":131,"file.name":"filestream/filestream.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*logFile).Read"},"ecs.version":"1.6.0"}

Here log file is collected and sent for the second time:

log.file.inode = 524337
log.file.path = /var/log/app/app.log.1
message = Test001 log rotation - data data data data data data data data

Test 2

Now we'll continue the test, we will have the same bug, but different timing and locks introduced.

  1. Two log files are already harvesting, add new data, data will be collected correctly: 
    echo 'Test002 log rotation - data data data data data data data data' >> app.log
  2. Rotate log with copythuncate method: 
    logrotate -f /etc/logrotate.conf
  3. Wait for 5 minutes (till app.log harvester is closed and released lock) and now full log file content will be collected second time, duplicated again.

Log:

{"log.level":"debug","@timestamp":"2024-05-24T19:53:22.642Z","message":"File /var/log/app/app.log has been updated","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"service.name":"filebeat","id":"your-filestream-stream-id","prospector":"copy_truncate_file_prospector","source_name":"native::524336-2049","os_id":"524336-2049","ecs.version":"1.6.0","log.origin":{"file.line":251,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"old_path":"/var/log/app/app.log","log.logger":"input.filestream","operation":"write","new_path":"/var/log/app/app.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:53:22.642Z","message":"File /var/log/app/app.log is original","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"operation":"write","id":"your-filestream-stream-id","log.origin":{"file.line":272,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"old_path":"/var/log/app/app.log","service.name":"filebeat","prospector":"copy_truncate_file_prospector","source_name":"native::524336-2049","os_id":"524336-2049","new_path":"/var/log/app/app.log","ecs.version":"1.6.0","log.logger":"input.filestream","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:53:22.642Z","message":"Starting harvester for file","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"service.name":"filebeat","id":"your-filestream-stream-id","log.logger":"input.filestream","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","source_file":"filestream::your-filestream-stream-id::native::524336-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:53:22.642Z","message":"Stopped harvester for file","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","log.origin":{"file.line":205,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.startHarvester.func1"},"id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524336-2049","ecs.version":"1.6.0","service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:53:22.657Z","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"},"log.logger":"input.filestream","source_file":"filestream::your-filestream-stream-id::native::524336-2049","state-id":"native::524336-2049","id":"your-filestream-stream-id","path":"/var/log/app/app.log","ecs.version":"1.6.0","log.origin":{"file.line":131,"file.name":"filestream/filestream.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*logFile).Read"},"service.name":"filebeat","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:53:26.657Z","message":"End of file reached: /var/log/app/app.log.1; Backoff now.","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","service.name":"filebeat","state-id":"native::524337-2049","ecs.version":"1.6.0","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::524337-2049","path":"/var/log/app/app.log.1","ecs.version":"1.6.0"}

Here log line is collected for the first time:

log.file.inode = 524336
log.file.path = /var/log/app/app.log
message = Test002 log rotation - data data data data data data data data

Continue of log:

{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.642Z","message":"File /var/log/app/app.log has been truncated","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"ecs.version":"1.6.0","new_path":"/var/log/app/app.log","service.name":"filebeat","prospector":"copy_truncate_file_prospector","id":"your-filestream-stream-id","operation":"truncate","os_id":"524336-2049","log.logger":"input.filestream","log.origin":{"file.line":280,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"source_name":"native::524336-2049","old_path":"/var/log/app/app.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.642Z","message":"Restarting harvester for file","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"service.name":"filebeat","id":"your-filestream-stream-id","log.logger":"input.filestream","log.origin":{"file.line":156,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.(*defaultHarvesterGroup).Restart"},"source_file":"filestream::your-filestream-stream-id::native::524336-2049","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.642Z","message":"File /var/log/app/app.log.1 has been removed","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"source_name":"native::524337-2049","operation":"delete","ecs.version":"1.6.0","log.origin":{"file.line":289,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"prospector":"copy_truncate_file_prospector","old_path":"/var/log/app/app.log.1","log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","os_id":"524337-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.642Z","message":"Stopping harvester as file native::524337-2049 has been removed and close.on_state_change.removed is enabled.","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"prospector":"copy_truncate_file_prospector","ecs.version":"1.6.0","log.logger":"input.filestream","log.origin":{"file.line":241,"file.name":"filestream/prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*fileProspector).onRemove"},"service.name":"filebeat","operation":"delete","source_name":"native::524337-2049","os_id":"524337-2049","id":"your-filestream-stream-id","old_path":"/var/log/app/app.log.1","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.642Z","message":"Remove state for file as file removed: /var/log/app/app.log.1","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"service.name":"filebeat","old_path":"/var/log/app/app.log.1","log.logger":"input.filestream","prospector":"copy_truncate_file_prospector","source_name":"native::524337-2049","log.origin":{"file.line":246,"file.name":"filestream/prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*fileProspector).onRemove"},"id":"your-filestream-stream-id","operation":"delete","os_id":"524337-2049","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2024-05-24T19:54:12.643Z","message":"Resource 'filestream::your-filestream-stream-id::native::524336-2049' currently in use, waiting...","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"source_file":"filestream::your-filestream-stream-id::native::524336-2049","log.origin":{"file.line":319,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.lockResource"},"service.name":"filebeat","id":"your-filestream-stream-id","log.logger":"input.filestream","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.643Z","message":"A new file /var/log/app/app.log.1 has been found","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.origin":{"file.line":249,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"service.name":"filebeat","operation":"create","source_name":"native::524338-2049","prospector":"copy_truncate_file_prospector","os_id":"524338-2049","new_path":"/var/log/app/app.log.1","ecs.version":"1.6.0","log.logger":"input.filestream","id":"your-filestream-stream-id","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.643Z","message":"File /var/log/app/app.log.1 is rotated","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"prospector":"copy_truncate_file_prospector","service.name":"filebeat","id":"your-filestream-stream-id","new_path":"/var/log/app/app.log.1","ecs.version":"1.6.0","log.logger":"input.filestream","operation":"create","os_id":"524338-2049","log.origin":{"file.line":267,"file.name":"filestream/copytruncate_prospector.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*copyTruncateFileProspector).onFSEvent"},"source_name":"native::524338-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.643Z","message":"Continue harvester for file prev=native::524336-2049, next=native::524338-2049","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","log.origin":{"file.line":253,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.(*defaultHarvesterGroup).Continue"},"service.name":"filebeat","id":"your-filestream-stream-id","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2024-05-24T19:54:12.643Z","message":"Resource 'filestream::your-filestream-stream-id::native::524336-2049' currently in use, waiting...","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","log.origin":{"file.line":319,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.lockResource"},"service.name":"filebeat","id":"your-filestream-stream-id","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2024-05-24T19:54:12.643Z","message":"Reader was closed. Closing. Path='/var/log/app/app.log.1'","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524337-2049","path":"/var/log/app/app.log.1","state-id":"native::524337-2049","log.origin":{"file.line":336,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).readFromSource"},"ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.643Z","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"},"source_file":"filestream::your-filestream-stream-id::native::524337-2049","ecs.version":"1.6.0","log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.643Z","message":"Closing reader of filestream","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.origin":{"file.line":151,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).Run.func1"},"service.name":"filebeat","state-id":"native::524337-2049","ecs.version":"1.6.0","log.logger":"input.filestream","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524337-2049","path":"/var/log/app/app.log.1","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2024-05-24T19:54:12.643Z","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"},"source_file":"filestream::your-filestream-stream-id::native::524336-2049","path":"/var/log/app/app.log","state-id":"native::524336-2049","log.logger":"input.filestream","log.origin":{"file.line":336,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).readFromSource"},"ecs.version":"1.6.0","service.name":"filebeat","id":"your-filestream-stream-id","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.643Z","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"},"source_file":"filestream::your-filestream-stream-id::native::524336-2049","log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2024-05-24T19:54:12.643Z","message":"Resource 'filestream::your-filestream-stream-id::native::524336-2049' finally released. Lock acquired","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","log.origin":{"file.line":321,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.lockResource"},"service.name":"filebeat","ecs.version":"1.6.0","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524336-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.643Z","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","path":"/var/log/app/app.log","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","source_file":"filestream::your-filestream-stream-id::native::524336-2049","state-id":"native::524336-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.643Z","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"},"service.name":"filebeat","id":"your-filestream-stream-id","state-id":"native::524336-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"},"source_file":"filestream::your-filestream-stream-id::native::524336-2049","path":"/var/log/app/app.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:12.643Z","message":"Closing reader of filestream","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"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"},"service.name":"filebeat","state-id":"native::524336-2049","ecs.version":"1.6.0","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524336-2049","path":"/var/log/app/app.log","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:54:14.643Z","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::524336-2049","path":"/var/log/app/app.log","state-id":"native::524336-2049","log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","ecs.version":"1.6.0","log.origin":{"file.line":131,"file.name":"filestream/filestream.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*logFile).Read"},"ecs.version":"1.6.0"}

Notice, that the same lock id required twice ("@timestamp":"2024-05-24T19:54:12.643Z","message":"Resource 'filestream::your-filestream-stream-id::native::524336-2049' currently in use, waiting..."), one lock released fast, second lock will be released 5 minutes later (after harvester is closed):

{"log.level":"info","@timestamp":"2024-05-24T19:59:16.663Z","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.origin":{"file.line":336,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).readFromSource"},"id":"your-filestream-stream-id","path":"/var/log/app/app.log","log.logger":"input.filestream","service.name":"filebeat","source_file":"filestream::your-filestream-stream-id::native::524336-2049","state-id":"native::524336-2049","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:59:16.663Z","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"},"service.name":"filebeat","source_file":"filestream::your-filestream-stream-id::native::524336-2049","ecs.version":"1.6.0","log.logger":"input.filestream","id":"your-filestream-stream-id","ecs.version":"1.6.0"}
{"log.level":"info","@timestamp":"2024-05-24T19:59:16.663Z","message":"Resource 'filestream::your-filestream-stream-id::native::524336-2049' finally released. Lock acquired","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","log.origin":{"file.line":321,"file.name":"input-logfile/harvester.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream/internal/input-logfile.lockResource"},"service.name":"filebeat","id":"your-filestream-stream-id","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:59:16.663Z","message":"Starting harvester for file","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","source_file":"filestream::your-filestream-stream-id::native::524338-2049","ecs.version":"1.6.0","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"},"service.name":"filebeat","id":"your-filestream-stream-id","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:59:16.663Z","message":"newLogFileReader with config.MaxBytes:10485760","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.origin":{"file.line":185,"file.name":"filestream/input.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*filestream).open"},"source_file":"filestream::your-filestream-stream-id::native::524338-2049","log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","path":"/var/log/app/app.log.1","state-id":"native::524338-2049","ecs.version":"1.6.0","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:59:16.664Z","message":"Closing reader of filestream","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524336-2049","path":"/var/log/app/app.log","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"},"service.name":"filebeat","state-id":"native::524336-2049","ecs.version":"1.6.0"}
{"log.level":"debug","@timestamp":"2024-05-24T19:59:16.664Z","message":"End of file reached: /var/log/app/app.log.1; Backoff now.","component":{"binary":"filebeat","dataset":"elastic_agent.filebeat","id":"filestream-default","type":"filestream"},"log":{"source":"filestream-default"},"log.logger":"input.filestream","service.name":"filebeat","id":"your-filestream-stream-id","source_file":"filestream::your-filestream-stream-id::native::524338-2049","path":"/var/log/app/app.log.1","ecs.version":"1.6.0","log.origin":{"file.line":131,"file.name":"filestream/filestream.go","function":"github.com/elastic/beats/v7/filebeat/input/filestream.(*logFile).Read"},"state-id":"native::524338-2049","ecs.version":"1.6.0"}

Here the same log file is collected for a second time:

log.file.inode = 524338
log.file.path = /var/log/app/app.log.1
message = Test002 log rotation - data data data data data data data data

Configs, registry and environment

/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::524336-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::524336-2049","v":{"cursor":null,"meta":{"source":"/var/log/app/app.log","identifier_name":"native"},"ttl":1800000000000,"updated":[643023359,1716580182]}} {"op":"set","id":3} {"k":"filestream::your-filestream-stream-id::native::524336-2049","v":{"cursor":{"offset":65},"meta":{"source":"/var/log/app/app.log","identifier_name":"native"},"ttl":1800000000000,"updated":[643088472,1716580182]}} {"op":"set","id":4} {"k":"filestream::your-filestream-stream-id::native::524336-2049","v":{"ttl":1800000000000,"updated":[643088472,1716580182],"cursor":{"offset":0},"meta":{"source":"/var/log/app/app.log","identifier_name":"native"}}} {"op":"set","id":5} {"k":"filestream::your-filestream-stream-id::native::524337-2049","v":{"ttl":0,"updated":[281470681743360,18446744011573954816],"cursor":null,"meta":{"source":"/var/log/app/app.log.1","identifier_name":"native"}}} {"op":"set","id":6} {"k":"filestream::your-filestream-stream-id::native::524336-2049","v":{"meta":{"source":"/var/log/app/app.log","identifier_name":"native"},"ttl":0,"updated":[643088472,1716580182],"cursor":{"offset":0}}} {"op":"set","id":7} {"k":"filestream::your-filestream-stream-id::native::524337-2049","v":{"updated":[642796274,1716580222],"cursor":null,"meta":{"source":"/var/log/app/app.log.1","identifier_name":"native"},"ttl":1800000000000}} {"op":"set","id":8} {"k":"filestream::your-filestream-stream-id::native::524337-2049","v":{"ttl":1800000000000,"updated":[642964167,1716580222],"cursor":null,"meta":null}} {"op":"set","id":9} {"k":"filestream::your-filestream-stream-id::native::524336-2049","v":{"meta":null,"ttl":1800000000000,"updated":[643163920,1716580222],"cursor":null}} {"op":"set","id":10} {"k":"filestream::your-filestream-stream-id::native::524337-2049","v":{"meta":null,"ttl":1800000000000,"updated":[643028919,1716580222],"cursor":{"offset":65}}} {"op":"set","id":11} {"k":"filestream::your-filestream-stream-id::native::524336-2049","v":{"meta":null,"ttl":1800000000000,"updated":[656118534,1716580396],"cursor":{"offset":65}}} {"op":"set","id":12} {"k":"filestream::your-filestream-stream-id::native::524336-2049","v":{"cursor":{"offset":0},"meta":null,"ttl":1800000000000,"updated":[656118534,1716580396]}} {"op":"set","id":13} {"k":"filestream::your-filestream-stream-id::native::524337-2049","v":{"cursor":{"offset":65},"meta":null,"ttl":0,"updated":[643028919,1716580222]}} {"op":"set","id":14} {"k":"filestream::your-filestream-stream-id::native::524338-2049","v":{"updated":[281470681743360,18446744011573954816],"cursor":null,"meta":{"source":"/var/log/app/app.log.1","identifier_name":"native"},"ttl":0}} {"op":"set","id":15} {"k":"filestream::your-filestream-stream-id::native::524336-2049","v":{"ttl":0,"updated":[656118534,1716580396],"cursor":{"offset":0},"meta":null}} {"op":"set","id":16} {"k":"filestream::your-filestream-stream-id::native::524338-2049","v":{"ttl":1800000000000,"updated":[663465767,1716580756],"cursor":null,"meta":{"source":"/var/log/app/app.log.1","identifier_name":"native"}}} {"op":"set","id":17} {"k":"filestream::your-filestream-stream-id::native::524338-2049","v":{"ttl":1800000000000,"updated":[663666219,1716580756],"cursor":null,"meta":null}} {"op":"set","id":18} {"k":"filestream::your-filestream-stream-id::native::524338-2049","v":{"ttl":1800000000000,"updated":[663809569,1716580756],"cursor":{"offset":65},"meta":null}} ```

/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.1
    rotation.external.strategy.copytruncate:
      suffix_regex: \.\d$
      count: 9

/etc/logrotate.d/app:

/var/log/app/*.log {
    daily
    rotate 9
    copytruncate
}

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

I see no obvious errors in confirs or log, seems that copytruncate rotation is correctly detected and harvester tries to continue reading rotated log file from where it has stopped. But full log file is always read and sent twice, causing a full duplication of events.

I've tested using fingerpring method, and got exectly the same results.

Is there any workaround to avoid full log duplication with copytruncate strategy?

botelastic[bot] commented 3 months ago

This issue doesn't have a Team:<team> label.