# Filebeat use (deleted) files **URL:** \ **Category:** Beats\ **Tags:** filebeat\ **Created:** [August 29, 2016, 11:19am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172 "2016-08-29T11:19:52Z")\ **Posts on this page:** 14\ **Page:** 1
**Author:** ![zakabluk](https://avatars.discourse-cdn.com/v4/letter/z/8baadc/32.png) [@zakabluk](https://discuss.elastic.co/u/zakabluk)\ **Post date:** [August 29, 2016, 11:19am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/1 "2016-08-29T11:19:53Z")
## filebeat-1.2.3-x86\_64 conf: ```auto filebeat: prospectors: - paths: - /var/opt/tibco/logs/*.log input_type: log close_older: 5m document_type: tibco_6 multiline: pattern: '\[BW' negate: true match: after force_close_files: true output: elasticsearch: hosts: ["srv-testapp-001t:9200"] ``` ## -- OS 2.6.18-274.el5 After long time work filebeat I have no free space on my server. When I execute /usr/sbin/lsof -p 8095 (PID filrbeat) I see what process have many deleted files: ```auto filebeat 31893 tibco 46r REG 8,17 20520987 638989 /var/opt/tibco/logs/UssdCs-UssdCs-prod6.log.4 (deleted) filebeat 31893 tibco 47r REG 8,17 5512425 638991 /var/opt/tibco/logs/VPartnerGw-mobileapi-VPartnerGw-mobileapi-prod6.log filebeat 31893 tibco 48r REG 8,17 20461307 638985 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 (deleted) filebeat 31893 tibco 49r REG 8,17 20526952 638984 /var/opt/tibco/logs/UssdCs-UssdCs-prod6.log.4 (deleted) filebeat 31893 tibco 50r REG 8,17 20460267 638990 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 (deleted) filebeat 31893 tibco 51r REG 8,17 18119756 639002 /var/opt/tibco/logs/partnergateway-PartnerGatewayConnector-prod6.log filebeat 31893 tibco 52r REG 8,17 1661592 639015 /var/opt/tibco/logs/VPartnerGw-voka-VPartnerGw-voka-prod6.log filebeat 31893 tibco 53r REG 8,17 20461356 638997 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 (deleted) filebeat 31893 tibco 54r REG 8,17 20504359 638978 /var/opt/tibco/logs/UssdCs-UssdCs-prod6.log.4 (deleted) filebeat 31893 tibco 55r REG 8,17 20532252 638981 /var/opt/tibco/logs/UssdCs-UssdCs-prod6.log.4 (deleted) ``` * * * I read issues > [https://github.com/elastic/beats/issues/1600](https://github.com/elastic/beats/issues/1600) but this not help me. ---
**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\ **Post date:** [August 30, 2016, 8:32am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/2 "2016-08-30T08:32:07Z")
Under filebeat 1.2.3 it is possible that in case a file is rotate during the scan that a file handler is kept open. Some improvements were made in 1.3 to prevent this issue. For version 5 the file handling part was rewritten and these issue do not exist anymore. For the version 1.2.3 currently the only fix is if it happened to restart filebeat. This will free all file handler. Obviously this is not a nice solution. How long was filebeat running until the issue happened? ---
**Author:** ![zakabluk](https://avatars.discourse-cdn.com/v4/letter/z/8baadc/32.png) [@zakabluk](https://discuss.elastic.co/u/zakabluk)\ **Post date:** [September 1, 2016, 6:14am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/3 "2016-09-01T06:14:05Z")
Hi! Filebeat worked 10 minutes. I try 1.3 and see in debug logs Launching harvester on new file: /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log. Old file was probably rotated ```auto filebeat 2635 tibco 30r REG 8,17 20473992 639009 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 (deleted) filebeat 2635 tibco 40r REG 8,17 20469091 639026 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 (deleted) filebeat 2635 tibco 41r REG 8,17 20466790 639084 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 (deleted) filebeat 2635 tibco 42r REG 8,17 20471145 638984 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 (deleted) filebeat 2635 tibco 43r REG 8,17 20470834 639075 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 (deleted) filebeat 2635 tibco 45r REG 8,17 20471937 639089 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 filebeat 2635 tibco 48r REG 8,17 20465266 639090 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.3 filebeat 2635 tibco 49r REG 8,17 20467060 639091 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.2 filebeat 2635 tibco 51r REG 8,17 9702675 639093 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log filebeat 2635 tibco 52r REG 8,17 20472383 639092 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.1 ``` Now will try ver5. ---
**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\ **Post date:** [September 1, 2016, 6:47am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/4 "2016-09-01T06:47:13Z")
Can you share some details on the number of events you have per second and how often your files are rotated? Thanks for testing the 5.0 release. ---
**Author:** ![zakabluk](https://avatars.discourse-cdn.com/v4/letter/z/8baadc/32.png) [@zakabluk](https://discuss.elastic.co/u/zakabluk)\ **Post date:** [September 1, 2016, 10:54am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/5 "2016-09-01T10:54:09Z")
Hi. I have same problems 1. ... number of events you have per second - I don`t know. How I can check? 2. ... how often your files are rotated? - When log is 20M applications change file. For example: Sep 1 13:35 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 Sep 1 13:37 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.3 Sep 1 13:40 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.2 Sep 1 13:42 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.1 Sep 1 13:43 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log In config file prospectors: paths: - /var/opt/tibco/logs/\*.log input\_type: log close\_older: 5m document\_type: tibco\_6 multiline: pattern: '[BW' negate: true match: after force\_close\_files: true Maybe for you will be interesting nohup file from my filebeat? ---
**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\ **Post date:** [September 1, 2016, 11:09am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/6 "2016-09-01T11:09:22Z")
@zakabluk When you wrote you have the same problem, you mean you have the same problem with the 5.0 nightly build? [https://beats-nightlies.s3.amazonaws.com/index.html?prefix=filebeat/](https://beats-nightlies.s3.amazonaws.com/index.html?prefix=filebeat/) About number of events: An estimate on how many log lines you created would be good. Just a rough estimate to understand if we talk about a high load project or not. For file rotation: Kind of related to the previous point: How often is it rotated because it reaches the 20MB? Every 10s, 10 minutes, 1 hour? ---
**Author:** ![zakabluk](https://avatars.discourse-cdn.com/v4/letter/z/8baadc/32.png) [@zakabluk](https://discuss.elastic.co/u/zakabluk)\ **Post date:** [September 2, 2016, 11:29am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/7 "2016-09-02T11:29:41Z")
Hi! Today tested filebeat-5.0.0-alpha6-SNAPSHOT-linux-x86\_64. Same problems. After 10 minutes, they began to appear - messages about deleted files. One file have about 10K rows. All events write in file VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log. When this file is 20M, he renamed VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.1 and file VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 deleted. below you can see time for log rotate: Sep 2 14:07 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 Sep 2 14:09 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.3 Sep 2 14:11 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.2 - not use Sep 2 14:14 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.1 - not use Sep 2 14:14 VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log - using applications test with lsof: [tibco]$ /usr/sbin/lsof /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log.4 [tibco]$ /usr/sbin/lsof /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME bwengine 26344 tibco 303w REG 8,17 10276872 639075 /var/opt/tibco/logs/VPartnerGw-ussdtail-VPartnerGw-ussdtail-6.log filebeat watches catalog LOG, what use for save logs about 30 app. ussdtail is most active ---
**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\ **Post date:** [September 2, 2016, 12:43pm UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/8 "2016-09-02T12:43:07Z")
Thanks for testing with the snapshot. Can you share the exact messages that show up? I'm not sure I can follow your lsof check. It seems like filebeat is not watching the .4 file which is good? ---
**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\ **Post date:** [September 2, 2016, 12:43pm UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/9 "2016-09-02T12:43:54Z")
BTW: `close_older` was renamed to close\_inactive in 5.0 and `force_close_files` is now `close_renamed` and `close_removed`. ---
**Author:** ![zakabluk](https://avatars.discourse-cdn.com/v4/letter/z/8baadc/32.png) [@zakabluk](https://discuss.elastic.co/u/zakabluk)\ **Post date:** [September 5, 2016, 11:44am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/10 "2016-09-05T11:44:42Z")
My config; ```auto filebeat: prospectors: - paths: - /var/opt/tibco/logs/*.log input_type: log close_inactive: 15m document_type: tibco_6 multiline: pattern: '\[BW' negate: true match: after close_renamed: true close_removed: true ``` * * * And my problems not disappear. 1. It seems like filebeat is not watching the .4 file which is good? For example file: In log filebaet: ```auto filebeat 15747 tibco 979r REG 8,17 20433483 639001 /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log.4 (deleted) ``` File ```auto [server]$ ll /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log.4 -rw-r--r-- 1 tibco tibco 20433909 Sep 5 10:44 /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log.4 ``` If use lsof for file /usr/sbin/lsof /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log.4 I see what file is not watching filebeat and other process. Messages from log Filebeat ```auto 2016/09/05 10:09:03.757905 prospector_log.go:140: DBG Check file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:03.757916 prospector_log.go:173: DBG Update existing file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log, offset: 150785 2016/09/05 10:09:03.757924 prospector_log.go:223: DBG Harvester for file is still running: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:13.762543 prospector_log.go:140: DBG Check file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:13.762559 prospector_log.go:173: DBG Update existing file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log, offset: 150785 2016/09/05 10:09:13.762572 prospector_log.go:223: DBG Harvester for file is still running: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:23.767274 prospector_log.go:140: DBG Check file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:23.767285 prospector_log.go:173: DBG Update existing file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log, offset: 150785 2016/09/05 10:09:23.767294 prospector_log.go:223: DBG Harvester for file is still running: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:33.771490 prospector_log.go:140: DBG Check file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:33.771501 prospector_log.go:173: DBG Update existing file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log, offset: 150785 2016/09/05 10:09:33.771510 prospector_log.go:223: DBG Harvester for file is still running: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:43.775458 prospector_log.go:140: DBG Check file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:43.775469 prospector_log.go:173: DBG Update existing file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log, offset: 150785 2016/09/05 10:09:43.775477 prospector_log.go:223: DBG Harvester for file is still running: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log 2016/09/05 10:09:53.779052 prospector_log.go:140: DBG Check file for harvesting: /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log ``` ---
**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\ **Post date:** [September 6, 2016, 11:02am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/11 "2016-09-06T11:02:15Z")
I tried to reformat your post above. Please use 3 ticks around code blocks to make it more readable. 1. The indentation for close\_removed, close\_renamed seems to be off. Not sure if that is a copy / paste problem or it is that way in the config file? 2. I don't understand the following sentence: "I see what file is not watching filebeat and other process." 3. For the filebeat log file, I would expect more debug messages with additional information between these outputs. Did you filter out part of it or is that everything from the log file? ---
**Author:** ![zakabluk](https://avatars.discourse-cdn.com/v4/letter/z/8baadc/32.png) [@zakabluk](https://discuss.elastic.co/u/zakabluk)\ **Post date:** [September 10, 2016, 9:30am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/12 "2016-09-10T09:30:59Z")
Hi. 1. The indentation for close\_removed, close\_renamed seems to be off. Not sure if that is a copy / paste problem or it is that way in the config file? This is was from config file. Now I commented this is options. And restart file beat. The problem persists. 2. I don't understand the following sentence: "I see what file is not watching filebeat and other process." If use **lsof** for **file** /usr/sbin/lsof /var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log.4 I see what filebeat DO NOT use the file `/var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log.4,` he watch only `/var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log` . But in this time if I check `lsof -p PID_FILEBEAT | grep 'deleted'` I have rows with (deleted). Example: `/var/opt/tibco/logs/VPartnerGw-vmeste-VPartnerGw-vmeste-prod6.log.4 (deleted)` 1. I am shared file with log from FB(FileBeat) in debug mode. [https://yadi.sk/d/GfG8WtjUuy3cB](https://yadi.sk/d/GfG8WtjUuy3cB) This is txt file. maybe he help. ---
**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\ **Post date:** [September 12, 2016, 8:36am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/13 "2016-09-12T08:36:35Z")
I found the following line in your log file: ```auto 2016/09/09 11:11:50.008100 log.go:42: ERR Stop Harvesting. Unexpected file opening error: open /var/opt/tibco/logs/partnergateway-PartnerGatewayConnector-prod6.log: too many open files ``` It seems like filebeat is potentially opening too many files which could lead to this issue. How many files do you harvest at the same time? What is your ulimit? An other thing I realised is that filebeat is constantly flushing events. The default for `spool_size` is 50 which is good to get started and use low memory, but for lots of events this value should be increased. Can you try to set it to `filebeat.spool_size: 2048` or even higher? It seems there are several issue where one leads to an other: - Events are not sent fast enough -\> files are not closed because harvesting is blocked by output - Because file are not closed -\> too many files are open - Beacuse too many files are open -\> errors on the output appear, because for the output also file descriptors are needed: `2016/09/09 12:53:33.051400 single.go:140: ERR Connecting error publishing events (retrying): lookup srv-testapp-001t on 10.254.0.3:53: dial udp 10.254.0.3:53: socket: too many open files`` You should make sure that events can be sent faster from filebeat then new events are created. Increase the recommended value above and check the following lines: ```auto 2016/09/09 10:37:29.932138 output.go:109: DBG output worker: publish 50 events ``` If it constantly sents afterwards still 2048 events you should increase the value even more. It would be still good to have some values on how many log lines are generated per second. ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [September 19, 2016, 11:20am UTC](https://discuss.elastic.co/t/filebeat-use-deleted-files/59172/14 "2016-09-19T11:20:04Z")
This topic was automatically closed after 21 days. New replies are no longer allowed.