Filebeat does not process any files after restart

Elastic Stack Beats
1

Hi,

We restarted filebeat in our server today and after restarting no new logs are pushed to logstash anymore.

Here is the config that we use for the input:

filebeat.inputs:
- type: log
  enabled: true
  paths:
  - /var/log/remotelogs/*/*.log
  scan_frequency: 2s
  ignore_older: 72h
  clean_inactive: 96h

output.logstash:
  hosts: ["logstash:5044"]
  ssl.enabled: true

Logstash works correctly and can receive data from other servers.

There is no indication of log files being read by harvester. lsof shows no log files are being read.

Tried to run in debug mode there is no error, but no data are pushed to Logstash.

2021-08-16T12:30:08.760+0200    INFO    [registrar]     registrar/registrar.go:109      States Loaded from registrar: 341619
2021-08-16T12:30:08.761+0200    INFO    [crawler]       beater/crawler.go:71    Loading Inputs: 1
2021-08-16T12:30:08.797+0200    DEBUG   [registrar]     registrar/registrar.go:140      Starting Registrar
2021-08-16T12:30:08.801+0200    DEBUG   [input] log/config.go:207       recursive glob enabled
2021-08-16T12:30:08.802+0200    DEBUG   [input] log/input.go:178        exclude_files: []. Number of states: 341619     {"input_id": "7c05bd9c-b9b3-45de-b720-0a502e416637"}
2021-08-16T12:30:08.803+0200    DEBUG   [input] file/states.go:68       New state added for /var/log/remotelogs/X.X.X.X/1319244.log
2021-08-16T12:30:08.803+0200    DEBUG   [acker] beater/acker.go:59      stateful ack    {"count": 1}
2021-08-16T12:30:08.804+0200    DEBUG   [publisher]     pipeline/client.go:231  Pipeline client receives callback 'onFilteredOut' for event: {Timestamp:0001-01-01 00:00:00 +0000 UTC Meta:null Fields:null Private:{Id:native::695236-64769 PrevId: Finished:true Fileinfo:<nil> Source:/var/log/remotelogs/X.X.X.X/1319244.log Offset:231 Timestamp:2021-08-14 13:04:48.85553314 +0200 CEST TTL:96h0m0s Type:log Meta:map[] FileStateOS:695236-64769 IdentifierName:native} TimeSeries:false}
2021-08-16T12:30:08.804+0200    DEBUG   [input] file/states.go:68       New state added for /var/log/remotelogs/X.X.X.X/6299244.log
2021-08-16T12:30:08.804+0200    DEBUG   [acker] beater/acker.go:59      stateful ack    {"count": 1}
2021-08-16T12:30:08.805+0200    DEBUG   [publisher]     pipeline/client.go:231  Pipeline client receives callback 'onFilteredOut' for event: {Timestamp:0001-01-01 00:00:00 +0000 UTC Meta:null Fields:null Private:{Id:native::2706842-64769 PrevId: Finished:true Fileinfo:<nil> Source:/var/log/remotelogs/X.X.X.X/6299244.log Offset:231 Timestamp:2021-08-13 16:45:38.862771576 +0200 CEST TTL:96h0m0s Type:log Meta:map[] FileStateOS:2706842-64769 IdentifierName:native} TimeSeries:false}
2021-08-16T12:30:08.805+0200    DEBUG   [input] file/states.go:68       New state added for /var/log/remotelogs/X.X.X.X/2606788.log
2021-08-16T12:30:08.806+0200    DEBUG   [acker] beater/acker.go:59      stateful ack    {"count": 1}
2021-08-16T12:30:08.806+0200    DEBUG   [registrar]     registrar/registrar.go:263      Processing 1 events
2021-08-16T12:30:08.807+0200    DEBUG   [registrar]     registrar/registrar.go:230      Registrar state updates processed. Count: 1
2021-08-16T12:30:08.811+0200    DEBUG   [registrar]     registrar/registrar.go:253      Registrar states cleaned up. Before: 341619, After: 341619, Pending: 1
2021-08-16T12:30:57.521+0200    INFO    [monitoring]    log/log.go:145  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cgroup":{"cpuacct":{"total":{"ns":3146741874}},"memory":{"mem":{"usage":{"bytes":61538304}}}},"cpu":{"system":{"ticks":2490,"time":{"ms":1055}},"total":{"ticks":17040,"time":{"ms":3148},"value":17040},"user":{"ticks":14550,"time":{"ms":2093}}},"handles":{"limit":{"hard":1048576,"soft":1024},"open":10},"info":{"ephemeral_id":"bf4579f9-2851-4d81-a48c-61005fc9d9c1","uptime":{"ms":60044},"version":"7.14.0"},"memstats":{"gc_next":1306827200,"memory_alloc":1037048024,"memory_sys":262144,"memory_total":1751020024,"rss":1361379328},"runtime":{"goroutines":16}},"filebeat":{"harvester":{"open_files":0,"running":0}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":0}},"pipeline":{"clients":1,"events":{"active":1}}},"registrar":{"states":{"current":341619}},"system":{"load":{"1":1.27,"15":1.22,"5":1.17,"norm":{"1":1.27,"15":1.22,"5":1.17}}}}}}

We have a large number of log files that is why I added ignore_older and clean_inactive.

What could be the issue? Is there any solution for this kind of issue without deleting the registry that will cause data duplication?

Thank you.

Regards,
Nugroho

2

Filebeat version is 7.14.0.

3

Looking at the log it seems the harvester has not not been started, it's been more than 12 hours stuck in "Loading input".

2021-08-16T17:46:01.277+0200    INFO    instance/beat.go:309    Setup Beat: filebeat; Version: 7.14.0
2021-08-16T17:46:01.277+0200    WARN    [cfgwarn]       tlscommon/config.go:100 DEPRECATED: Treating the CommonName field on X.509 certificates as a host name when no Subject Alternative Names are present is going to be removed. Please update your certificates if needed. Will be removed in version: 8.0.0
2021-08-16T17:46:01.277+0200    INFO    [publisher]     pipeline/module.go:113  Beat name: xxx
2021-08-16T17:46:01.277+0200    WARN    beater/filebeat.go:178  Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2021-08-16T17:46:01.278+0200    INFO    instance/beat.go:473    filebeat start running.
2021-08-16T17:46:07.944+0200    INFO    memlog/store.go:119     Loading data file of '/var/lib/filebeat/registry/filebeat' succeeded. Active transaction id=238951724
2021-08-16T17:46:08.530+0200    INFO    memlog/store.go:124     Finished loading transaction log file for '/var/lib/filebeat/registry/filebeat'. Active transaction id=238983636
2021-08-16T17:46:08.537+0200    WARN    beater/filebeat.go:381  Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2021-08-16T17:46:13.003+0200    INFO    [registrar]     registrar/registrar.go:109      States Loaded from registrar: 341619
2021-08-16T17:46:13.003+0200    INFO    [crawler]       beater/crawler.go:71    Loading Inputs: 1

@ruflin I am sorry for tagging you. I saw you answered many filebeat question. It is quite urgent for us, have created a support ticket with Elastic Cloud support but no response yet.

4

What is the size of your registry file? How many files are you having in this directory you want to read from? Can you check CPU / Memory usage of filebeat? I wonder if it is trying to cleanup the registry ...

5

@ruflin There are more than 1 million files in the directory. Most of the files contain only one line of log entry.

I have also tried in another server (less number of files 387K) without clean_inactive and ignore_older options also has the same issue, stuck during loading input, no harvester is started. So I don't think it is cleaning up registry process.

6

What happens if you start a fresh instance of filebeat and point the output to stdout of file? Will it pick the files up or nothing happens? I wonder if you hit and open file limiter issues but then I would kind of expect to see some errors.

BTW your scan frequency seems to be way too high. It will take much more then 2s to scan a million files. I wonder if scans just keep piling up?

7

@ruflin Thank you. I will give it a try and increase the scan frequency.

8

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