Filebeat sending the whole log again after stoping and starting filebeat container

Elastic Stack Beats
1

Hi,

When I stop filebeat container for a while to do some maintenance work on elasticsearch (output) and then start it again, the whole log is being sent again. because of this along with the new info which was written into log while the filebeat was down, the old content which was already sent to elasticsearch, is being sent again.

because of this i'm ending up with duplicate data in ES.

How to avoid it and make filebeat to read only new content written after stopping and starting it again.

Here's the config I'm using:

filebeat.prospectors:
- type: log
  enabled: true
  paths:
    - /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log
  encoding: plain
  include_lines: ['\d{4}\-\d{2}\-\d{2}']
  multiline.pattern: '^\d{4}\-\d{2}\-\d{2}'
  multiline.negate: false
  multiline.match: after
  fields:
    document_type: zuul_log
  clean_removed: true
  registry: /usr/share/filebeat/data/registry

setup.template:
  name: "filebeat"
  pattern: "filebeat-*"
  settings:
    index.number_of_shards: 1
    index.number_of_replicas: 1

output.elasticsearch:
  hosts: ["xxx:9200"]
  index: "%{[fields.document_type]}-%{[beat.version]}-%{+yyyy.MM.dd}"

Thanks for the help

2

Filebeat has a registry file to track the events it has already sent to outputs.
Are you sure Filebeat has access to it? Or does it get deleted between container runs?
Could you please share the debug logs of filebeat?

3

Here's is the log:

2018/10/03 09:43:26.387184 beat.go:268: INFO filebeat stopped.
2018/10/03 09:44:26.630278 beat.go:426: INFO Home path: [/usr/share/filebeat] Config path: [/usr/share/filebeat] Data path: [/usr/share/filebeat/data] Logs path: [/usr/share/filebeat/logs]
2018/10/03 09:44:26.630446 beat.go:433: INFO Beat UUID: 9ce44b4f-8f6e-4513-94bc-3f8c498b5d93
2018/10/03 09:44:26.630442 metrics.go:23: INFO Metrics logging every 30s
2018/10/03 09:44:26.630485 beat.go:192: INFO Setup Beat: filebeat; Version: 6.0.1
2018/10/03 09:44:26.631019 client.go:123: INFO Elasticsearch url: http://swamy-ansiblenode1.vse.rdlabs.hpecorp.net:9200
2018/10/03 09:44:26.631743 module.go:80: INFO Beat name: 442bba24eabf
2018/10/03 09:44:26.632518 beat.go:260: INFO filebeat start running.
2018/10/03 09:44:26.632630 registrar.go:88: INFO Registry file set to: /usr/share/filebeat/data/registry
2018/10/03 09:44:26.632705 registrar.go:108: INFO Loading registrar data from /usr/share/filebeat/data/registry
2018/10/03 09:44:26.633133 registrar.go:119: INFO States Loaded from registrar: 1
2018/10/03 09:44:26.633207 crawler.go:44: INFO Loading Prospectors: 1
2018/10/03 09:44:26.633430 registrar.go:150: INFO Starting Registrar
2018/10/03 09:44:26.634141 prospector.go:103: INFO Starting prospector of type: log; id: 11640557023490740795
2018/10/03 09:44:26.634175 crawler.go:78: INFO Loading and starting Prospectors completed. Enabled prospectors: 1
2018/10/03 09:44:26.637768 harvester.go:207: INFO Harvester started for file: /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log
2018/10/03 09:44:27.670319 client.go:651: INFO Connected to Elasticsearch version 5.6.2
2018/10/03 09:44:27.673102 load.go:73: INFO Template already exists and will not be overwritten.
2018/10/03 09:44:52.472795 registrar.go:233: ERR Failed to create tempfile (/usr/share/filebeat/data/registry.new) for writing: open /usr/share/filebeat/data/registry.new: permission denied
2018/10/03 09:44:52.472845 registrar.go:217: ERR Writing of registry returned error: open /usr/share/filebeat/data/registry.new: permission denied. Continuing...
2018/10/03 09:44:56.631574 metrics.go:39: INFO Non-zero metrics in the last 30s: beat.memstats.gc_next=88511696 beat.memstats.memory_alloc=52551160 beat.memstats.memory_total=3012819400 filebeat.events.active=19170 filebeat.events.added=1030463 filebeat.events.done=1011293 filebeat.harvester.open_files=1 filebeat.harvester.running=1 filebeat.harvester.started=1 libbeat.config.module.running=0 libbeat.output.read.bytes=201695 libbeat.output.type=elasticsearch libbeat.output.write.bytes=39799570 libbeat.pipeline.clients=1 libbeat.pipeline.events.active=382 libbeat.pipeline.events.filtered=1009452 libbeat.pipeline.events.published=21009 libbeat.pipeline.events.retry=50 libbeat.pipeline.events.total=1030461 libbeat.pipeline.queue.acked=20627 registrar.states.cleanup=1 registrar.states.current=1 registrar.states.update=1011293 registrar.writes=437
2018/10/03 09:44:57.375991 registrar.go:233: ERR Failed to create tempfile (/usr/share/filebeat/data/registry.new) for writing: open /usr/share/filebeat/data/registry.new: permission denied
2018/10/03 09:44:57.376033 registrar.go:217: ERR Writing of registry returned error: open /usr/share/filebeat/data/registry.new: permission denied. Continuing...
2018/10/03 09:45:06.905293 registrar.go:233: ERR Failed to create tempfile (/usr/share/filebeat/data/registry.new) for writing: open /usr/share/filebeat/data/registry.new: permission denied
2018/10/03 09:45:06.905332 registrar.go:217: ERR Writing of registry returned error: open /usr/share/filebeat/data/registry.new: permission denied. Continuing...
2018/10/03 09:45:11.474269 helper_other.go:14: ERR Rotate error: rename /usr/share/filebeat/data/registry.new /usr/share/filebeat/data/registry: no such file or directory
2018/10/03 09:45:11.474332 registrar.go:217: ERR Writing of registry returned error: rename /usr/share/filebeat/data/registry.new /usr/share/filebeat/data/registry: no such file or directory. Continuing...

I think filebeat has access to registry file but there's some permission error ? I'm not sure.

4

Yes, there is a permission problem. Filebeat is not able to write its registry.
Writing of registry returned error: open /usr/share/filebeat/data/registry.new: permission denied. Continuing...

Before writing to data/registry, Filebeat first creates a temp file registry.new and then renames it to registry. So it seems your instance is able to read from data/registry, but does not have the correct permissions to write to a new file under data.

5

But I'm not sure how is that the cause for re-sending entire log again after stopping and starting. Do you think fixing the permission error would fix the problem of re-sending the log? If it does, how? because filebeat still has access to registry file and has permission to read the registry file!

6

I changed permission of registry file (0755), but the issue still persists. addition of a single new line to log is resulting in sending the whole log to ES instead of just that one line!

7

Filebeat tracks progress of reading from input files, so it does not reread anything. It persist the state information of files by writing it to the registry. Thus, when Filebeat restarts, it reads the states and knows where it needs to continue reading.
If it cannot access the registry file, it does not have any information on the states of the files. If there is no information on a file, it means that Filebeat has not encountered it before, so it starts to read it from the beginning. According to the logs you have provided, Filebeat is unable to write the state information to disk, because of permission problems.

Could you share the debug logs again? Is it possible that Filebeat still does not have the proper access to the folder, so it is not able to write the temporary file?

8

Yes, here's the debug log.

2018/10/04 13:35:29.433676 registrar.go:150: INFO Starting Registrar
2018/10/04 13:35:29.433770 processor.go:49: DBG Processors:
2018/10/04 13:35:29.434239 config.go:174: DBG recursive glob disabled
2018/10/04 13:35:29.434588 prospector.go:109: DBG exclude_files: []
2018/10/04 13:35:29.434611 state.go:81: DBG New state added for /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log
2018/10/04 13:35:29.434643 prospector.go:130: DBG Prospector with previous states loaded: 1
2018/10/04 13:35:29.434659 prospector.go:100: DBG File Configs: [/usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log]
2018/10/04 13:35:29.434672 prospector.go:103: INFO Starting prospector of type: log; id: 11640557023490740795
2018/10/04 13:35:29.434688 crawler.go:78: INFO Loading and starting Prospectors completed. Enabled prospectors: 1
2018/10/04 13:35:29.434734 prospector.go:136: DBG Start next scan
2018/10/04 13:35:29.434828 prospector.go:350: DBG Check file for harvesting: /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log
2018/10/04 13:35:29.434818 registrar.go:200: DBG Processing 1 events
2018/10/04 13:35:29.434880 registrar.go:195: DBG Registrar states cleaned up. Before: 1, After: 1
2018/10/04 13:35:29.434895 registrar.go:228: DBG Write registry file: /usr/share/filebeat/data/registry
2018/10/04 13:35:29.434848 prospector.go:436: DBG Update existing file for harvesting: /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log, offset: 343298048
2018/10/04 13:35:29.434973 prospector.go:490: DBG File didn't change: /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log
2018/10/04 13:35:29.434986 prospector.go:157: DBG Prospector states cleaned up. Before: 1, After: 1
2018/10/04 13:35:29.442743 registrar.go:253: DBG Registry file updated. 1 states written.
2018/10/04 13:35:39.435377 prospector.go:140: DBG Run prospector
2018/10/04 13:35:39.435432 prospector.go:136: DBG Start next scan
2018/10/04 13:35:39.435550 prospector.go:350: DBG Check file for harvesting: /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log
2018/10/04 13:35:39.435575 prospector.go:436: DBG Update existing file for harvesting: /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log, offset: 343298048
2018/10/04 13:35:39.435588 prospector.go:490: DBG File didn't change: /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log
2018/10/04 13:35:39.435602 prospector.go:157: DBG Prospector states cleaned up. Before: 1, After: 1

If it cannot access the registry file, it does not have any information on the states of the files. If there is no information on a file, it means that Filebeat has not encountered it before, so it starts to read it from the beginning. According to the logs you have provided, Filebeat is unable to write the state information to disk, because of permission problems.

But if that was the case, it should have re read the whole log after restarting also. In the case when there are no new contents and the filebeat is restarted, it correctly does the job of not sending anything to ES as it has already sent the old log info.

9

When do you see this behavoiur exactly? When does Filebeat reread everything? In your initial post you have written: "How to avoid it and make filebeat to read only new content written after stopping and starting it again." To me it means that Filebeat rereads everything after restarting it.

10

I'm very sorry that i wasn't clear before.

The issue occurs:

  1. when the new content is written to log and filebeat is running.
  2. when the new content was written when filebeat was in stop mode, on starting
    filebeat whole content was re-read.

So basically, the whole log is being re-read everytime when a new content is written to log.

11

Could you please share the debug logs of the following scenario: Filebeat is started again after finishing reading a file. Then please add one more line to the file, so it triggers the reread of the full file?

12

Could you please share the debug logs of the following scenario: Filebeat is started again after finishing reading a file.

In this scenario, log is not sent again (Assuming no new content was written when filebeat was down). The debug log of this scenario is already send in previous message (8/11). It correctly recognizes that:
2018/10/04 13:35:39.435588 prospector.go:490: DBG File didn't change: /usr/share/filebeat/logs/zuul/log/50lk_1cr_lines.log

Then please add one more line to the file, so it triggers the reread of the full file?

Yes, exactly. Addition of any new content triggers re-sending of whole log instead of just the new content.

Am i missing some config item in my configuration file here?

13

Can someone please help?

14

how exactly do you modify the file. Have you tried $ echo 'new line' >> /usr/src/app/log.log ? filebeat tries to detect if file is new or not based on meta-data. some tools/editors do create a completely new file on save and unlink the old one. This is detected by filebeat as new file forcing it to resend all content.

I was using vi editor to edit file manually. so the issue. The above solved problem.

1 Like
15

Yet, if that was the situation, it ought to have re perused the entire log in the wake of restarting moreover. For the situation when there are no new substance and the filebeat is restarted, it effectively does the activity of not sending anything to ES as it has officially sent the old log information.
https://www.assignmentprofs.co.uk/

16

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