Filebeat - Windows 10 x64

Elastic Stack Beats
1

I have a bit of a unique set up, I'm trying to create a proof of concept environment to test some of the functionality. I have the following set up:

  1. Filebeat 5.3 on my host OS. This is running Windows 10 64-bit.
  2. Logstash 2.2.1 on a guest OS. This is running RHEL 7.3. (It has to be 2.2.1 for another supported product by IBM that I have running outside of this).

Basically, the problem is that I can't seem to get any communication to go through to Logstash from the Windows machine. I can telnet to the server on 5044, and I even get a message from the Logstash server about it. However, restarting Filebeat and/or changing the files in the location it is monitoring don't seem to do anything.

Filebeat.yml:

filebeat.prospectors:

  • input_type: log
    • C:/Sandbox/*.txt

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

logging.level: debug

Logstash configuration for Filebeat:

input { beats { port => 5044 } }

Any help or ideas would be greatly appreciated.

2

Can you post your filebeat log. Please also check that filebeat is not block by windows firewall or maybe a anti virus program.

3

I actually can not test but I think C:/Sandbox/*.txt has to be C:\Sandbox\*.txt

4

I'm attaching a log from this morning after I restarted the service.

2017-04-17T08:40:42-04:00 DBG Disable stderr logging
2017-04-17T08:40:42-04:00 INFO Home path: [C:\Program Files\Filebeat] Config path: [C:\Program Files\Filebeat] Data path: [C:\ProgramData\filebeat] Logs path: [C:\Program Files\Filebeat\logs]
2017-04-17T08:40:42-04:00 INFO Setup Beat: filebeat; Version: 5.3.0
2017-04-17T08:40:42-04:00 DBG Processors:
2017-04-17T08:40:42-04:00 DBG Initializing output plugins
2017-04-17T08:40:42-04:00 INFO Max Retries set to: 3
2017-04-17T08:40:42-04:00 INFO Activated logstash as output plugin.
2017-04-17T08:40:42-04:00 DBG Create output worker
2017-04-17T08:40:42-04:00 DBG No output is defined to store the topology. The server fields might not be filled.
2017-04-17T08:40:42-04:00 INFO Publisher name: LAPTOP-VDCBMHE9
2017-04-17T08:40:42-04:00 INFO Flush Interval set to: 1s
2017-04-17T08:40:42-04:00 INFO Max Bulk Size set to: 2048
2017-04-17T08:40:42-04:00 DBG create bulk processing worker (interval=1s, bulk size=2048)
2017-04-17T08:40:42-04:00 INFO filebeat start running.
2017-04-17T08:40:42-04:00 DBG Windows is interactive: false
2017-04-17T08:40:42-04:00 INFO Registry file set to: C:\ProgramData\filebeat\registry
2017-04-17T08:40:42-04:00 INFO Loading registrar data from C:\ProgramData\filebeat\registry
2017-04-17T08:40:42-04:00 INFO States Loaded from registrar: 1
2017-04-17T08:40:42-04:00 INFO Loading Prospectors: 1
2017-04-17T08:40:42-04:00 INFO Starting Registrar
2017-04-17T08:40:42-04:00 INFO Start sending events to output
2017-04-17T08:40:42-04:00 INFO Starting spooler: spool_size: 2048; idle_timeout: 5s
2017-04-17T08:40:42-04:00 DBG File Configs: [C:/Sandbox/*.txt]
2017-04-17T08:40:42-04:00 DBG exclude_files:
2017-04-17T08:40:42-04:00 DBG New state added for C:\Sandbox\Test file.txt
2017-04-17T08:40:42-04:00 INFO Prospector with previous states loaded: 1
2017-04-17T08:40:42-04:00 INFO Starting prospector of type: log; id: 4854950514442491088
2017-04-17T08:40:42-04:00 INFO Loading and starting Prospectors completed. Enabled prospectors: 1
2017-04-17T08:40:42-04:00 DBG Start next scan
2017-04-17T08:40:42-04:00 DBG Check file for harvesting: C:\Sandbox\Test file.txt
2017-04-17T08:40:42-04:00 DBG Update existing file for harvesting: C:\Sandbox\Test file.txt, offset: 0
2017-04-17T08:40:42-04:00 DBG Resuming harvesting of file: C:\Sandbox\Test file.txt, offset: 0
2017-04-17T08:40:42-04:00 DBG Setting offset for file based on seek: C:\Sandbox\Test file.txt
2017-04-17T08:40:42-04:00 DBG Setting offset for file: C:\Sandbox\Test file.txt. Offset: 0
2017-04-17T08:40:42-04:00 DBG Prospector states cleaned up. Before: 1, After: 1
2017-04-17T08:40:42-04:00 INFO Harvester started for file: C:\Sandbox\Test file.txt
2017-04-17T08:40:42-04:00 DBG End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T08:40:43-04:00 DBG End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T08:40:45-04:00 DBG End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T08:40:47-04:00 DBG Flushing spooler because of timeout. Events flushed: 2
2017-04-17T08:40:47-04:00 DBG No events to publish
2017-04-17T08:40:47-04:00 DBG Events sent: 2
2017-04-17T08:40:47-04:00 DBG Processing 2 events
2017-04-17T08:40:47-04:00 DBG Registrar states cleaned up. Before: 1, After: 1
2017-04-17T08:40:47-04:00 DBG Write registry file: C:\ProgramData\filebeat\registry
2017-04-17T08:40:47-04:00 DBG Registry file updated. 1 states written.

I also don't think the path is incorrect, but I'll change it this morning and try it.

5

Updated and restarted - no change in functionality.

6

I don't see any indications from the Filebeat log that it is failing. It looks like two events were sent from Filebeat. Are you deleting the Filebeat registry file in between tests so that Filebeat resends all events from the files each time?

Try LS with a really simple config like:

input { beats { port => 5044 } }

output { 
  stdout { 
    codec  => rubydebug {
      metadata => true
    }
  }
}
7

The output on my LS server is already very simple:

output {
  stdout { codec => json }
}

And I don't see anything after the pipeline has been started.

I also have not been deleting the registry, just making changes to the file were pretty simple.

8

Could you try stopping filebeat, deleting C:\ProgramData\filebeat\registry, and then start Filebeat again. Then post the debug logs. Let it run for at least 60 seconds so that there are metrics in the debug logs.

9

Still no change in what I'm seeing in the LS logs.

2017-04-17T12:29:29-04:00 DBG  Disable stderr logging
2017-04-17T12:29:29-04:00 INFO Home path: [C:\Program Files\Filebeat] Config path: [C:\Program Files\Filebeat] Data path: [C:\\ProgramData\\filebeat] Logs path: [C:\Program Files\Filebeat\logs]
2017-04-17T12:29:29-04:00 INFO Setup Beat: filebeat; Version: 5.3.0
2017-04-17T12:29:29-04:00 DBG  Processors: 
2017-04-17T12:29:29-04:00 DBG  Initializing output plugins
2017-04-17T12:29:29-04:00 INFO Metrics logging every 30s
2017-04-17T12:29:29-04:00 INFO Max Retries set to: 3
2017-04-17T12:29:29-04:00 INFO Activated logstash as output plugin.
2017-04-17T12:29:29-04:00 DBG  Create output worker
2017-04-17T12:29:29-04:00 DBG  No output is defined to store the topology. The server fields might not be filled.
2017-04-17T12:29:29-04:00 INFO Publisher name: LAPTOP-VDCBMHE9
2017-04-17T12:29:29-04:00 INFO Flush Interval set to: 1s
2017-04-17T12:29:29-04:00 INFO Max Bulk Size set to: 2048
2017-04-17T12:29:29-04:00 DBG  create bulk processing worker (interval=1s, bulk size=2048)
2017-04-17T12:29:29-04:00 INFO filebeat start running.
2017-04-17T12:29:29-04:00 INFO No registry file found under: C:\ProgramData\filebeat\registry. Creating a new registry file.
2017-04-17T12:29:29-04:00 DBG  Write registry file: C:\ProgramData\filebeat\registry
2017-04-17T12:29:29-04:00 DBG  Windows is interactive: false
2017-04-17T12:29:29-04:00 DBG  delete old: remove C:\ProgramData\filebeat\registry.old: The system cannot find the file specified.
2017-04-17T12:29:29-04:00 DBG  rotate to old: rename C:\ProgramData\filebeat\registry C:\ProgramData\filebeat\registry.old: The system cannot find the file specified.
2017-04-17T12:29:29-04:00 DBG  Registry file updated. 0 states written.
2017-04-17T12:29:29-04:00 INFO Loading registrar data from C:\ProgramData\filebeat\registry
2017-04-17T12:29:29-04:00 INFO States Loaded from registrar: 0
2017-04-17T12:29:29-04:00 INFO Loading Prospectors: 1
2017-04-17T12:29:29-04:00 INFO Starting Registrar
2017-04-17T12:29:29-04:00 INFO Start sending events to output
2017-04-17T12:29:29-04:00 DBG  File Configs: [C:\Sandbox\*.txt]
2017-04-17T12:29:29-04:00 INFO Starting spooler: spool_size: 2048; idle_timeout: 5s
2017-04-17T12:29:29-04:00 DBG  exclude_files: []
2017-04-17T12:29:29-04:00 INFO Prospector with previous states loaded: 0
2017-04-17T12:29:29-04:00 INFO Starting prospector of type: log; id: 14512291071695414108 
2017-04-17T12:29:29-04:00 INFO Loading and starting Prospectors completed. Enabled prospectors: 1
2017-04-17T12:29:29-04:00 DBG  Start next scan
2017-04-17T12:29:29-04:00 DBG  Check file for harvesting: C:\Sandbox\Test file.txt
2017-04-17T12:29:29-04:00 DBG  Start harvester for new file: C:\Sandbox\Test file.txt
2017-04-17T12:29:29-04:00 DBG  New state added for C:\Sandbox\Test file.txt
2017-04-17T12:29:29-04:00 DBG  Setting offset for file based on seek: C:\Sandbox\Test file.txt
2017-04-17T12:29:29-04:00 DBG  Setting offset for file: C:\Sandbox\Test file.txt. Offset: 0 
2017-04-17T12:29:29-04:00 DBG  Prospector states cleaned up. Before: 1, After: 1
2017-04-17T12:29:29-04:00 INFO Harvester started for file: C:\Sandbox\Test file.txt
2017-04-17T12:29:29-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T12:29:30-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T12:29:32-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T12:29:34-04:00 DBG  Flushing spooler because of timeout. Events flushed: 1
2017-04-17T12:29:34-04:00 DBG  No events to publish
2017-04-17T12:29:34-04:00 DBG  Events sent: 1
2017-04-17T12:29:34-04:00 DBG  Processing 1 events
2017-04-17T12:29:34-04:00 DBG  New state added for C:\Sandbox\Test file.txt
2017-04-17T12:29:34-04:00 DBG  Registrar states cleaned up. Before: 1, After: 1
2017-04-17T12:29:34-04:00 DBG  Write registry file: C:\ProgramData\filebeat\registry
2017-04-17T12:29:34-04:00 DBG  delete old: remove C:\ProgramData\filebeat\registry.old: The system cannot find the file specified.
2017-04-17T12:29:34-04:00 DBG  Registry file updated. 1 states written.
2017-04-17T12:29:36-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T12:29:39-04:00 DBG  Run prospector
2017-04-17T12:29:39-04:00 DBG  Start next scan
2017-04-17T12:29:39-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T12:29:39-04:00 DBG  Check file for harvesting: C:\Sandbox\Test file.txt
2017-04-17T12:29:39-04:00 DBG  Update existing file for harvesting: C:\Sandbox\Test file.txt, offset: 0
2017-04-17T12:29:39-04:00 DBG  Harvester for file is still running: C:\Sandbox\Test file.txt
2017-04-17T12:29:39-04:00 DBG  Prospector states cleaned up. Before: 1, After: 1
10

If it is possible, can you post what is inside you Test file.txt

11

It might seem silly, but I was just hoping to get some data across to LS. So I made it very simple:

Test file for beats. Edit.

If there is a reason this won't work, then let me know. :slight_smile:

12

Can you please add a second and a third line and look if this works.

13 
2017-04-17T20:10:23-04:00 DBG  Run prospector
2017-04-17T20:10:23-04:00 DBG  Start next scan
2017-04-17T20:10:23-04:00 DBG  Check file for harvesting: C:\Sandbox\Test file.txt
2017-04-17T20:10:23-04:00 DBG  Update existing file for harvesting: C:\Sandbox\Test file.txt, offset: 0
2017-04-17T20:10:23-04:00 DBG  Harvester for file is still running: C:\Sandbox\Test file.txt
2017-04-17T20:10:23-04:00 DBG  Prospector states cleaned up. Before: 1, After: 1
2017-04-17T20:10:23-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T20:10:28-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T20:10:28-04:00 DBG  Flushing spooler because of timeout. Events flushed: 2
2017-04-17T20:10:28-04:00 DBG  Publish: {
  "@timestamp": "2017-04-18T00:10:28.428Z",
  "beat": {
    "hostname": "LAPTOP-VDCBMHE9",
    "name": "LAPTOP-VDCBMHE9",
    "version": "5.3.0"
  },
  "input_type": "log",
  "message": "Test file for beats. Edit.",
  "offset": 28,
  "source": "C:\\Sandbox\\Test file.txt",
  "type": "log"
}
2017-04-17T20:10:28-04:00 DBG  Publish: {
  "@timestamp": "2017-04-18T00:10:28.428Z",
  "beat": {
    "hostname": "LAPTOP-VDCBMHE9",
    "name": "LAPTOP-VDCBMHE9",
    "version": "5.3.0"
  },
  "input_type": "log",
  "message": "Second line for test.",
  "offset": 51,
  "source": "C:\\Sandbox\\Test file.txt",
  "type": "log"
}
2017-04-17T20:10:28-04:00 DBG  output worker: publish 2 events
2017-04-17T20:10:28-04:00 DBG  connect
2017-04-17T20:10:28-04:00 DBG  Try to publish 2 events to logstash with window size 10
2017-04-17T20:10:28-04:00 DBG  2 events out of 2 events sent to logstash. Continue sending
2017-04-17T20:10:28-04:00 DBG  send completed
2017-04-17T20:10:28-04:00 DBG  Events sent: 2
2017-04-17T20:10:28-04:00 DBG  Processing 2 events
2017-04-17T20:10:28-04:00 DBG  Registrar states cleaned up. Before: 1, After: 1
2017-04-17T20:10:28-04:00 DBG  Write registry file: C:\ProgramData\filebeat\registry
2017-04-17T20:10:28-04:00 DBG  Registry file updated. 1 states written.
2017-04-17T20:10:29-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T20:10:29-04:00 INFO Non-zero metrics in the last 30s: libbeat.logstash.call_count.PublishEvents=1 libbeat.logstash.publish.read_bytes=6 libbeat.logstash.publish.write_bytes=269 libbeat.logstash.published_and_acked_events=2 libbeat.publisher.published_events=2 publish.events=2 registrar.states.update=2 registrar.writes=1
2017-04-17T20:10:31-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T20:10:33-04:00 DBG  Run prospector
2017-04-17T20:10:33-04:00 DBG  Start next scan
2017-04-17T20:10:33-04:00 DBG  Check file for harvesting: C:\Sandbox\Test file.txt
2017-04-17T20:10:33-04:00 DBG  Update existing file for harvesting: C:\Sandbox\Test file.txt, offset: 51
2017-04-17T20:10:33-04:00 DBG  Harvester for file is still running: C:\Sandbox\Test file.txt
2017-04-17T20:10:33-04:00 DBG  Prospector states cleaned up. Before: 1, After: 1
2017-04-17T20:10:33-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T20:10:35-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T20:10:38-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T20:10:43-04:00 DBG  Run prospector
2017-04-17T20:10:43-04:00 DBG  Start next scan
2017-04-17T20:10:43-04:00 DBG  Check file for harvesting: C:\Sandbox\Test file.txt
2017-04-17T20:10:43-04:00 DBG  Update existing file for harvesting: C:\Sandbox\Test file.txt, offset: 51
2017-04-17T20:10:43-04:00 DBG  Harvester for file is still running: C:\Sandbox\Test file.txt
2017-04-17T20:10:43-04:00 DBG  Prospector states cleaned up. Before: 1, After: 1
2017-04-17T20:10:43-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T20:10:43-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T20:10:48-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T20:10:53-04:00 DBG  Run prospector
2017-04-17T20:10:53-04:00 DBG  Start next scan
2017-04-17T20:10:53-04:00 DBG  Check file for harvesting: C:\Sandbox\Test file.txt
2017-04-17T20:10:53-04:00 DBG  Update existing file for harvesting: C:\Sandbox\Test file.txt, offset: 51
2017-04-17T20:10:53-04:00 DBG  Harvester for file is still running: C:\Sandbox\Test file.txt
2017-04-17T20:10:53-04:00 DBG  Prospector states cleaned up. Before: 1, After: 1
2017-04-17T20:10:53-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T20:10:53-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T20:10:58-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T20:10:59-04:00 INFO No non-zero metrics in the last 30s
2017-04-17T20:11:03-04:00 DBG  Run prospector
2017-04-17T20:11:03-04:00 DBG  Start next scan
2017-04-17T20:11:03-04:00 DBG  End of file reached: C:\Sandbox\Test file.txt; Backoff now.
2017-04-17T20:11:03-04:00 DBG  Check file for harvesting: C:\Sandbox\Test file.txt
2017-04-17T20:11:03-04:00 DBG  Update existing file for harvesting: C:\Sandbox\Test file.txt, offset: 51
2017-04-17T20:11:03-04:00 DBG  Harvester for file is still running: C:\Sandbox\Test file.txt
2017-04-17T20:11:03-04:00 DBG  Prospector states cleaned up. Before: 1, After: 1
2017-04-17T20:11:03-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T20:11:08-04:00 DBG  Flushing spooler because of timeout. Events flushed: 0
2017-04-17T20:11:13-04:00 DBG  Run prospector

So I see the data populated in the log now for Filebeat. However, still nothing showing that it even received it. I can easily telnet and see that activity, which is odd. I've also added an exception to the Windows firewall to allow all connections on 5044 with the Filebeat application.

14

I don't know whats going on on LS side. But filebeat is working correctly. And LS also sends an ACK that is has received those 2 events. @andrewkroh?

15

I suppose it would help if I provided those logs. I have them tailed as I'm working through this. The only thing I see, is the pipeline started:

{:timestamp=>"2017-04-12T14:15:01.022000-0400", :message=>"Adding pattern", "RPROCESSING"=>"\\W*Processing by %{RCONTROLLER} as (?<format>\\S+)(?:\\W*Parameters: {%{DATA:params}}\\W*)?", :level=>:info}
{:timestamp=>"2017-04-12T14:15:01.023000-0400", :message=>"Adding pattern", "RAILS3FOOT"=>"Completed %{NUMBER:response}%{DATA} in %{NUMBER:totalms}ms %{RAILS3PROFILE}%{GREEDYDATA}", :level=>:info}
{:timestamp=>"2017-04-12T14:15:01.024000-0400", :message=>"Adding pattern", "RAILS3PROFILE"=>"(?:\\(Views: %{NUMBER:viewms}ms \\| ActiveRecord: %{NUMBER:activerecordms}ms|\\(ActiveRecord: %{NUMBER:activerecordms}ms)?", :level=>:info}
{:timestamp=>"2017-04-12T14:15:01.024000-0400", :message=>"Adding pattern", "RAILS3"=>"%{RAILS3HEAD}(?:%{RPROCESSING})?(?<context>(?:%{DATA}\\n)*)(?:%{RAILS3FOOT})?", :level=>:info}
{:timestamp=>"2017-04-12T14:15:01.025000-0400", :message=>"Adding pattern", "REDISTIMESTAMP"=>"%{MONTHDAY} %{MONTH} %{TIME}", :level=>:info}
{:timestamp=>"2017-04-12T14:15:01.025000-0400", :message=>"Adding pattern", "REDISLOG"=>"\\[%{POSINT:pid}\\] %{REDISTIMESTAMP:timestamp} \\* ", :level=>:info}
{:timestamp=>"2017-04-12T14:15:01.026000-0400", :message=>"Adding pattern", "RUBY_LOGLEVEL"=>"(?:DEBUG|FATAL|ERROR|WARN|INFO)", :level=>:info}
{:timestamp=>"2017-04-12T14:15:01.027000-0400", :message=>"Adding pattern", "RUBY_LOGGER"=>"[DFEWI], \\[%{TIMESTAMP_ISO8601:timestamp} #%{POSINT:pid}\\] *%{RUBY_LOGLEVEL:loglevel} -- +%{DATA:progname}: %{GREEDYDATA:message}", :level=>:info}
{:timestamp=>"2017-04-12T14:15:01.031000-0400", :message=>"Starting pipeline", :id=>"base", :pipeline_workers=>2, :batch_size=>125, :batch_delay=>5, :max_inflight=>250, :level=>:info}
{:timestamp=>"2017-04-12T14:15:01.033000-0400", :message=>"Pipeline started", :level=>:info}

I appreciate the help. :slight_smile:

16

It appears as if Logstash has acknowledged the events and everything it working properly on the Filebeat side.

How are you running Logstash? I'm pretty sure that the stdout is not going to show up in normal LS log file. I think you need to run LS in the foreground. You might want to add a file output to the LS config and see if data shows up there.

17

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