Filebeat isn't filtering and sending huge logs

elk11 · September 5, 2018, 9:50am

Hi,

This is in continuation of: Error loading config file: yaml: line 21: did not find expected key

Config file:

filebeat.prospectors:
- type: log
  enabled: true
  paths:
    - /usr/share/filebeat/dockerlogs/3780b5604149475b7911122dfe734760e4e4cbeb70d37350ae112a34f3cf6936/*.log
  encoding: plain
  fields:
    document_type: jenkins_container_log
  registry: /usr/share/filebeat/data/registry
  include_lines: ['failed']
  json.keys_under_root: true
  json.add_error_key: true
  json.message_key: log

setup.template:
  name: "filebeat"
  pattern: "filebeat-*"
  settings:
    index.number_of_shards: 1
    index.number_of_replicas: 1
output.elasticsearch:
  hosts: ["xxx:9200"]
  index: "filebeat-%{[fields.document_type]}-%{+yyyy.MM.dd}"

My log file is about 1.3 GB, when i grep for 'failed' i get following output:

{"log":"[08/30/18 09:06:27] SSH Launch of xxx-01 on sanjay-stack1.vse.rdlabs.hpecorp.net failed in 10 ms\n","stream":"stdout","time":"2018-08-30T09:06:27.224570921Z"}
{"log":"[08/30/18 09:06:27] SSH Launch of node01 on xxx failed in 11 ms\n","stream":"stdout","time":"2018-08-30T09:06:27.225456133Z"}
{"log":"[08/30/18 09:30:27] SSH Launch of node01 on xxx failed in 6 ms\n","stream":"stdout","time":"2018-08-30T09:30:27.205131035Z"}

filebeat debug log:

2018/09/04 11:16:09.704538 registrar.go:253: DBG Registry file updated. 7 states written.
2018/09/04 11:16:09.704599 registrar.go:200: DBG Processing 1 events
2018/09/04 11:16:09.704617 registrar.go:195: DBG Registrar states cleaned up. Before: 7, After: 7
2018/09/04 11:16:09.704627 registrar.go:228: DBG Write registry file: /usr/share/filebeat/data/registry
2018/09/04 11:16:09.704791 harvester.go:353: DBG Drop line as it does not match any of the include patterns     at java.net.Socket.connect(Socket.java:538)
2018/09/04 11:16:09.705710 registrar.go:253: DBG Registry file updated. 7 states written.
2018/09/04 11:16:09.705758 registrar.go:200: DBG Processing 1 events
2018/09/04 11:16:09.705777 registrar.go:195: DBG Registrar states cleaned up. Before: 7, After: 7
2018/09/04 11:16:09.705788 registrar.go:228: DBG Write registry file: /usr/share/filebeat/data/registry
2018/09/04 11:16:09.706034 harvester.go:353: DBG Drop line as it does not match any of the include patterns     at java.net.Socket.<init>(Socket.java:434)
2018/09/04 11:16:09.706774 registrar.go:253: DBG Registry file updated. 7 states written.
2018/09/04 11:16:09.706821 registrar.go:200: DBG Processing 1 events
2018/09/04 11:16:09.706839 registrar.go:195: DBG Registrar states cleaned up. Before: 7, After: 7
2018/09/04 11:16:09.706849 registrar.go:228: DBG Write registry file: /usr/share/filebeat/data/registry
2018/09/04 11:16:09.707005 harvester.go:353: DBG Drop line as it does not match any of the include patterns     at java.net.Socket.<init>(Socket.java:211)
2018/09/04 11:16:09.707956 registrar.go:253: DBG Registry file updated. 7 states written.
2018/09/04 11:16:09.707997 registrar.go:200: DBG Processing 1 events
2018/09/04 11:16:09.708015 registrar.go:195: DBG Registrar states cleaned up. Before: 7, After: 7
2018/09/04 11:16:09.708026 registrar.go:228: DBG Write registry file: /usr/share/filebeat/data/registry
2018/09/04 11:16:09.708165 harvester.go:353: DBG Drop line as it does not match any of the include patterns     at com.jcraft.jsch.Util.createSocket(Util.java:338)
2018/09/04 11:16:09.709185 registrar.go:253: DBG Registry file updated. 7 states written.
2018/09/04 11:16:09.709224 registrar.go:200: DBG Processing 1 events
2018/09/04 11:16:09.709246 registrar.go:195: DBG Registrar states cleaned up. Before: 7, After: 7
2018/09/04 11:16:09.709259 registrar.go:228: DBG Write registry file: /usr/share/filebeat/data/registry

Even after running filebeat for long time (because the size of log file is large) nothing is being sent to elasticsearch. Can you please tell me where I am going wrong?

kvch · September 5, 2018, 12:27pm

I have tested your prospector configuration. It works correctly at my machine.
Could you share a few monitoring events to see how many events were published and dropped?

elk11 · September 5, 2018, 2:55pm

I don't see anything published in kibana. Is that what you are talking about? If not where would I find
'monitoring events'? I thought the filebeat debug log would cover it. And also the size of the log file should not matter, am I right? Because I have tested using part (some 20 lines ) of that huge log file, the config works fine for that.

kvch · September 5, 2018, 2:59pm

It is enabled by default.
Monitoring events are the logs which start with "Non-zero metrics in the last 30s".

elk11 · September 5, 2018, 3:31pm

Here's the monitoring events:

2018/09/05 15:27:45.736222 registrar.go:108: INFO Loading registrar data from /usr/share/filebeat/data/registry
2018/09/05 15:27:45.736316 registrar.go:119: INFO States Loaded from registrar: 0
2018/09/05 15:27:45.736445 crawler.go:44: INFO Loading Prospectors: 1
2018/09/05 15:27:45.736626 registrar.go:150: INFO Starting Registrar
2018/09/05 15:27:45.737329 prospector.go:103: INFO Starting prospector of type: log; id: 8005789346222350771
2018/09/05 15:27:45.737362 crawler.go:78: INFO Loading and starting Prospectors completed. Enabled prospectors: 1
2018/09/05 15:28:15.733286 metrics.go:39: INFO Non-zero metrics in the last 30s: beat.memstats.gc_next=4473924 beat.memstats.memory_alloc=3058216 beat.memstats.memory_total=3058216 filebeat.harvester.open_files=0 filebeat.harvester.running=0 libbeat.config.module.running=0 libbeat.output.type=elasticsearch libbeat.pipeline.clients=1 libbeat.pipeline.events.active=0 registrar.states.current=0 registrar.writes=1
2018/09/05 15:28:45.733253 metrics.go:39: INFO Non-zero metrics in the last 30s: beat.memstats.gc_next=4473924 beat.memstats.memory_alloc=3076344 beat.memstats.memory_total=3076344 filebeat.harvester.open_files=0 filebeat.harvester.running=0 libbeat.config.module.running=0 libbeat.pipeline.clients=1 libbeat.pipeline.events.active=0 registrar.states.current=0
2018/09/05 15:29:15.733144 metrics.go:39: INFO Non-zero metrics in the last 30s: beat.memstats.gc_next=4473924 beat.memstats.memory_alloc=3095224 beat.memstats.memory_total=3095224 filebeat.harvester.open_files=0 filebeat.harvester.running=0 libbeat.config.module.running=0 libbeat.pipeline.clients=1 libbeat.pipeline.events.active=0 registrar.states.current=0
2018/09/05 15:29:45.733556 metrics.go:39: INFO Non-zero metrics in the last 30s: beat.memstats.gc_next=4473924 beat.memstats.memory_alloc=3107512 beat.memstats.memory_total=3107512 filebeat.harvester.open_files=0 filebeat.harvester.running=0 libbeat.config.module.running=0 libbeat.pipeline.clients=1 libbeat.pipeline.events.active=0 registrar.states.current=0
2018/09/05 15:30:15.733096 metrics.go:39: INFO Non-zero metrics in the last 30s: beat.memstats.gc_next=4473924 beat.memstats.memory_alloc=3119208 beat.memstats.memory_total=3119208 filebeat.harvester.open_files=0 filebeat.harvester.running=0 libbeat.config.module.running=0 libbeat.pipeline.clients=1 libbeat.pipeline.events.active=0 registrar.states.current=0
2018/09/05 15:30:45.733165 metrics.go:39: INFO Non-zero metrics in the last 30s: beat.memstats.gc_next=4473924 beat.memstats.memory_alloc=3137832 beat.memstats.memory_total=3137832 filebeat.harvester.open_files=0 filebeat.harvester.running=0 libbeat.config.module.running=0 libbeat.pipeline.clients=1 libbeat.pipeline.events.active=0 registrar.states.current=0

kvch · September 5, 2018, 3:42pm

Could you please entries from the registry related to the files which are not visible in Kibana? If you cannot see it in Kibana, it's likely they were never sent. So deleting the entries are safe and does not lead to duplicated events. Then run filebeat again and attach the debug logs. Thanks.

elk11 · September 5, 2018, 4:23pm

These are registry file contents:

[{"source":"/usr/share/filebeat/dockerlogs/3780b5604149475b7911122dfe734760e4e4cbeb70d37350ae112a34f3cf6936/3780b5604149475b
7911122dfe734760e4e4cbeb70d37350ae112a34f3cf6936-json.log","offset":143809846,"timestamp":"2018-09-05T16:20:08.989075652Z","
ttl":-1,"type":"log","FileStateOS":{"inode":347774673,"device":64768}},{"source":"/usr/share/filebeat/dockerlogs/3780b560414
9475b7911122dfe734760e4e4cbeb70d37350ae112a34f3cf6936/half_jnk_cont.log","offset":143989392,"timestamp":"2018-09-05T16:20:08
.990217432Z","ttl":-1,"type":"log","FileStateOS":{"inode":361985643,"device":64768}}]

I tried redeploying the filebeat container (which starts fresh registry file) but it didn't help. the log is still not getting sent. And again, the log size (1.3 GB) should't matter no?

kvch · September 6, 2018, 7:33am

Yes, the size of the input file is irrelevant.

Is it possible that Filebeat cannot find the logs you want to forward? Does /usr/share/filebeat/dockerlogs/3780b5604149475b7911122dfe734760e4e4cbeb70d37350ae112a34f3cf6936/3780b5604149475b7911122dfe734760e4e4cbeb70d37350ae112a34f3cf6936-json.log stores the lines including the word "failed"?

system · October 4, 2018, 7:34am

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