Beats => Logstash => Elasticsearch ingestion

Hello, I am new user of the elastic components. I am trying to get a FileBeats => Logstash => ElasticSearch pipeline working. I have been able to verify LS => ES working, but nothing is happening with FB => LS. I have checked the FileBeats log and can see that the harvester was started for the inputs. Logstash doesn't appear to do anything with the harvested data and I confirmed that no new indices show up in elasticsearch.

FileBeats.yml:
filebeat.inputs:
- type: log
  enabled: true
  paths:
    - c:\elk\logs\*

filebeat.config.modules:
  path: ${path.config}/modules.d/*.yml
  reload.enabled: false

setup.template.settings:
  index.number_of_shards: 1

output.logstash:
  hosts: ["localhost:5044"]
  index: "fb"

processors:
  - add_host_metadata: ~
  - add_cloud_metadata: ~

logstash.conf:

input {
  beats {
    port => 5044
  }
}

output {
  elasticsearch {
    hosts => ["http://localhost:9200"]
    index => "logstash-beats"
    #user => "elastic"
    #password => "changeme"
  }
}

I have verified that the ports are working with netstat and the configuration seems to be correct. There is output to the logs and seemingly without errors. I am using Postman and doing a "Get: http://localhost:9200/_cat/indices" to see if anything makes it into elasticsearch db. Can't figure out what I am doing wrong.

Please help! Thanks in advance!

Filebeats Log:
    2019-08-20T11:56:12.136-0700 INFO instance/beat.go:606 Home path: [C:\elk\filebeat] Config path: [C:\elk\filebeat] Data path: [C:\elk\filebeat\data] Logs path: [C:\elk\filebeat\logs]
    2019-08-20T11:56:12.137-0700 INFO instance/beat.go:614 Beat ID: ac845bac-bb74-4517-8732-80c6ef802e05
    2019-08-20T11:56:12.141-0700 INFO [beat] instance/beat.go:902 Beat info {"system_info": {"beat": {"path": {"config": "C:\elk\filebeat", "data": "C:\elk\filebeat\data", "home": "C:\elk\filebeat", "logs": "C:\elk\filebeat\logs"}, "type": "filebeat", "uuid": "ac845bac-bb74-4517-8732-80c6ef802e05"}}}
    2019-08-20T11:56:12.141-0700 INFO [beat] instance/beat.go:911 Build info {"system_info": {"build": {"commit": "6f0ec01a0e57fe7d4fd703b017fb5a2f6448d097", "libbeat": "7.3.0", "time": "2019-07-24T17:39:33.000Z", "version": "7.3.0"}}}
    2019-08-20T11:56:12.141-0700 INFO [beat] instance/beat.go:914 Go runtime info {"system_info": {"go": {"os":"windows","arch":"amd64","max_procs":4,"version":"go1.12.4"}}}
    2019-08-20T11:56:12.143-0700 INFO [beat] instance/beat.go:918 Host info {"system_info": {"host": {"architecture":"x86_64","boot_time":"2019-08-20T10:59:52.26-07:00","name":"vagrant-2012-r2","ip":["fe80::4c67:7188:66c1:e795/64","10.0.2.15/24","::1/128","127.0.0.1/8","fe80::5efe:a00:20f/128"],"kernel_version":"6.3.9600.19426 (winblue_ltsb_escrow.190715-1750)","mac":["08:00:27:e9:96:13","00:00:00:00:00:00:00:e0"],"os":{"family":"windows","platform":"windows","name":"Windows Server 2012 R2 Standard","version":"6.3","major":3,"minor":0,"patch":0,"build":"9600.19431"},"timezone":"PDT","timezone_offset_sec":-25200,"id":"42f11c3b-3062-4874-9ea3-50e0e08c4434"}}}
    2019-08-20T11:56:12.146-0700 INFO [beat] instance/beat.go:947 Process info {"system_info": {"process": {"cwd": "C:\elk\filebeat", "exe": "C:\elk\filebeat\filebeat.exe", "name": "filebeat.exe", "pid": 3868, "ppid": 5620, "start_time": "2019-08-20T11:56:12.109-0700"}}}
    2019-08-20T11:56:12.146-0700 INFO instance/beat.go:292 Setup Beat: filebeat; Version: 7.3.0
    2019-08-20T11:56:12.147-0700 INFO [publisher] pipeline/module.go:97 Beat name: vagrant-2012-r2
    2019-08-20T11:56:12.147-0700 WARN beater/filebeat.go:152 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.
    2019-08-20T11:56:12.147-0700 INFO instance/beat.go:421 filebeat start running.
    2019-08-20T11:56:12.147-0700 INFO [monitoring] log/log.go:118 Starting metrics logging every 30s
    2019-08-20T11:56:12.148-0700 INFO registrar/registrar.go:145 Loading registrar data from C:\elk\filebeat\data\registry\filebeat\data.json
    2019-08-20T11:56:12.148-0700 INFO registrar/registrar.go:152 States Loaded from registrar: 0
    2019-08-20T11:56:12.148-0700 WARN beater/filebeat.go:368 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.
    2019-08-20T11:56:12.148-0700 INFO crawler/crawler.go:72 Loading Inputs: 1
    2019-08-20T11:56:12.148-0700 INFO log/input.go:148 Configured paths: [c:\elk\logs*]
    2019-08-20T11:56:12.148-0700 INFO input/input.go:114 Starting input of type: log; ID: 2112759327222265173
    2019-08-20T11:56:12.148-0700 INFO crawler/crawler.go:106 Loading and starting Inputs completed. Enabled inputs: 1
    2019-08-20T11:56:12.148-0700 INFO cfgfile/reload.go:171 Config reloader started
    2019-08-20T11:56:12.149-0700 INFO cfgfile/reload.go:226 Loading of config files completed.
    2019-08-20T11:56:12.156-0700 INFO log/harvester.go:253 Harvester started for file: c:\elk\logs\test.log
    2019-08-20T11:56:15.053-0700 INFO add_cloud_metadata/add_cloud_metadata.go:347 add_cloud_metadata: hosting provider type not detected.
    2019-08-20T11:56:42.874-0700 INFO [monitoring] log/log.go:145 Non-zero metrics in the last 30s {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":15,"time":{"ms":15}},"total":{"ticks":30,"time":{"ms":30},"value":30},"user":{"ticks":15,"time":{"ms":15}}},"handles":{"open":161},"info":{"ephemeral_id":"2dc9b8c8-f8f7-4020-9f67-a946240b4427","uptime":{"ms":30028}},"memstats":{"gc_next":4523760,"memory_alloc":2700912,"memory_total":7650424,"rss":23592960},"runtime":{"goroutines":27}},"filebeat":{"events":{"added":1,"done":1},"harvester":{"open_files":1,"running":1,"started":1}},"libbeat":{"config":{"module":{"running":0},"reloads":1},"output":{"type":"logstash"},"pipeline":{"clients":1,"events":{"active":0,"filtered":1,"total":1}}},"registrar":{"states":{"current":1,"update":1},"writes":{"success":1,"total":1}},"system":{"cpu":{"cores":4}}}}}

After further troubleshooting it appears I am getting the following error in the "logstash-plain.log":

[2019-08-21T19:00:34,432][INFO ][org.logstash.beats.BeatsHandler] [local: 0:0:0:0:0:0:0:1:5044, remote: 0:0:0:0:0:0:0:1:49358] Handling exception: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 84
[2019-08-21T19:00:34,433][WARN ][io.netty.channel.DefaultChannelPipeline] An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.handler.codec.DecoderException: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 84
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:472) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:405) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:372) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:355) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.channel.AbstractChannelHandlerContext.access$300(AbstractChannelHandlerContext.java:38) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.channel.AbstractChannelHandlerContext$4.run(AbstractChannelHandlerContext.java:236) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) [netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-all-4.1.30.Final.jar:4.1.30.Final]
	at java.lang.Thread.run(Unknown Source) [?:1.8.0_221]
Caused by: org.logstash.beats.BeatsParser$InvalidFrameProtocolException: Invalid Frame Type, received: 84
	at org.logstash.beats.BeatsParser.decode(BeatsParser.java:92) ~[logstash-input-beats-6.0.0.jar:?]
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:502) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:441) ~[netty-all-4.1.30.Final.jar:4.1.30.Final]

I haven't been able to find the root cause though...

In case anyone is following my elastic adventures, I focused on isolating Filebeats and Logstash with a very simple configuration.

logstash simple.conf:

input {
    beats {
        port => "5044"
    }
}

output { 
 stdout { codec => rubydebug } 
}

Filebeat.yml:

filebeat.inputs:
- type: log
  paths:
    - c:\elk\logs\test.log

output.logstash:
  hosts: ["localhost:5044"]

Beats log basically outputs: "2019-08-21T19:57:23.400-0700 INFO log/harvester.go:253 Harvester started for file: c:\elk\logs\test.log"

Logstash sits there doing nothing apparently:

[2019-08-21T21:12:26,304][WARN ][logstash.config.source.multilocal] Ignoring the 'pipelines.yml' file because modules or command line options are specified
[2019-08-21T21:12:26,320][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"7.3.0"}
[2019-08-21T21:12:27,825][INFO ][org.reflections.Reflections] Reflections took 50 ms to scan 1 urls, producing 19 keys and 39 values 
[2019-08-21T21:12:29,530][WARN ][org.logstash.instrument.metrics.gauge.LazyDelegatingGauge] A gauge metric of an unknown type (org.jruby.RubyArray) has been create for key: cluster_uuids. This may result in invalid serialization.  It is recommended to log an issue to the responsible developer/development team.
[2019-08-21T21:12:29,547][INFO ][logstash.javapipeline    ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>4, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50, "pipeline.max_inflight"=>500, :thread=>"#<Thread:0x4c93540 run>"}
[2019-08-21T21:12:30,349][INFO ][logstash.inputs.beats    ] Beats inputs: Starting input listener {:address=>"0.0.0.0:5044"}
[2019-08-21T21:12:30,367][INFO ][logstash.javapipeline    ] Pipeline started {"pipeline.id"=>"main"}
[2019-08-21T21:12:30,483][INFO ][org.logstash.beats.Server] Starting server on port: 5044
[2019-08-21T21:12:30,500][INFO ][logstash.agent           ] Pipelines running {:count=>1, :running_pipelines=>[:main], :non_running_pipelines=>[]}
[2019-08-21T21:12:30,918][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}

The adventure continues

Hi,

There is something connecting to beats input that does not speak the expected protocol. You need to identify with <ip>:5044 what is connected to this port.

Br,
Harsh Bajaj

1 Like

Hello and thank you for replying! As far as I can tell by using netstat, the port is only being used (listening) when I have beats/logstash running. I went ahead and changed the port in the configs to 5043 for testing purposes and I am having the same issue. Is there some other way I can check what you are referring to? Thanks in advance

With regards to your Logstash exception - that's normal when a beat client disconnects. You can ignore that.

You may not be seeing events because filebeat thinks it sent everything to Logstash. Stop the filebeat service. Navigate to your filebeat install directory. Under the data directory, delete the registry directory. Start your filebeat service.

Hi Justin, thanks for the info - I deleted the data directory and re-ran everything. Logstash doesn't seem to do anything still:
ls

I was hoping that it would project out any data that is received with the out in the conf file:

output { 
 stdout { codec => rubydebug } 
}

Do you know of any other settings/files that need to be considered? Or any way to verify that data is actually making it to logstash?

thanks so much for taking time to answer

In your console output, I see it starting the Beats listener on port 5043. The config for filebeat above is trying to send the events to port 5044 (the default). Open your Logstash conf file. Change the port for Beats to 5044.
input {
beats {
port => 5044
}
}

Stop & start Logstash.

Hey Justin, the port 5043 was a troubleshooting test and had a matching value in both logstash conf and beats yml files. Another user (up above) mentioned something about "something connecting to beats input that does not speak the expected protocol". I've reverted this and tested with the default 5044 port and the outcome is this same.

Can anyone confirm that this is the expected output of filebeats when it successfully harvests and ships the associated data?

2019-08-22T06:52:15.307-0700	INFO	instance/beat.go:606	Home path: [C:\elk\filebeat] Config path: [C:\elk\filebeat] Data path: [C:\elk\filebeat\data] Logs path: [C:\elk\filebeat\logs]
2019-08-22T06:52:15.309-0700	INFO	instance/beat.go:614	Beat ID: ac845bac-bb74-4517-8732-80c6ef802e05
2019-08-22T06:52:15.309-0700	INFO	[beat]	instance/beat.go:902	Beat info	{"system_info": {"beat": {"path": {"config": "C:\\elk\\filebeat", "data": "C:\\elk\\filebeat\\data", "home": "C:\\elk\\filebeat", "logs": "C:\\elk\\filebeat\\logs"}, "type": "filebeat", "uuid": "ac845bac-bb74-4517-8732-80c6ef802e05"}}}
2019-08-22T06:52:15.309-0700	INFO	[beat]	instance/beat.go:911	Build info	{"system_info": {"build": {"commit": "6f0ec01a0e57fe7d4fd703b017fb5a2f6448d097", "libbeat": "7.3.0", "time": "2019-07-24T17:39:33.000Z", "version": "7.3.0"}}}
2019-08-22T06:52:15.309-0700	INFO	[beat]	instance/beat.go:914	Go runtime info	{"system_info": {"go": {"os":"windows","arch":"amd64","max_procs":4,"version":"go1.12.4"}}}
2019-08-22T06:52:15.314-0700	INFO	[beat]	instance/beat.go:918	Host info	{"system_info": {"host": {"architecture":"x86_64","boot_time":"2019-08-21T20:52:23.4-07:00","name":"vagrant-2012-r2","ip":["fe80::4c67:7188:66c1:e795/64","10.0.2.15/24","::1/128","127.0.0.1/8","2001:0:5cf2:8c02:1c54:153c:f5ff:fdf0/64","fe80::1c54:153c:f5ff:fdf0/64","fe80::5efe:a00:20f/128"],"kernel_version":"6.3.9600.19426 (winblue_ltsb_escrow.190715-1750)","mac":["08:00:27:e9:96:13","00:00:00:00:00:00:00:e0","00:00:00:00:00:00:00:e0"],"os":{"family":"windows","platform":"windows","name":"Windows Server 2012 R2 Standard","version":"6.3","major":3,"minor":0,"patch":0,"build":"9600.19431"},"timezone":"PDT","timezone_offset_sec":-25200,"id":"42f11c3b-3062-4874-9ea3-50e0e08c4434"}}}
2019-08-22T06:52:15.315-0700	INFO	[beat]	instance/beat.go:947	Process info	{"system_info": {"process": {"cwd": "C:\\elk\\filebeat", "exe": "C:\\elk\\filebeat\\filebeat.exe", "name": "filebeat.exe", "pid": 3560, "ppid": 2960, "start_time": "2019-08-22T06:52:15.268-0700"}}}
2019-08-22T06:52:15.315-0700	INFO	instance/beat.go:292	Setup Beat: filebeat; Version: 7.3.0
2019-08-22T06:52:15.315-0700	INFO	[publisher]	pipeline/module.go:97	Beat name: vagrant-2012-r2
2019-08-22T06:52:15.316-0700	WARN	beater/filebeat.go:152	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.
2019-08-22T06:52:15.316-0700	INFO	instance/beat.go:421	filebeat start running.
2019-08-22T06:52:15.316-0700	INFO	[monitoring]	log/log.go:118	Starting metrics logging every 30s
2019-08-22T06:52:15.317-0700	INFO	registrar/registrar.go:145	Loading registrar data from C:\elk\filebeat\data\registry\filebeat\data.json
2019-08-22T06:52:15.317-0700	INFO	registrar/registrar.go:152	States Loaded from registrar: 1
2019-08-22T06:52:15.317-0700	WARN	beater/filebeat.go:368	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.
2019-08-22T06:52:15.317-0700	INFO	crawler/crawler.go:72	Loading Inputs: 1
2019-08-22T06:52:15.317-0700	INFO	log/input.go:148	Configured paths: [c:\elk\logs\test.log]
2019-08-22T06:52:15.317-0700	INFO	input/input.go:114	Starting input of type: log; ID: 2903726485811444168 
2019-08-22T06:52:15.317-0700	INFO	crawler/crawler.go:106	Loading and starting Inputs completed. Enabled inputs: 1
2019-08-22T06:52:15.317-0700	INFO	log/harvester.go:253	Harvester started for file: c:\elk\logs\test.log
2019-08-22T06:52:46.155-0700	INFO	[monitoring]	log/log.go:145	Non-zero metrics in the last 30s	{"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":15,"time":{"ms":15}},"total":{"ticks":30,"time":{"ms":30},"value":0},"user":{"ticks":15,"time":{"ms":15}}},"handles":{"open":141},"info":{"ephemeral_id":"b4ca2c98-9110-441c-adfa-d1c03b8bc488","uptime":{"ms":30045}},"memstats":{"gc_next":7761456,"memory_alloc":4465120,"memory_total":7445408,"rss":22880256},"runtime":{"goroutines":26}},"filebeat":{"events":{"added":2,"done":2},"harvester":{"open_files":1,"running":1,"started":1}},"libbeat":{"config":{"module":{"running":0}},"output":{"type":"logstash"},"pipeline":{"clients":1,"events":{"active":0,"filtered":2,"total":2}}},"registrar":{"states":{"current":1,"update":2},"writes":{"success":2,"total":2}},"system":{"cpu":{"cores":4}}}}}

That's what I'd expect to see. You won't see the details of each entry sent to Logstash unless you enable debugging.
https://www.elastic.co/guide/en/beats/filebeat/current/enable-filebeat-debugging.html

In Logstash, you should see the entry printed to the screen when it arrives. Assuming you're still using stdout { codec => rubydebug }

Thanks Justin, appreciate you taking the time to answer. Yep, I still have the output as "stdout { codec => rubydebug }

Has anyone run into issues using localhost for filebeats and logstash? Do I need to designate the IP as 127.0.0.1?

Also, is it normal for logstash to operate on port 9600?

Thanks all

Yes, the monitoring API binds to 9600.

localhost:5044 is fine for beats. I run a test bed that has all the beats installed on the same host as the ELK stack. Works fine.

Hi Brian,

I've used winlogbeats, but not filebeats (yet), but I'm wondering a few things about the configs you have.

Are you able to confirm that filebeats has any data at all?

What about skipping logstash and sending the output to send directly to elasticsearch just for testing?

Under the "paths" statement, you've got "c:\elk\logs*", but other examples on this forum use forward slashes instead of backslashes. Try one or both of

c:/elk/logs/*

or escape like

 c:\\elk\\logs\\*

It probably doesn't hurt anything, but the 'index: "fb"' statement likely doesn't do what you expect.

For logstash testing, could you also add a test input and send some test data using netcat or telnet?

input {
  tcp {
    port => 5555
  }
}

Then test with something like:

telnet localhost 5555
hello, this is a test
ctrl + ]
quit

Let me know how it goes

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