Filebeat[5.6.3] - tail_files not working

olololll · November 7, 2017, 8:34am

Problem:
I want filebeat only read the newly added line in log file and send it to logstash.

For example, there are 2lines in the log originally.
Line1: A
Line2: B
The log file will keep updating, says a new line3,
Line1: A
Line2: B
Line3: C

It expected only "Line3: C" will send to logstash, but filebeat will send Line1,2,3 again after new line 3 is added.
I then found suggestion about "tail_files":
https://www.elastic.co/guide/en/beats/filebeat/master/configuration-filebeat-options.html#_literal_type_literal

Stopped filebeat, deleted regiestry and start again, but it still not work.

version:
filebeat-5.6.3-linux-x86_64

filebeat.yml:

filebeat.prospectors:
-input_type: log
paths:
-/{path}/myLogFile.log
tail_files: true

multiline.pattern: (\n|^)[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9] [0-9][0-9]:[0-9][0-9]:[0-9][0-9].[0-9][0-9][0-9]
multiline.negate: true
multiline.match: after

output.logstash:
hosts: ["Windows:5044"]

Also, i used command below for debugging

/{path}/filebeat -e -d "*" -c /filebeat.yml

After I update my log file for adding Line3, I found the offset value is reset to 0. I guess this is the reason why tail_files cant work.

2017/11/07 08:47:54.410566 prospector.go:183: DBG Run prospector
2017/11/07 08:47:54.410590 prospector_log.go:70: DBG Start next scan
2017/11/07 08:47:54.410650 prospector_log.go:226: DBG Check file for harvesting: /{path}/myLogFile.log
2017/11/07 08:47:54.410670 prospector_log.go:259: DBG Update existing file for harvesting: /{path}/myLogFile.log, offset: 340
2017/11/07 08:47:54.410679 prospector_log.go:311: DBG Harvester for file is still running: /{path}/myLogFile.log
2017/11/07 08:47:54.410690 prospector_log.go:91: DBG Prospector states cleaned up. Before: 2, After: 2
2017/11/07 08:47:59.403057 spooler.go:89: DBG Flushing spooler because of timeout. Events flushed: 0
2017/11/07 08:47:59.410997 log_file.go:84: DBG End of file reached: /{path}/myLogFile.log; Backoff now.
2017/11/07 08:48:04.403261 spooler.go:89: DBG Flushing spooler because of timeout. Events flushed: 0
2017/11/07 08:48:04.410848 prospector.go:183: DBG Run prospector
2017/11/07 08:48:04.410874 prospector_log.go:70: DBG Start next scan
2017/11/07 08:48:04.410933 prospector_log.go:226: DBG Check file for harvesting: /{path}/myLogFile.log
2017/11/07 08:48:04.410951 prospector_log.go:259: DBG Update existing file for harvesting: /{path}/myLogFile.log, offset: 340
2017/11/07 08:48:04.410961 prospector_log.go:311: DBG Harvester for file is still running: /{path}/myLogFile.log
2017/11/07 08:48:04.410972 prospector_log.go:91: DBG Prospector states cleaned up. Before: 2, After: 2
2017/11/07 08:48:09.403516 spooler.go:89: DBG Flushing spooler because of timeout. Events flushed: 0
2017/11/07 08:48:09.411273 log_file.go:84: DBG End of file reached: /{path}/myLogFile.log; Backoff now.
2017/11/07 08:48:14.365303 metrics.go:34: INFO No non-zero metrics in the last 30s
2017/11/07 08:48:14.403759 spooler.go:89: DBG Flushing spooler because of timeout. Events flushed: 0
2017/11/07 08:48:14.411117 prospector.go:183: DBG Run prospector
2017/11/07 08:48:14.411135 prospector_log.go:70: DBG Start next scan
2017/11/07 08:48:14.411184 prospector_log.go:226: DBG Check file for harvesting: /{path}/myLogFile.log
2017/11/07 08:48:14.411200 prospector_log.go:259: DBG Update existing file for harvesting: /{path}/myLogFile.log, offset: 0
2017/11/07 08:48:14.411208 prospector_log.go:268: DBG Resuming harvesting of file: /{path}/myLogFile.log, offset: 0
2017/11/07 08:48:14.411554 log.go:288: DBG Setting offset for file based on seek: /{path}/myLogFile.log
2017/11/07 08:48:14.411569 log.go:273: DBG Setting offset for file: /{path}/myLogFile.log. Offset: 0
2017/11/07 08:48:14.411616 prospector_log.go:91: DBG Prospector states cleaned up. Before: 2, After: 2
2017/11/07 08:48:14.411653 log.go:91: INFO Harvester started for file: /{path}/myLogFile.log
2017/11/07 08:48:14.411854 log_file.go:84: DBG End of file reached: /{path}/myLogFile.log; Backoff now.
2017/11/07 08:48:15.412080 log_file.go:84: DBG End of file reached: /{path}/myLogFile.log; Backoff now.

But why.gif?

Christian_Dahlqvist · November 7, 2017, 9:15am

How are you updating the log file? If you do this through an editor, a new file (with the same name) is generally generated, which will cause Filebeat to read it all over again. Make sure that you append to the file when you add additional log lines.

olololll · November 7, 2017, 9:49am

You are right. Thanks Christian!

But I found another problem by using echo to append instead of vi.
After appended new line, seems the prospector cant detect my changed file and keeping ignore the new line.

2017/11/07 09:45:35.324098 prospector.go:183: DBG Run prospector
2017/11/07 09:45:35.324141 prospector_log.go:70: DBG Start next scan
2017/11/07 09:45:35.324229 prospector_log.go:226: DBG Check file for harvesting: /{path}/myLogFile.log
2017/11/07 09:45:35.324247 prospector_log.go:259: DBG Update existing file for harvesting: /{path}/myLogFile.log, offset: 0
2017/11/07 09:45:35.324259 prospector_log.go:311: DBG Harvester for file is still running: /{path}/myLogFile.log
2017/11/07 09:45:35.324270 prospector_log.go:91: DBG Prospector states cleaned up. Before: 2, After: 2
2017/11/07 09:45:35.329926 spooler.go:89: DBG Flushing spooler because of timeout. Events flushed: 0
2017/11/07 09:45:40.324790 log_file.go:84: DBG End of file reached: /{path}/myLogFile.log; Backoff now.
2017/11/07 09:45:40.330272 spooler.go:89: DBG Flushing spooler because of timeout. Events flushed: 0
2017/11/07 09:45:45.305277 metrics.go:34: INFO No non-zero metrics in the last 30s
2017/11/07 09:45:45.324587 prospector.go:183: DBG Run prospector
2017/11/07 09:45:45.324619 prospector_log.go:70: DBG Start next scan
2017/11/07 09:45:45.324711 prospector_log.go:226: DBG Check file for harvesting: /{path}/myLogFile.log
2017/11/07 09:45:45.324728 prospector_log.go:259: DBG Update existing file for harvesting: /{path}/myLogFile.log, offset: 0
2017/11/07 09:45:45.324736 prospector_log.go:311: DBG Harvester for file is still running: /{path}/myLogFile.log
2017/11/07 09:45:45.324747 prospector_log.go:91: DBG Prospector states cleaned up. Before: 2, After: 2
2017/11/07 09:45:45.330573 spooler.go:89: DBG Flushing spooler because of timeout. Events flushed: 0
2017/11/07 09:45:50.325182 log_file.go:84: DBG End of file reached: /{path}/myLogFile.log; Backoff now.
2017/11/07 09:45:50.330920 spooler.go:89: DBG Flushing spooler because of timeout. Events flushed: 0
2017/11/07 09:45:55.325030 prospector.go:183: DBG Run prospector
2017/11/07 09:45:55.325056 prospector_log.go:70: DBG Start next scan
2017/11/07 09:45:55.325117 prospector_log.go:226: DBG Check file for harvesting: /{path}/myLogFile.log
2017/11/07 09:45:55.325136 prospector_log.go:259: DBG Update existing file for harvesting: /{path}/myLogFile.log, offset: 0
2017/11/07 09:45:55.325148 prospector_log.go:311: DBG Harvester for file is still running: /{path}/myLogFile.log
2017/11/07 09:45:55.325158 prospector_log.go:91: DBG Prospector states cleaned up. Before: 2, After: 2
2017/11/07 09:45:55.331242 spooler.go:89: DBG Flushing spooler because of timeout. Events flushed: 0

Is it a normal behavior?

Christian_Dahlqvist · November 7, 2017, 9:51am

How are you appending? Are you adding a newline at the end?

olololll · November 7, 2017, 9:52am

echo -n "some log" >> /{path}/myLogFile.log

yes, adding a new line at the end

Christian_Dahlqvist · November 7, 2017, 9:56am

The -n flag means no trailing newline is added. Instead try with: echo "some log" >> /{path}/myLogFile.log.

olololll · November 7, 2017, 10:01am

Its work! Thank you Chris!

system · December 5, 2017, 10:01am

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