Filebeat does not send the message due to inode reused

Elastic Stack Beats
1

hi expert,

I use the filebeat to import the data files to e.s, and there's a script keeping running in the background to scan the filog lebeat log, the data file(XXX) will be removed once it found a harvester eof event "End of file reached:XXX".

this is the filebeat log module settings:

 - type: log

  # Change to true to enable this input configuration.
  enabled: true

  # Paths that should be crawled and fetched. Glob based paths.
  paths:
    - /extend/data_log/SLT/*.log
    #- c:\programdata\elasticsearch\logs\*

  # Exclude files. A list of regular expressions to match. Filebeat drops the files that
  # are matching any regular expression from the list. By default, no files are dropped.
  #exclude_files: ['.gz$']
  scan_frequency: 50
  close_eof: true
  clean_removed: true
  harvester_limit: 100

  pipeline: slt-test

now the problem is, some data files are still not removed after 1-2 days. actually those files are all old files and data content is generated in one time. so I just checked the filebeat log and the register file to see what happened, and now what I can't understand is there's no any filebeat log for the old files, but the registry file has the log for the old files, and aslo the registry shows the files is just to the end.

So I'm confused why there's no any log to the old files in the filebeat, basically there should be 2 events if eof reached, the first is the harvester start event, another is the harvester end event. please see below 2 typical log events:

[tdni@tdexample01 filebeat]$ grep 082446 ./filebeat
2018-11-12T09:00:06.551+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00193.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181112_082446_suzamdaslt083_008_MAIN.kdf.20181112085005.log
2018-11-12T09:00:06.552+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00193.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181112_082446_suzamdaslt083_008_MAIN.kdf.20181112085005.log. Closing because close_eof is enabled.
2

please see the registry file:

[{"source":"/home/tdni/HG00149B.1_6310_H800Z0020100704_CESLT_ATCACP_DS2000DBGBC00_20181025_012213_suzamdaslt083_008_MAIN.kdf.20181025020207.a.log","offset":22315,"timestamp":"2018-10-25T14:10:20.502599406+08:00","ttl":-2,"type":"log","meta":null,"FileStateOS":{"inode":671089871,"device":64768}},{"source":"/extend/data_log/SLT/HG00124B.1_6310_H800H0011071104_CESLT_ATCACP_DS2000DAGCB00_20181108_145545_suzamdaslt083_002_MAIN.kdf.20181108155001.log","offset":24457,"timestamp":"2018-11-08T16:00:22.358303075+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747920,"device":64770}},{"source":"/extend/data_log/SLT/HG00124B.1_6310_H800M0021091304_CESLT_ATCACP_DS2000DAGCB00_20181108_145343_suzamdaslt083_004_MAIN.kdf.20181108155004.log","offset":24460,"timestamp":"2018-11-08T16:00:22.358303075+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747915,"device":64770}},{"source":"/extend/data_log/SLT/HG00124B.1_6310_H800M0009032404_CESLT_ATCACP_DS2000DAGCB00_20181108_180145_suzamdaslt083_004_MAIN.kdf.20181108185002.log","offset":24413,"timestamp":"2018-11-08T19:00:23.09186058+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747918,"device":64770}},{"source":"/extend/data_log/SLT/HG00126B.1_6310_H800J0014050804_CESLT_ATCACP_DS2000DAGCB00_20181109_003414_suzamdaslt083_004_MAIN.kdf.20181109013004.log","offset":24416,"timestamp":"2018-11-09T02:00:25.433478745+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747921,"device":64770}},{"source":"/extend/data_log/SLT/HG00126B.1_6310_H800J0023100604_CESLT_ATCACP_DS2000DAGCB00_20181109_024914_suzamdaslt083_005_MAIN.kdf.20181109035003.log","offset":24456,"timestamp":"2018-11-09T04:00:26.127848749+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747926,"device":64770}},{"source":"/extend/data_log/SLT/HG00126B.1_6310_H800J0011100904_CESLT_ATCACP_DS2000DAGCB00_20181109_032306_suzamdaslt083_003_MAIN.kdf.20181109041004.log","offset":24458,"timestamp":"2018-11-09T04:30:27.107341741+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747922,"device":64770}},{"source":"/extend/data_log/SLT/HG00126B.1_6310_H800J0014062204_CESLT_ATCACP_DS2000DAGCB00_20181109_040002_suzamdaslt083_005_MAIN.kdf.20181109045003.log","offset":24460,"timestamp":"2018-11-09T05:00:26.638574629+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747924,"device":64770}},{"source":"/extend/data_log/SLT/HG00126B.1_6310_H800J0015060804_CESLT_ATCACP_DS2000DAGCB00_20181109_035149_suzamdaslt083_010_MAIN.kdf.20181109045004.log","offset":24459,"timestamp":"2018-11-09T05:00:26.454052835+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747927,"device":64770}},{"source":"/extend/data_log/SLT/HG00120B.1_6310_H800M0008102504_CESLT_ATCACP_DS2000DAGCB00_20181109_113431_suzamdaslt083_001_MAIN.kdf.20181109123004.log","offset":24455,"timestamp":"2018-11-09T13:00:29.383464363+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747929,"device":64770}},{"source":"/extend/data_log/SLT/HG00120B.1_6310_H800J0014090704_CESLT_ATCACP_DS2000DAGCB00_20181109_132532_suzamdaslt083_010_MAIN.kdf.20181109141003.log","offset":24461,"timestamp":"2018-11-09T14:30:30.237989457+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747919,"device":64770}},{"source":"/extend/data_log/SLT/HG00127B.1_6310_H80140011050404_CESLT_ATCACP_DS2000DAGCB00_20181109_173230_suzamdaslt083_010_MAIN.kdf.20181109183005.log","offset":24464,"timestamp":"2018-11-09T19:00:31.514328252+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747914,"device":64770}},{"source":"/extend/data_log/SLT/HG00125B.1_6310_H800J0022041304_CESLT_ATCACP_DS2000DAGCB00_20181110_075453_suzamdaslt083_002_MAIN.kdf.20181110085002.log","offset":24460,"timestamp":"2018-11-10T09:00:36.322355191+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747923,"device":64770}},{"source":"/extend/data_log/SLT/HG00157B.1_6310_H800R0025100704_CESLT_ATCACP_DS2000DAGCB00_20181110_123807_suzamdaslt083_007_MAIN.kdf.20181110133003.log","offset":24456,"timestamp":"2018-11-10T14:00:39.760406401+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747939,"device":64770}},{"source":"/extend/data_log/SLT/HG00125B.1_6310_H800J0017061004_CESLT_ATCACP_DS2000DAGCB00_20181110_033657_suzamdaslt083_000_MAIN.kdf.20181110043003.log","offset":24464,"timestamp":"2018-11-10T05:00:34.883500998+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747932,"device":64770}},{"source":"/extend/data_log/SLT/HG00193.1.1_6310_H80100014072804_SLT_AXFNCP_DS2000DAGCB00_20181111_202803_suzamdaslt083_004_MAIN.kdf.20181111211006.log","offset":28872,"timestamp":"2018-11-11T21:30:51.354757413+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747928,"device":64770}},{"source":"/extend/data_log/SLT/HG00125B.1_6310_H800J0017072804_CESLT_ATCACP_DS2000DAGCB00_20181110_043532_suzamdaslt083_006_MAIN.kdf.20181110053004.log","offset":24461,"timestamp":"2018-11-10T06:00:35.102990558+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747925,"device":64770}},{"source":"/extend/data_log/SLT/HG00191.1.1_6310_H80170006111604_SLT_AXFNCP_DS2000DAGCB00_20181111_093057_suzamdaslt116_003_MAIN.kdf.20181111101005.log","offset":28887,"timestamp":"2018-11-11T10:30:47.05959817+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747930,"device":64770}},{"source":"/extend/data_log/SLT/HG00157B.1_6310_H800S0016042404_CESLT_ATCACP_DS2000DAGCB00_20181110_110828_suzamdaslt083_006_MAIN.kdf.20181110121004.log","offset":24463,"timestamp":"2018-11-10T12:30:38.314139044+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747933,"device":64770}},{"source":"/extend/data_log/SLT/HG00125B.1_6310_H800J0012092004_CESLT_ATCACP_DS2000DAGCB00_20181110_050432_suzamdaslt083_005_MAIN.kdf.20181110061002.log","offset":24463,"timestamp":"2018-11-10T06:30:35.553049312+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747934,"device":64770}},{"source":"/extend/data_log/SLT/HG00162B.1_6310_H800R0015021804_CESLT_ATCACP_DS2000DAGCB00_20181111_050109_suzamdaslt083_004_MAIN.kdf.20181111055001.log","offset":24456,"timestamp":"2018-11-11T06:00:45.443886317+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747942,"device":64770}},{"source":"/extend/data_log/SLT/HG00191.1.1_6310_H80170011050804_SLT_AXFNCP_DS2000DAGCB00_20181111_075401_suzamdaslt116_008_MAIN.kdf.20181111085003.log","offset":28842,"timestamp":"2018-11-11T09:00:46.146198853+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747937,"device":64770}},{"source":"/extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log","offset":5382,"timestamp":"2018-11-10T21:00:42.718736704+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747941,"device":64770}}]

3

and this is my data files still left:

[tdni@tdexample01 SLT]$ ls -l |grep 20181110
-rw-r--r--. 1 tdni tdni 24463 Nov 10 06:30 HG00125B.1_6310_H800J0012092004_CESLT_ATCACP_DS2000DAGCB00_20181110_050432_suzamdaslt083_005_MAIN.kdf.20181110061002.log
-rw-r--r--. 1 tdni tdni 24464 Nov 10 05:00 HG00125B.1_6310_H800J0017061004_CESLT_ATCACP_DS2000DAGCB00_20181110_033657_suzamdaslt083_000_MAIN.kdf.20181110043003.log
-rw-r--r--. 1 tdni tdni 24461 Nov 10 06:00 HG00125B.1_6310_H800J0017072804_CESLT_ATCACP_DS2000DAGCB00_20181110_043532_suzamdaslt083_006_MAIN.kdf.20181110053004.log
-rw-r--r--. 1 tdni tdni 24460 Nov 10 09:00 HG00125B.1_6310_H800J0022041304_CESLT_ATCACP_DS2000DAGCB00_20181110_075453_suzamdaslt083_002_MAIN.kdf.20181110085002.log
-rw-r--r--. 1 tdni tdni 24456 Nov 10 14:00 HG00157B.1_6310_H800R0025100704_CESLT_ATCACP_DS2000DAGCB00_20181110_123807_suzamdaslt083_007_MAIN.kdf.20181110133003.log
-rw-r--r--. 1 tdni tdni 24463 Nov 10 12:30 HG00157B.1_6310_H800S0016042404_CESLT_ATCACP_DS2000DAGCB00_20181110_110828_suzamdaslt083_006_MAIN.kdf.20181110121004.log
-rw-r--r--. 1 tdni tdni 28891 Nov 10 19:30 HG00191.1.1_6310_H80170003122204_SLT_AXFNCP_DS2000DAGCB00_20181110_183022_suzamdaslt116_008_MAIN.kdf.20181110191007.log
-rw-r--r--. 1 tdni tdni  5382 Nov 10 21:00 HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log
4

please see the last file:

-rw-r--r--. 1 tdni tdni  5382 Nov 10 21:00 HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log

and the registry log of this file:
{"source":"/extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log","offset":5382,"timestamp":"2018-11-10T21:00:42.718736704+08:00","ttl":-1,"type":"log","meta":null,"FileStateOS":{"inode":10747941,"device":64770}}

filebeat already read all the file and goes to the end of file. file size: 5382 and "offset":5382,"timestamp":"2018-11-10T21:00:42.718736704+08:00"

5

But actually there's no any harvester event[start and close] for this file in the filebeat log.

this is part of filebeat log nearby 2018-11-10T21:100:

2018-11-10T21:00:20.688+0800    INFO    [monitoring]    log/log.go:141  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":897520,"time":{"ms":11}},"total":{"ticks":11158040,"time":{"ms":20},"value":11158040},"user":{"ticks":10260520,"time":{"ms":9}}},"info":{"ephemeral_id":"d4f349f8-f9a6-4bba-a6c4-fb917aa77c61","uptime":{"ms":205800068}},"memstats":{"gc_next":25727616,"memory_alloc":15214176,"memory_total":693948143040}},"filebeat":{"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":5,"events":{"active":0}}},"registrar":{"states":{"current":50}},"system":{"load":{"1":0.71,"15":0.23,"5":0.2,"norm":{"1":0.0177,"15":0.0058,"5":0.005}}}}}}
2018-11-10T21:00:39.042+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SORT/GFDRS_S6310A1AB0PG_P_ATC617_H802E.00_WS2_8T021D82SLB5_6_80_181110_090501.kdf.20181110203005.log
2018-11-10T21:00:41.345+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00121B.1_6310_H800J0023070404_CESLT_ATCACP_DS2000DAGCB00_20181110_195142_suzamdaslt083_004_MAIN.kdf.20181110205002.log
2018-11-10T21:00:41.345+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00121B.1_6310_H800M0007050304_CESLT_ATCACP_DS2000DAGCB00_20181110_195642_suzamdaslt083_007_MAIN.kdf.20181110205003.log
2018-11-10T21:00:41.419+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170003052304_SLT_AXFNCP_DS2000DAGCB00_20181110_195355_suzamdaslt116_005_MAIN.kdf.20181110205005.log
2018-11-10T21:00:41.419+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00121B.1_6310_H800J0023070404_CESLT_ATCACP_DS2000DAGCB00_20181110_195142_suzamdaslt083_004_MAIN.kdf.20181110205002.log. Closing because close_eof is enabled.

2018-11-10T21:00:41.419+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170008031204_SLT_AXFNCP_DS2000DAGCB00_20181110_200412_suzamdaslt116_007_MAIN.kdf.20181110205005.log
2018-11-10T21:00:41.419+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170003052304_SLT_AXFNCP_DS2000DAGCB00_20181110_195355_suzamdaslt116_005_MAIN.kdf.20181110205005.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.420+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170014060604_SLT_AXFNCP_DS2000DAGCB00_20181110_195735_suzamdaslt116_002_MAIN.kdf.20181110205006.log
2018-11-10T21:00:41.420+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170003050404_SLT_AXFNCP_DS2000DAGCB00_20181110_195758_suzamdaslt116_010_MAIN.kdf.20181110205004.log
2018-11-10T21:00:41.420+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170014060604_SLT_AXFNCP_DS2000DAGCB00_20181110_195735_suzamdaslt116_002_MAIN.kdf.20181110205006.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.420+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00121B.1_6310_H800H0020082204_CESLT_ATCACP_DS2000DAGCB00_20181110_195800_suzamdaslt083_006_MAIN.kdf.20181110205002.log
2018-11-10T21:00:41.420+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170008031204_SLT_AXFNCP_DS2000DAGCB00_20181110_200412_suzamdaslt116_007_MAIN.kdf.20181110205005.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.421+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00121B.1_6310_H800M0007050304_CESLT_ATCACP_DS2000DAGCB00_20181110_195642_suzamdaslt083_007_MAIN.kdf.20181110205003.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.421+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170007070804_SLT_AXFNCP_DS2000DAGCB00_20181110_195329_suzamdaslt116_007_MAIN.kdf.20181110203003.log
2018-11-10T21:00:41.421+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170014110804_SLT_AXFNCP_DS2000DAGCB00_20181110_195414_suzamdaslt116_009_MAIN.kdf.20181110205006.log
2018-11-10T21:00:41.422+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00121B.1_6310_H800H0002080404_CESLT_ATCACP_DS2000DAGCB00_20181110_195503_suzamdaslt083_000_MAIN.kdf.20181110205001.log
2018-11-10T21:00:41.422+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00121B.1_6310_H800U0001042104_CESLT_ATCACP_DS2000DAGCB00_20181110_195307_suzamdaslt083_001_MAIN.kdf.20181110205004.log
2018-11-10T21:00:41.422+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170006050604_SLT_AXFNCP_DS2000DAGCB00_20181110_193905_suzamdaslt116_003_MAIN.kdf.20181110203003.log
2018-11-10T21:00:41.422+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00121B.1_6310_H800H0020082204_CESLT_ATCACP_DS2000DAGCB00_20181110_195800_suzamdaslt083_006_MAIN.kdf.20181110205002.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.423+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170015042004_SLT_AXFNCP_DS2000DAGCB00_20181110_194157_suzamdaslt116_001_MAIN.kdf.20181110203004.log
2018-11-10T21:00:41.423+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170015042004_SLT_AXFNCP_DS2000DAGCB00_20181110_194157_suzamdaslt116_001_MAIN.kdf.20181110203004.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.423+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170015110604_SLT_AXFNCP_DS2000DAGCB00_20181110_195808_suzamdaslt116_008_MAIN.kdf.20181110205007.log
2018-11-10T21:00:41.423+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log
6 
2018-11-10T21:00:41.423+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170006050604_SLT_AXFNCP_DS2000DAGCB00_20181110_193905_suzamdaslt116_003_MAIN.kdf.20181110203003.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.423+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170003050404_SLT_AXFNCP_DS2000DAGCB00_20181110_195758_suzamdaslt116_010_MAIN.kdf.20181110205004.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.423+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00191.1.1_6310_H80170004080204_SLT_AXFNCP_DS2000DAGCB00_20181110_194506_suzamdaslt116_011_MAIN.kdf.20181110205005.log
2018-11-10T21:00:41.423+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170004080204_SLT_AXFNCP_DS2000DAGCB00_20181110_194506_suzamdaslt116_011_MAIN.kdf.20181110205005.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.424+0800    INFO    log/harvester.go:251    Harvester started for file: /extend/data_log/SLT/HG00121B.1_6310_H800M0014060504_CESLT_ATCACP_DS2000DAGCB00_20181110_195208_suzamdaslt083_003_MAIN.kdf.20181110205003.log
2018-11-10T21:00:41.424+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170007070804_SLT_AXFNCP_DS2000DAGCB00_20181110_195329_suzamdaslt116_007_MAIN.kdf.20181110203003.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.424+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170015110604_SLT_AXFNCP_DS2000DAGCB00_20181110_195808_suzamdaslt116_008_MAIN.kdf.20181110205007.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.424+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00121B.1_6310_H800H0002080404_CESLT_ATCACP_DS2000DAGCB00_20181110_195503_suzamdaslt083_000_MAIN.kdf.20181110205001.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.425+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_H80170014110804_SLT_AXFNCP_DS2000DAGCB00_20181110_195414_suzamdaslt116_009_MAIN.kdf.20181110205006.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.426+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00121B.1_6310_H800U0001042104_CESLT_ATCACP_DS2000DAGCB00_20181110_195307_suzamdaslt083_001_MAIN.kdf.20181110205004.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.427+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00121B.1_6310_H800P0015082404_CESLT_ATCACP_DS2000DAGCB00_20181110_195512_suzamdaslt083_008_MAIN.kdf.20181110205004.log. Closing because close_eof is enabled.
2018-11-10T21:00:41.428+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00121B.1_6310_H800M0014060504_CESLT_ATCACP_DS2000DAGCB00_20181110_195208_suzamdaslt083_003_MAIN.kdf.20181110205003.log. Closing because close_eof is enabled.
2018-11-10T21:00:50.688+0800    INFO    [monitoring]    log/log.go:141  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":898770,"time":{"ms":1253}},"total":{"ticks":11173280,"time":{"ms":15246},"value":11173280},"user":{"ticks":10274510,"time":{"ms":13993}}},"info":{"ephemeral_id":"d4f349f8-f9a6-4bba-a6c4-fb917aa77c61","uptime":{"ms":205830068}},"memstats":{"gc_next":39949568,"memory_alloc":23711584,"memory_total":694905348712,"rss":24801280}},"filebeat":{"events":{"active":7616,"added":166309,"done":158693},"harvester":{"closed":17,"open_files":1,"running":1,"started":18},"input":{"log":{"files":{"renamed":1,"truncated":8}}}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":158648,"active":3000,"batches":342,"total":161648},"read":{"bytes":1305752},"write":{"bytes":167214402}},"pipeline":{"clients":5,"events":{"active":7505,"filtered":45,"published":166153,"total":166198},"queue":{"acked":158648}}},"registrar":{"states":{"cleanup":9,"current":42,"update":158693},"writes":{"success":171,"total":171}},"system":{"load":{"1":0.6,"15":0.24,"5":0.22,"norm":{"1":0.015,"15":0.006,"5":0.0055}}}}}}
2018-11-10T21:01:20.688+0800    INFO    [monitoring]    log/log.go:141  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":901850,"time":{"ms":3084}},"total":{"ticks":11214310,"time":{"ms":41030},"value":11214310},"user":{"ticks":10312460,"time":{"ms":37946}}},"info":{"ephemeral_id":"d4f349f8-f9a6-4bba-a6c4-fb917aa77c61","uptime":{"ms":205860068}},"memstats":{"gc_next":42321184,"memory_alloc":23380776,"memory_total":697518442344,"rss":1138688}},"filebeat":{"events":{"active":597,"added":451157,"done":450560},"harvester":{"open_files":1,"running":1}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":450560,"batches":945,"total":450560},"read":{"bytes":3706008},"write":{"bytes":466521245}},"pipeline":{"clients":5,"events":{"active":8213,"published":451267,"total":451268},"queue":{"acked":450560}}},"registrar":{"states":{"current":42,"update":450560},"writes":{"success":486,"total":486}},"system":{"load":{"1":0.61,"15":0.25,"5":0.27,"norm":{"1":0.0153,"15":0.0063,"5":0.0068}}}}}}

who know why there's no any log for this file? and actually there's no start and close file log, and there's no any data of this file was send to elasticsearch.

7

after change to debug mode, it does read the file, but why there's no the eof file event in the previous log?

2018-11-12T12:17:58.483+0800    DEBUG   [input] log/input.go:404        Check file for harvesting: /extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log
2018-11-12T12:17:58.483+0800    DEBUG   [input] log/input.go:494        Update existing file for harvesting: /extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log, offset: 5382
2018-11-12T12:17:58.483+0800    DEBUG   [input] log/input.go:548        File didn't change: /extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log
8

and what's more instresting is, filebeat start to consume this data file from the start of file while I append a dummy line 'EOF' to the file.
2018-11-12T12:34:38.694+0800 DEBUG [publish] pipeline/processor.go:308 Publish event: {
"@timestamp": "2018-11-12T04:34:38.693Z",
"@metadata": {
"beat": "filebeat",
"type": "doc",
"version": "6.4.2",
"pipeline": "slt-test"
},
"offset": 0,
"message": "LotNumber=HG00191.1.1,Device=6310,Program=MAIN,ProgramVersion=DNXSP3SLT_1.0.2,Tester=suzamdaslt116_001,TestCode=AXFNCP,Operation=SLT,FileTime=2018-11-10T20:11:28.00+08:00,Type=Unit,Site=1,TestTime=19717,EndTestTime=2018-11-10T12:11:48.00+08:00,StartTestTime=2018-11-10T12:11:28.00+08:00,HBin=15,SBin=710002,SBinDesc=Test Fail Power Up Fail,HBinDesc=Fail,BinType=0,DieType=MasterDie,FileName=HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf",
"prospector": {
"type": "log"
},
"input": {
"type": "log"
},
"host": {
"name": "data-reader"
},
"beat": {
"name": "data-reader",
"hostname": "tdexample01",
"version": "6.4.2"
},
"source": "/extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log"
}

9

and the last message:

2018-11-12T12:34:38.695+0800    DEBUG   [publish]       pipeline/processor.go:308       Publish event: {
  "@timestamp": "2018-11-12T04:34:38.695Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "doc",
    "version": "6.4.2",
    "pipeline": "slt-test"
  },
  "host": {
    "name": "data-reader"
  },
  "message": "Type=File,DoneTime=2018-11-10T21:00:04.562+08:00,KDFName=HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf,UnitCnt=1,LotNumber=HG00191.1.1,Operation=SLT,KDFMonth=201811,KDFDate=20181110,TransferTime=2018-11-10T20:30:04.00+08:00,DocCnt=13,FileTime=2018-11-10T20:11:28.00+08:00,LotStartTime=2018-11-10T12:11:28.00+08:00,LotEndTime=2018-11-10T12:11:48.00+08:00,GrossTime=19",
  "source": "/extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log",
  "offset": 4962,
  "input": {
    "type": "log"
  },
  "prospector": {
    "type": "log"
  },
  "beat": {
    "name": "data-reader",
    "hostname": "tdexample01",
    "version": "6.4.2"
  }
}
2018-11-12T12:34:38.695+0800    DEBUG   [harvester]     log/harvester.go:401    Drop line as it does not match any of the include patterns EOF
2018-11-12T12:34:38.695+0800    INFO    log/harvester.go:274    End of file reached: /extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log. Closing because close_eof is enabled.
2018-11-12T12:34:38.695+0800    DEBUG   [harvester]     log/harvester.go:507    Stopping harvester for file: /extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log
2018-11-12T12:34:38.695+0800    DEBUG   [harvester]     log/harvester.go:517    Closing file: /extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log
2018-11-12T12:34:38.695+0800    DEBUG   [harvester]     log/harvester.go:387    Update state: /extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log, offset: 5386
2018-11-12T12:34:38.695+0800    DEBUG   [harvester]     log/harvester.go:528    harvester cleanup finished for file: /extend/data_log/SLT/HG00191.1.1_6310_UnknownUnitID_SLT_AXFNCP_DS2000DAGCB00_20181110_201128_suzamdaslt116_001_MAIN.kdf.20181110203004.log
2018-11-12T12:34:38.696+0800    DEBUG   [registrar]     registrar/registrar.go:393      Registry file updated. 58 states written.
2018-11-12T12:34:38.709+0800    DEBUG   [elasticsearch] elasticsearch/client.go:321     PublishEvents: 1 events have been published to elasticsearch in 14.569295ms.
2018-11-12T12:34:38.709+0800    DEBUG   [elasticsearch] elasticsearch/client.go:321     PublishEvents: 1 events have been published to elasticsearch in 14.838974ms.
10

so why filebeat send all the log until I add a new line to the end of this data file? and why it did not send the log to elasticsearch and it said no file changes and it has read all the file content before my new line append change?

11

so my conclustion for my issue:
filebeat register file shows it read all the data in the data log file, but It does not send any data to elasticsearch since no data in the elasticsearch of this data file. filebeat just read this data file from the beginning of file to the end while I append a new dummy line to the data file.
this issue only happens on some files, but alwasy happens since there're lot of new data files each day.

12

waht I found is it maybe someting about the iNode reused during old files removed and new files generated. basically my system will generate thourands of data log files TypeA for each day, and only a fews of TypeB and TypeC for each day, and this issue only happens TypeA.

what I found is a rename event is detected by filebeat, actually this should be a iNode re-use case? so how to avoid this situation?

[tdni@tdexample01 SLT]$ grep  HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log /var/log/filebeat/filebeat
2018-11-12T13:00:28.950+0800    DEBUG   [input] log/input.go:404        Check file for harvesting: /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log
2018-11-12T13:00:28.950+0800    DEBUG   [input] log/input.go:494        Update existing file for harvesting: /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log, offset: 28816
2018-11-12T13:00:28.950+0800    DEBUG   [input] log/input.go:527        File rename was detected: /extend/data_log/SLT/HG00190.1.1_6310_H80100004011704_SLT_AXFNCP_DS2000DAGCB00_20181112_112227_suzamdaslt083_006_MAIN.kdf.20181112121006.log -> /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log, Current offset: 28816
2018-11-12T13:00:28.950+0800    DEBUG   [input] log/input.go:530        Updating state for renamed file: /extend/data_log/SLT/HG00190.1.1_6310_H80100004011704_SLT_AXFNCP_DS2000DAGCB00_20181112_112227_suzamdaslt083_006_MAIN.kdf.20181112121006.log -> /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log, Current offset: 28816
2018-11-12T13:00:28.951+0800    DEBUG   [input] log/input.go:548        File didn't change: /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log
2018-11-12T13:01:18.984+0800    DEBUG   [input] log/input.go:404        Check file for harvesting: /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log
2018-11-12T13:01:18.984+0800    DEBUG   [input] log/input.go:494        Update existing file for harvesting: /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log, offset: 28816
2018-11-12T13:01:18.984+0800    DEBUG   [input] log/input.go:548        File didn't change: /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log
2018-11-12T13:02:08.991+0800    DEBUG   [input] log/input.go:404        Check file for harvesting: /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log
2018-11-12T13:02:08.991+0800    DEBUG   [input] log/input.go:494        Update existing file for harvesting: /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log, offset: 28816
2018-11-12T13:02:08.991+0800    DEBUG   [input] log/input.go:548        File didn't change: /extend/data_log/SLT/HG00190.1.1_6310_H80100005042404_SLT_AXFNCP_DS2000DAGCB00_20181112_115552_suzamdaslt083_004_MAIN.kdf.20181112125002.log
13

This topics contains a many logs and a many posts. This makes it a little difficult to see the forest for all the trees.

Let's concentrate on one log file that is still there, but should have been removed. Can you extract 1 single log file from your samples which should have been removed?
And then collect all log messages related to this log file + registry state.

filebeat just read this data file from the beginning of file to the end while I append a new dummy line to the data file.

Depends on how you did append the line. A many tools/editors do not append contents, but instead write a completely new file. After the new file is written they replace the old file with the new file. In this case the inode changes and filebeat will think it is a completely new file -> send all contents again.

Filebeat detects a rename by an inode being reused. This is perfectly normal: when a file is renamed the OS makes sure it keeps the old inode. This allows filebeat to continue an old but renamed log file.

In some cases inode reuse can indeed be an issue. The sequence of events goes like this:

  1. filebeats reads file A with inode X
  2. file is deleted by external process (as filebeat still reads the file, it actually still exists)
  3. filebeat closes file and updates state in registry
  4. a new file B is generated with inode X
  5. filebeat scans disk and finds file B with inode X
  6. filebeat thinks file B is file A, due to same inode
  7. filebeat does skip contents in file B by jumping to the old offset
14

thanks, and sorry for so may post here cz I'm really very confused since it's my first time to use filebeat for production.

I think the most probably root cause is the iNode issue since it only happens on my log TypeA.
and now I just modified the filebeat configuration file, my logic is as below:

Note: our data log files are generated in one time, first generate a temp and then rename it to the XXX.log to consume for filebeat. there's no any data in after the rename.

this is my new configuration and I just disable clean_removed, and use close_eof/ ignore_older and clean_inactive to clean the register or the harvester.

and my housekeeping script will grep the end of file event in the filebeat log, and only removed the data log files which are exceed the clean_inactive setting time, I use 4 hours for my case.

so that means the old data log files are only removed while they are consumed by filebeat and also be cleaned in the register file. so even there's a possibility of duplicate iNode, this INode is still a new iNode to filebeat. please correct me if anything wrong for my case.

thanks!

- type: log

  # Change to true to enable this input configuration.
  enabled: true

  # Paths that should be crawled and fetched. Glob based paths.
  paths:
    - /extend/data_log/FT/*.log
    #- c:\programdata\elasticsearch\logs\*

  # Exclude files. A list of regular expressions to match. Filebeat drops the files that
  # are matching any regular expression from the list. By default, no files are dropped.
  #exclude_files: ['.gz$']
  scan_frequency: 300
  close_eof: true
  clean_removed: false
  ignore_older: 2h
  clean_inactive: 3h
  harvester_limit: 5
  
  pipeline: ft-test
15

inode reuse can be somewhat tricky, but your solutions sounds good to me. Filebeat uses inodes for file identity. In your use-case you don't really need inodes, but file path would be good enough (you have no log-rotation use case here). Feel free to open an enhancement request to use the file path as identity.

16

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