Filebeat is skipping lines randomly


(Hermes Vazquez Figueras) #1

Hello,

I'm shipping my logs directly to ES with filebeat and is skipping some lines from the logs randomly. My filebeat version is 5.4.2 on Debian GNU/Linux 8 (jessie)

The following is the configuration file that I'm using:

filebeat.prospectors:
- input_type: log
  pipeline: "pb-core-log-pipeline"
  paths:
    - /path_to_file/logs/api/*.log
    - /path_to_file/logs/site/*.log
    - /path_to_file/logs/billerResponse/*.log
    - /path_to_file/logs/reporting/*.log
    - /path_to_file/logs/jobs/*.log
  ignore_older: 20m
  clean_inactive: 30m
- input_type: log
  pipeline: "pb-core-event-pipeline"
  paths:
    - /path_to_file/logs/events/*.log
  fields_under_root: true
  fields:
    type: "event"
  ignore_older: 20m
  clean_inactive: 30m

processors:
- drop_fields:
    fields: ["offset", "beat.name", "beat.version", "read_timestamp"]

output.elasticsearch:
  hosts: ["server1", "server2", "server3"]
  compression_level: 9
  worker: 3
  template.name: "logging"
  template.path: "${path.config}/logs.template.json"
  index: "logs-%{+yyyy.MM.dd}"
  indices:
    - index: "logs-event-%{+yyyy.MM.dd}"
      when.equals:
        type: "event"
    - index: "logs-login-%{+yyyy.MM.dd}"
      when.contains:
        message: "Login"

The logs file growth very quickly, except for /path_to_file/logs/events/*.log

The logs files rotates every 10 minutes. On every file I missing more than 5 events on ES at different timing. Please I need to figure out this, let me know if you need more information.

I enable debug mode and I realized that some events are Publish, but I can not find it on ES.

On the following debug output example, there is 2 events, first one at 2017-09-21T17:51:36.287Z, this was not delivered to ES, second one 2017-09-21T17:51:51.288Z, this one was deliver to ES

This is a log sample with debug enable:

2017-09-21T17:51:36Z DBG  PublishEvents: 50 events have been  published to elasticsearch in 36.920719ms.
2017-09-21T17:51:36Z DBG  PublishEvents: 50 events have been  published to elasticsearch in 37.011998ms.
2017-09-21T17:51:36Z DBG  PublishEvents: 50 events have been  published to elasticsearch in 36.807949ms.
2017-09-21T17:51:36Z DBG  PublishEvents: 50 events have been  published to elasticsearch in 36.893952ms.
2017-09-21T17:51:36Z DBG  PublishEvents: 50 events have been  published to elasticsearch in 37.049889ms.
2017-09-21T17:51:36Z DBG  PublishEvents: 50 events have been  published to elasticsearch in 24.807887ms.
2017-09-21T17:51:36Z DBG  events from worker worker queue
2017-09-21T17:51:36Z DBG  message forwarded
2017-09-21T17:51:36Z DBG  PublishEvents: 50 events have been  published to elasticsearch in 24.992345ms.
2017-09-21T17:51:36Z DBG  PublishEvents: 50 events have been  published to elasticsearch in 26.683036ms.
2017-09-21T17:51:36Z DBG  PublishEvents: 50 events have been  published to elasticsearch in 26.818002ms.
2017-09-21T17:51:36Z DBG  End of file reached: /path_to_file/api/combined.log; Backoff now.
2017-09-21T17:51:36Z DBG  PublishEvents: 36 events have been  published to elasticsearch in 28.898856ms.
2017-09-21T17:51:36Z DBG  Events sent: 1086
2017-09-21T17:51:36Z DBG  Processing 1086 events
2017-09-21T17:51:36Z DBG  Registrar states cleaned up. Before: 439, After: 439
2017-09-21T17:51:36Z DBG  Write registry file: /var/lib/filebeat/registry
2017-09-21T17:51:36Z DBG  Registry file updated. 439 states written.
2017-09-21T17:51:37Z DBG  End of file reached: /path_to_file/events/events.log; Backoff now.
.
.
.
2017-09-21T17:51:40Z DBG  End of file reached: /path_to_file/api/combined.log; Backoff now.
2017-09-21T17:51:41Z DBG  Flushing spooler because of timeout. Events flushed: 708
2017-09-21T17:51:41Z DBG  fail to apply processor drop_fields=offset, beat.name, beat.version, read_timestamp: key=read_timestamp: key not found
2017-09-21T17:51:41Z DBG  Publish: {
  "@timestamp": "2017-09-21T17:51:36.287Z",
  "beat": {
	"hostname": "hostname"
  },
  "input_type": "log",
  "message": "2367844997350\t2017-09-21T17:51:36.164900+0000\te1d7e8ee6da82c6e6350f1b0f61ddccd....",
  "source": "/path_to_file/events/events.log",
  "type": "event"
}
2017-09-21T17:51:41Z DBG  fail to apply processor drop_fields=offset, beat.name, beat.version, read_timestamp: key=read_timestamp: key not found
2017-09-21T17:51:41Z DBG  Publish: {
  "@timestamp": "2017-09-21T17:51:36.375Z",
  "beat": {
	"hostname": "hostname"
  },
  "input_type": "log",
  "message": "2367844997350\t2017-09-21T17:51:36.164900+0000\....",
  "source": "/path_to_file/site/errors.log",
  "type": "log"
}
.
.
.
2017-09-21T17:51:51Z DBG  Check file for harvesting: /path_to_file/logs/site/badrequests.log
2017-09-21T17:51:51Z DBG  Update existing file for harvesting: /path_to_file/logs/site/badrequests.log, offset: 144
2017-09-21T17:51:51Z DBG  Harvester for file is still running: /path_to_file/logs/site/badrequests.log
2017-09-21T17:51:51Z DBG  Prospector states cleaned up. Before: 433, After: 433
2017-09-21T17:51:52Z DBG  End of file reached: /path_to_file/logs/events/events.log; Backoff now.
.
.
.
2017-09-21T17:51:55Z DBG  End of file reached: /path_to_file/logs/site/combined.log; Backoff now.
2017-09-21T17:51:55Z DBG  End of file reached: /path_to_file/logs/api/combined.log; Backoff now.
2017-09-21T17:51:56Z DBG  Flushing spooler because of timeout. Events flushed: 488
2017-09-21T17:51:56Z DBG  fail to apply processor drop_fields=offset, beat.name, beat.version, read_timestamp: key=read_timestamp: key not found
2017-09-21T17:51:56Z DBG  Publish: {
  "@timestamp": "2017-09-21T17:51:51.288Z",
  "beat": {
	"hostname": "hostname"
  },
  "input_type": "log",
  "message": "2986057879\t2017-09-21T17:51:43.577800+0000\tb994e8433cbd04ac6a8e485f70078804\t....",
  "source": "/path_to_file/logs/events/events.log",
  "type": "event"
}
2017-09-21T17:51:56Z DBG  fail to apply processor drop_fields=offset, beat.name, beat.version, read_timestamp: key=read_timestamp: key not found
2017-09-21T17:51:56Z DBG  Publish: {
  "@timestamp": "2017-09-21T17:51:51.375Z",
  "beat": {
	"hostname": "hostname"
  },
  "input_type": "log",
  "message": "2986057879\t2017-09-21T17:51:43.577800+0000\t68.132.189.148\tWARN\t...",
  "source": "/path_to_file/logs/site/errors.log",
  "type": "log"
}

(Hermes Vazquez Figueras) #2

Hold on this. I think that I found the issue.


(system) #3

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