Filebeat not closing file handle even after ignore_older

Omar_Al_Zabir · December 19, 2016, 4:15pm

I have the following filebeat config, where I do not want to monitor files older than an hour, as I need to delete files 30 mins older:

      close_renamed: true
      close_inactive: 15m
      close_removed: true
      close_eof: true
      clean_inactive: 1h
      clean_removed: true
      clean_renamed: true
      ignore_older: 1h

But filebeat keeps file handle open longer than configured. You can see files opened 1300 is still held by filebeat, where current time is 1600.

COMMAND    PID USER   FD   TYPE DEVICE   SIZE/OFF NLINK    NODE NAME
vmtoolsd  1290 root    5u   REG   0,18       9342     0   10466 /tmp/vmware-root/appLoader-1290.log (deleted)
/osmf/mgm 1756 root  txt    REG   0,18    1733200     0   12369 /tmp/par-726f6f74/cache-hunter-79859/gpp (deleted)
/osmf/mgm 1905 root  txt    REG   0,18    1733200     0   13187 /tmp/par-726f6f74/cache-hunter-79859/procscan (deleted)
filebeat  6937 root    9r   REG  252,3 1006910348     0 2343034 /logs/ovlog/cbs137a135_combined_**1303**.log (deleted)
filebeat  6937 root   11r   REG  252,3  253114818     0 2342919 /logs/ovlog/cbs137a132_combined_1511.log (deleted)
filebeat  6937 root   12r   REG  252,3  905681525     0 2343040 /logs/ovlog/cbs137a135_combined_**1347**.log (deleted)
filebeat  6937 root   13r   REG  252,3  294481722     0 2343035 /logs/ovlog/cbs137a132_combined_1522.log (deleted)
filebeat  6937 root   14r   REG  252,3  927783819     0 2343058 /logs/ovlog/cbs137a133_combined_1537.log (deleted)
filebeat  6937 root   16r   REG  252,3  825060195     0 2343048 /logs/ovlog/cbs137a133_combined_1405.log (deleted)
filebeat  6937 root   18r   REG  252,3  261785584     0 2342922

I can see around 1300 there were some errors sending logs. Maybe that's why it did not close the file handle. But it should:

2016/12/19 13:07:47.879536 sync_worker.go:167: INFO Error publishing events (retrying): read tcp 10.187.147.58:55366->10.9.181.155:50494: i/o timeout
2016/12/19 13:07:48.786483 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a134_combined_1233.log
2016/12/19 13:07:48.786521 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a130_combined_1236.log
2016/12/19 13:07:58.787724 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a130_combined_1236.log
2016/12/19 13:07:58.787793 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a134_combined_1233.log
2016/12/19 13:08:03.468050 logp.go:230: INFO Non-zero metrics in the last 30s: libbeat.logstash.call_count.PublishEvents=29 libbeat.logstash.publish.read_errors=1 libbeat.logstash.published_and_acked_events=32353 libbeat.publisher.published_events=32024 registrar.writes=24 libbeat.logstash.publish.write_bytes=2460880 libbeat.logstash.published_but_not_acked_events=1186 registrar.states.update=120000 libbeat.logstash.publish.read_bytes=1092 publish.events=120000
2016/12/19 13:08:08.788958 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a134_combined_1233.log
2016/12/19 13:08:08.788998 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a130_combined_1236.log
2016/12/19 13:08:14.221208 sync.go:85: ERR Failed to publish events caused by: EOF
2016/12/19 13:08:14.221259 sync_worker.go:167: INFO Error publishing events (retrying): EOF
2016/12/19 13:08:18.790451 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a130_combined_1236.log
2016/12/19 13:08:18.790488 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a134_combined_1233.log
2016/12/19 13:08:18.790573 log.go:84: INFO Harvester started for file: /logs/ovlog/cbs137a088_combined_1308.log
2016/12/19 13:08:28.791197 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a134_combined_1233.log
2016/12/19 13:08:28.791241 prospector_log.go:310: INFO File is falling under ignore_older before harvesting is finished. Adjust your close_* settings: /logs/ovlog/cbs137a130_combined_1236.log

Also these are logged as INFO. They should be logged as ERR or WARN, so that we can set traps on such problems.

ruflin · December 20, 2016, 9:21am

close_inactive does only apply, when filebeat finished reading the file. So in case there are some errors and the file content did not complete sending, it will only apply after it finished sending. Also important to note that close_inactive is not based on the modtime of the file, but based on when filebeat touched it the last time. So if you have close_inactive 15m and filebeat touched the file the last time at 13:08, it will only close it at 13:23 independent of the file modtime.

The above is to ensure no log lines are lost. You should investigate the problem of sending events. Please also be aware that clean_renamed does not exist.

Omar_Al_Zabir · December 20, 2016, 11:19am

Thanks Ruflin. But I checked the file handle after 2 hours and they were still open. They never get closed, even if I wait for several hours, until I restarted filebeat.

ruflin · December 20, 2016, 11:47am

Can you confirm that all events of the file in question were sent? Can you share your filebeat config? Are you using publish_async?

system · January 17, 2017, 11:47am

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