FIlebeat from a Windows Network Share


(Jamesleech) #1

Hi,

Today I was trying to get FileBeat up and running. I have logstash, elasticsearch and kibana all setup but i'm new to FileBeat.

Previously I had logstash running on an ubuntu VM, smb mounting windows shares, and correctly tailing log files from multiple servers. These log files roll over whenever they hit 50mb. Logstash was handling this fine.

I've now got filebeat running on a windows2012r2 server pickup up files from the same windows shares. all is good until the files roll over.

They way the files are rolled over is somelog.log will be renamed somelog.1.log and a new file will be created somelog.log.

Should filebeat be able to handle this, I read through the doco, played with force_close_files and tailfiles but no luck.

The windows share thing is because i'll trailing ELK for our log analytics and can't get approval to run filebeat on the actual servers just yet.

Sorry no config atm, at home with beer. but has anyone seen this issue and got the magic bullet?


(Steffen Siering) #2

out of curiosity, the shares are backed by windows or linux?

filebeat should be able to handle this fine (more or less, we're talking about windows here).

Can you share your filebeat config?

Some debug output would be helpful too. Try fileabeat with -e -d '*' to get all debug output written to stderr.

Can you check .filebeat registry entries for the file? We're using some volume identity to figure out if file is really new or was renamed.


(ruflin) #3

Please have a look at this note here: https://www.elastic.co/guide/en/beats/filebeat/current/_getting_support.html#_network_volumes

What happens when the file is rotated? Does it start to read it again from the beginning?


(Jamesleech) #4

Hi Guys,

My config currently stands as;

filebeat:
  prospectors:
    -
      paths:
        - \\winserver\logs\single.log
      input_type: log
      fields:
        sourceType: someservicename
      tail_files: false
      force_close_files: true
output:
  elasticsearch:
    enabled: false 
    hosts: ["elasticserver:9200"] #if this is deleted config is reported as invalid.
  logstash:
    enabled: true
    hosts: ["1.1.1.1:5044"]
    index: appname

The shares are backed by Windows.

I had read through to that network volume part and as I mentioned I can't run filebeat in prod just yet, Unfortunately our servers are still pets.

If "For example, changed file identifiers may result in Filebeat reading a log file from scratch again." this was happening I'd be happy. As my understanding on that is that if a file changes name it'll re-read from the beginning. As from my config i'm monitoring only a single file. When it hits 51mb it gets renamed and a new file is created with the same name. This is where filebeat stops working.

Results from -e -d '*' in next post because of size constraits.


(Jamesleech) #5

Every log event gets outputted to the screen, then once the log file has a .1 appended and a new file is created;

2015/12/13 23:18:39.430443 preprocess.go:94: DBG Forward preprocessed events
2015/12/13 23:18:39.431444 output.go:103: DBG output worker: publish 45 events
2015/12/13 23:18:39.431444 output.go:103: DBG output worker: publish 45 events
2015/12/13 23:18:39.432447 client.go:96: DBG Try to publish %!s(int=45) events to logstash with window size %!s(int=1024)
2015/12/13 23:18:39.433452 bulkapi.go:130: DBG Sending bulk request to http://elasticserver:9200/_bulk
2015/12/13 23:18:39.497518 client.go:79: DBG %!s(int=45) events out of %!s(int=45) events sent to logstash. Continue sending ...
2015/12/13 23:18:39.569565 filebeat.go:134: INFO Events sent: 45
2015/12/13 23:18:39.569565 registrar.go:111: DBG Processing 45 events
2015/12/13 23:18:39.570566 registrar.go:142: DBG Write registry file: C:\ElasticBeats\filebeat-1.0.0-windows\registry
2015/12/13 23:18:39.571567 registrar.go:157: INFO Registry file updated. 6 states written.
2015/12/13 23:18:43.577784 prospector.go:186: DBG Start next scan
2015/12/13 23:18:43.577784 prospector.go:207: DBG scan path \windowsserver\logs\single.log
2015/12/13 23:18:43.578784 prospector.go:219: DBG Check file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:18:43.579785 prospector.go:341: DBG Update existing file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:18:43.584790 prospector.go:383: DBG Not harvesting, file didn't change: \windowsserver\logs\single.log
2015/12/13 23:18:43.941995 spooler.go:97: DBG Flushing spooler because of timemout. Events flushed: 0
2015/12/13 23:18:48.942232 spooler.go:97: DBG Flushing spooler because of timemout. Events flushed: 0
2015/12/13 23:18:53.585918 prospector.go:186: DBG Start next scan
2015/12/13 23:18:53.585918 prospector.go:207: DBG scan path \windowsserver\logs\single.log
2015/12/13 23:18:53.585918 prospector.go:219: DBG Check file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:18:53.590902 prospector.go:341: DBG Update existing file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:18:53.597936 prospector.go:383: DBG Not harvesting, file didn't change: \windowsserver\logs\single.log
2015/12/13 23:18:56.442910 spooler.go:97: DBG Flushing spooler because of timemout. Events flushed: 0
2015/12/13 23:19:03.602402 prospector.go:186: DBG Start next scan
2015/12/13 23:19:03.624410 prospector.go:207: DBG scan path \windowsserver\logs\single.log
2015/12/13 23:19:03.625402 prospector.go:219: DBG Check file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:19:03.626428 prospector.go:341: DBG Update existing file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:19:03.630408 prospector.go:383: DBG Not harvesting, file didn't change: \windowsserver\logs\single.log
2015/12/13 23:19:03.942201 spooler.go:97: DBG Flushing spooler because of timemout. Events flushed: 0
2015/12/13 23:19:08.942805 spooler.go:97: DBG Flushing spooler because of timemout. Events flushed: 0
2015/12/13 23:19:13.631339 prospector.go:186: DBG Start next scan
2015/12/13 23:19:13.631339 prospector.go:207: DBG scan path \windowsserver\logs\single.log
2015/12/13 23:19:13.631339 prospector.go:219: DBG Check file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:19:13.633338 prospector.go:341: DBG Update existing file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:19:13.637356 prospector.go:383: DBG Not harvesting, file didn't change: \windowsserver\logs\single.log
2015/12/13 23:19:13.942956 spooler.go:97: DBG Flushing spooler because of timemout. Events flushed: 0
2015/12/13 23:19:21.444375 spooler.go:97: DBG Flushing spooler because of timemout. Events flushed: 0
2015/12/13 23:19:23.638425 prospector.go:186: DBG Start next scan
2015/12/13 23:19:23.638425 prospector.go:207: DBG scan path \windowsserver\logs\single.log
2015/12/13 23:19:23.639403 prospector.go:219: DBG Check file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:19:23.640412 prospector.go:341: DBG Update existing file for harvesting: \windowsserver\logs\single.log
2015/12/13 23:19:23.644411 prospector.go:383: DBG Not harvesting, file didn't change: \windowsserver\logs\single.log

etc...


(Steffen Siering) #6

in paths you might consider using \\winserver\logs\single*.log, such that after file rotation the rotated content will be send until file end (in case filebeat didn't process complete file yet).

After file rotation the new 'single.log' should have a new file id and new file should be picked up.

Is your application using some logging library, e.g. log4net? Is file really renamed or copied?

I don't see anything of interest in logs :confused: . Maybe run with "-v -e -d '*'" ? I'm basically missing a log line saying 'Force close file' (which is logged at INFO level). Can you grep the log file for this message? force_close_file option is active if file does not exist anymore or the volume/file id changed for same file name (file/volume ids uniquely identify a file).

As I don't have much experience with windows network shares on this low level i'd like to see what happens with volume and file id on file rotation.

If possible let's run some small experiment:

  1. check log directory is empty
  2. start filebeat it capture full log
  3. start application to generate log
  4. wait log file is rotated and filebeat stop processing
  5. stop filebeat
  6. copy registry file (default is .filebeat I think) into (registry1)
  7. delete registry file
  8. start filebeat and wait for another log rotate and stop filebeat
  9. copy registry file into (registry2)

What's the content of registry1 and registry2 after processing? The registry file stores file informartion like offset, path, volume/file id in json format. The volume/file id must be different for filebeat being able to detect a file was rotated.

If volume/file ids differ in registry files, but the 'Force close file' log message is still missing it points towards a bug in filebeat.

Sorry for the inconvenience, but properly supporting windows backed volumes is quite tricky in itself. Supporting network shared windows volumes is no easier. Any help is much appreciated.


(Steffen Siering) #7

@jamesleech: @ruflin mentioned windows network shares to be a hole different beast. He tried once and ran into multiple different issues at once. Like lower file id changing by random (for same file, due to SMB/CIF having to make up some metadata) or metadata just not being updated (maybe due to metadata caching).

We'd strongly vote for not using windows, but collect log files from disk server.


(Ori Rubinfeld) #8

Hi Jamesleech,

Did you have any luck with that ?
I am also having Filebeat on a Centrol Windows server collecting logs from remote Application servers using Shares.
Accessing the files using FQDN.

\app-server\logs\mylog\file.log.*

while files can be:
file.log
file.log.1
file.log.2
.
.
.

Thanks,

Ori


(system) #9