Filebeat on FreeBSD / PFsense

Noebas · January 3, 2016, 6:58pm

I'am trying to use filebeat on freebsd (pfsense), reading the filter.log

This is working fine on filebeat startup, but after this the logging stops, If i then stop and restart filebeat it starts logging againt and stops.

My config:

filebeat:
prospectors:
-
paths:
- /var/log/filter.log

input_type: log

output:
logstash:
hosts: ["172.21.10.53:5044"]

The debug log
016/01/03 18:55:28.779289 prospector.go:179: DBG Start next scan
2016/01/03 18:55:28.779351 prospector.go:246: DBG scan path /var/log/filter.log
2016/01/03 18:55:28.779391 prospector.go:259: DBG Check file for harvesting: /var/log/filter.log
2016/01/03 18:55:28.779419 prospector.go:382: DBG Update existing file for harvesting: /var/log/filter.log
2016/01/03 18:55:28.779437 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/filter.log
2016/01/03 18:55:30.859265 spooler.go:97: DBG Flushing spooler because of timeout. Events flushed: 0
2016/01/03 18:55:34.539342 reader.go:138: DBG End of file reached: /var/log/filter.log; Backoff now.
2016/01/03 18:55:38.385313 spooler.go:97: DBG Flushing spooler because of timeout. Events flushed: 0
2016/01/03 18:55:38.789296 prospector.go:179: DBG Start next scan
2016/01/03 18:55:38.789382 prospector.go:246: DBG scan path /var/log/filter.log
2016/01/03 18:55:38.789426 prospector.go:259: DBG Check file for harvesting: /var/log/filter.log
2016/01/03 18:55:38.789454 prospector.go:382: DBG Update existing file for harvesting: /var/log/filter.log
2016/01/03 18:55:38.789472 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/filter.log

After the restart it is doing full line read and seems to pick up the changes

2016/01/03 19:03:28.572166 util.go:20: DBG full line read
2016/01/03 19:03:28.572201 util.go:20: DBG full line read
2016/01/03 19:03:28.572237 util.go:20: DBG full line read
2016/01/03 19:03:28.572266 util.go:20: DBG full line read
2016/01/03 19:03:28.572298 util.go:20: DBG full line read
2016/01/03 19:03:28.572332 util.go:20: DBG full line read
2016/01/03 19:03:28.572396 util.go:20: DBG full line read
2016/01/03 19:03:28.572434 util.go:20: DBG full line read
2016/01/03 19:03:28.572704 spooler.go:77: INFO Starting spooler: spool_size: 1024; idle_timeout: 5s
2016/01/03 19:03:28.572757 crawler.go:71: DBG Registrar will re-save state for /var/log/filter.log
2016/01/03 19:03:28.572782 crawler.go:65: DBG No pending prospectors. Finishing setup
2016/01/03 19:03:28.572805 crawler.go:78: INFO All prospectors initialised with 1 states to persist
2016/01/03 19:03:28.572829 registrar.go:83: INFO Starting Registrar
2016/01/03 19:03:28.572875 filebeat.go:126: INFO Start sending events to output
2016/01/03 19:03:28.572929 prospector.go:246: DBG scan path /var/log/filter.log
2016/01/03 19:03:28.572993 prospector.go:259: DBG Check file for harvesting: /var/log/filter.log
2016/01/03 19:03:28.573040 prospector.go:382: DBG Update existing file for harvesting: /var/log/filter.log
2016/01/03 19:03:28.573068 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/filter.log
2016/01/03 19:03:28.575709 reader.go:138: DBG End of file reached: /var/log/filter.log; Backoff now.
2016/01/03 19:03:29.579292 reader.go:138: DBG End of file reached: /var/log/filter.log; Backoff now.
2016/01/03 19:03:31.120500 spooler.go:97: DBG Flushing spooler because of timeout. Events flushed: 8
2016/01/03 19:03:31.120647 preprocess.go:37: DBG Start Preprocessing
2016/01/03 19:03:31.120838 publish.go:102: DBG Publish: {
"@timestamp": "2016-01-03T19:03:28.572Z",

and it updating the registry also looking ok to me

016/01/03 19:05:17.544438 client.go:122: DBG Try to publish 36 events to logstash with window size 10
2016/01/03 19:05:17.555883 client.go:196: DBG update max ok window size: 0 < 10
2016/01/03 19:05:17.555937 client.go:200: DBG increase window size to: 15
2016/01/03 19:05:17.555971 client.go:100: DBG 10 events out of 36 events sent to logstash. Continue sending ...
2016/01/03 19:05:17.555997 client.go:122: DBG Try to publish 26 events to logstash with window size 15
2016/01/03 19:05:17.591491 client.go:196: DBG update max ok window size: 10 < 15
2016/01/03 19:05:17.591555 client.go:200: DBG increase window size to: 23
2016/01/03 19:05:17.591591 client.go:100: DBG 15 events out of 26 events sent to logstash. Continue sending ...
2016/01/03 19:05:17.591618 client.go:122: DBG Try to publish 11 events to logstash with window size 23
2016/01/03 19:05:17.636516 client.go:100: DBG 11 events out of 11 events sent to logstash. Continue sending ...
2016/01/03 19:05:17.636605 filebeat.go:138: INFO Events sent: 36
2016/01/03 19:05:17.636671 registrar.go:111: DBG Processing 36 events
2016/01/03 19:05:17.636723 registrar.go:142: DBG Write registry file: /home/backup/.filebeat
2016/01/03 19:05:17.637011 registrar.go:157: INFO Registry file updated. 1 states written.

ruflin · January 4, 2016, 7:42am

Which Filebeat version are you using?

Noebas · January 4, 2016, 7:58am

I'am using filebeat version 1.0.0 (386) build 129 but also tried the 64bit. Got it form the site here:

https://beats-nightlies.s3.amazonaws.com/index.html?prefix=jenkins/filebeat/129-17fce387888052987c1e2e62f8260f80f16d67d7/

Just to confirm if i stop and start it wil process all log's correctly

Noebas · January 5, 2016, 8:24am

Is there anyboby that did get it working on FreeBsd, or is there any extra logging / debugging i can do?

ruflin · January 5, 2016, 9:04am

For the freebsd binary have a look at this issue: https://github.com/elastic/beats/issues/583

Can you please upgrade to 1.0.1 or even use the 1.1 snapshot as in 1.0.0 there are some known issues.

Noebas · January 5, 2016, 10:20am

Upgrading is no problem, but can i just download the binary or do i have to compile it?

Because i can not find it here : https://beats-nightlies.s3.amazonaws.com/index.html?prefix=jenkins/filebeat/135-adffd8d72409cb1a4b14be25b7d1ae578e622e56/

ruflin · January 5, 2016, 10:55am

There are 3 freebsd binaries listed on the page you linked. Does non of these work?

Noebas · January 5, 2016, 10:57am

No none of those work, using these https://beats-nightlies.s3.amazonaws.com/index.html?prefix=jenkins/filebeat/135-adffd8d72409cb1a4b14be25b7d1ae578e622e56/

So wondering if i'am usering the right file location?

ruflin · January 5, 2016, 11:09am

The location is correct. What happens if you try to run the binary? Can you try to compile it yourself and see if the outcome is the same?

Noebas · January 5, 2016, 11:51am

Binary runs fine, giving
[2.2.6-RELEASE][root@fw01klantnaam.domain.local]/root: ./filebeat -version
filebeat version 1.2.0 (amd64)

but the same result, runs fine but stops picking up changes. If i then stop it and start it again it will see the changes en send them.

ruflin · January 5, 2016, 12:06pm

Are you using a shared file system?
Can you share again the debug log output from version 1.2.0?

Noebas · January 5, 2016, 12:48pm

No i'am running direct on the server the filesystem is not shared

log:
2016/01/05 12:43:09.118190 prospector.go:179: DBG Start next scan
2016/01/05 12:43:09.118242 prospector.go:246: DBG scan path /var/log/filter.log
2016/01/05 12:43:09.118292 prospector.go:259: DBG Check file for harvesting: /var/log/filter.log
2016/01/05 12:43:09.118320 prospector.go:382: DBG Update existing file for harvesting: /var/log/filter.log
2016/01/05 12:43:09.118344 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/filter.log
2016/01/05 12:43:09.118359 prospector.go:246: DBG scan path /var/log/dhcpd.log
2016/01/05 12:43:09.118397 prospector.go:259: DBG Check file for harvesting: /var/log/dhcpd.log
2016/01/05 12:43:09.118420 prospector.go:382: DBG Update existing file for harvesting: /var/log/dhcpd.log
2016/01/05 12:43:09.118434 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/dhcpd.log
2016/01/05 12:43:09.118447 prospector.go:246: DBG scan path /var/log/system.log
2016/01/05 12:43:09.118469 prospector.go:259: DBG Check file for harvesting: /var/log/system.log
2016/01/05 12:43:09.118491 prospector.go:382: DBG Update existing file for harvesting: /var/log/system.log
2016/01/05 12:43:09.118504 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/system.log
2016/01/05 12:43:09.118517 prospector.go:246: DBG scan path /var/log/snort/snort_/alert
2016/01/05 12:43:14.588231 reader.go:138: DBG End of file reached: /var/log/system.log; Backoff now.
2016/01/05 12:43:14.588248 reader.go:138: DBG End of file reached: /var/log/dhcpd.log; Backoff now.
2016/01/05 12:43:14.588267 reader.go:138: DBG End of file reached: /var/log/filter.log; Backoff now.
2016/01/05 12:43:16.008204 spooler.go:97: DBG Flushing spooler because of timeout. Events flushed: 0
2016/01/05 12:43:19.138255 prospector.go:179: DBG Start next scan
2016/01/05 12:43:19.138313 prospector.go:246: DBG scan path /var/log/filter.log
2016/01/05 12:43:19.138362 prospector.go:259: DBG Check file for harvesting: /var/log/filter.log
2016/01/05 12:43:19.138389 prospector.go:382: DBG Update existing file for harvesting: /var/log/filter.log
2016/01/05 12:43:19.138407 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/filter.log
2016/01/05 12:43:19.138422 prospector.go:246: DBG scan path /var/log/dhcpd.log
2016/01/05 12:43:19.138444 prospector.go:259: DBG Check file for harvesting: /var/log/dhcpd.log
2016/01/05 12:43:19.138465 prospector.go:382: DBG Update existing file for harvesting: /var/log/dhcpd.log
2016/01/05 12:43:19.138479 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/dhcpd.log
2016/01/05 12:43:19.138492 prospector.go:246: DBG scan path /var/log/system.log
2016/01/05 12:43:19.138514 prospector.go:259: DBG Check file for harvesting: /var/log/system.log
2016/01/05 12:43:19.138535 prospector.go:382: DBG Update existing file for harvesting: /var/log/system.log
2016/01/05 12:43:19.138548 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/system.log
2016/01/05 12:43:19.138561 prospector.go:246: DBG scan path /var/log/snort/snort_/alert
2016/01/05 12:43:21.008289 spooler.go:97: DBG Flushing spooler because of timeout. Events flushed: 0

Noebas · January 5, 2016, 12:48pm

Then stopping it:
C2016/01/05 12:43:32.165585 service.go:30: DBG Received sigterm/sigint, stopping
2016/01/05 12:43:32.165619 registrar.go:129: INFO Stopping Registrar
2016/01/05 12:43:32.165637 registrar.go:93: INFO Ending Registrar
2016/01/05 12:43:32.165655 registrar.go:142: DBG Write registry file: /root/.filebeat
2016/01/05 12:43:32.165948 registrar.go:157: INFO Registry file updated. 3 states written.
2016/01/05 12:43:32.166081 beat.go:185: INFO Cleaning up filebeat before shutting down.
[2.2.6-RELEASE][root@fw01klantnaam.domain.local]/root:

Noebas · January 5, 2016, 12:49pm

and statring again (and it picking up the cange):
6/01/05 12:43:50.024396 prospector.go:259: DBG Check file for harvesting: /var/log/system.log
2016/01/05 12:43:50.024546 prospector.go:382: DBG Update existing file for harvesting: /var/log/system.log
2016/01/05 12:43:50.024665 prospector.go:425: DBG Not harvesting, file didn't change: /var/log/system.log
2016/01/05 12:43:50.024780 prospector.go:246: DBG scan path /var/log/snort/snort_*/alert
2016/01/05 12:43:50.022743 util.go:20: DBG full line read
2016/01/05 12:43:50.024958 util.go:20: DBG full line read
2016/01/05 12:43:50.024972 util.go:20: DBG full line read
2016/01/05 12:43:50.024986 util.go:20: DBG full line read
2016/01/05 12:43:50.025003 util.go:20: DBG full line read
2016/01/05 12:43:50.025051 util.go:20: DBG full line read
2016/01/05 12:43:50.025067 util.go:20: DBG full line read
2016/01/05 12:43:50.036113 reader.go:138: DBG End of file reached: /var/log/system.log; Backoff now.
2016/01/05 12:43:50.039518 reader.go:138: DBG End of file reached: /var/log/filter.log; Backoff now.
2016/01/05 12:43:50.041737 reader.go:138: DBG End of file reached: /var/log/dhcpd.log; Backoff now.
2016/01/05 12:43:51.049504 reader.go:138: DBG End of file reached: /var/log/system.log; Backoff now.
2016/01/05 12:43:51.049559 reader.go:138: DBG End of file reached: /var/log/filter.log; Backoff now.
2016/01/05 12:43:51.049577 reader.go:138: DBG End of file reached: /var/log/dhcpd.log; Backoff now.
2016/01/05 12:43:52.538229 spooler.go:97: DBG Flushing spooler because of timeout. Events flushed: 26
2016/01/05 12:43:52.538387 preprocess.go:37: DBG Start Preprocessing
2016/01/05 12:43:52.538562 publish.go:102: DBG Publish: {
"@timestamp": "2016-01-05T12:43:50.021Z",
"beat": {
"hostname": "fw01klantnaam.domain.local",
"name": "fw01klantnaam.domain.local"
},
"count": 1,
"fields": null,
"input_type": "log",
"message": "Jan 5 12:59:54 fw01klantnaam filterlog: 74,16777216,,1000002665,em1,match,pass,out,4,0x0,,64,44471,0,DF,6,tcp,60,172.21.10.199,172.21.10.53,8549,5044,0,S,163065722,,65228,,mss;nop;wscale;sackOK;TS",
"offset": 16793,
"source": "/var/log/filter.log",
"type": "log"

ruflin · January 5, 2016, 3:56pm

That is quite strange. Based on your config in the beginning I assume you don't use any special scan_frequency or ignore_older? There is also no file rotation happening?

Can you check when filebeat is not sending any updates anymore what the last modified date of the files was? And what happens if you update the file manually?

Thanks for your patience and help.

Noebas · January 5, 2016, 4:08pm

There is no scan_frequency or ignore_older, but i did try those in differect setting but non helpt. The files can rotate but i did check that this is not the case during testing.

The last moified date will change during a running filebeat, manualy addding a entry will not trigger.

ruflin · January 6, 2016, 1:23pm

What is the file system type your are using?

Noebas · January 6, 2016, 6:51pm

Running on FreeBSD 10.1 using UFS.

In the meanwhile i did some more testing because i'am running on vmware. But a physical system installed on a shuttle pc is giving the same result.

ruflin · January 6, 2016, 7:24pm

I think I really have to try it out myself on FreeBSD. I get more and more the feeling, that it is a FreeBSD and not a general issue. One guess I have is that there is something wrong either with inode changes or reading modification changes, but that doesn't explain why it works on restart.

One very interesting thing would be to run our unit and system tests on freebsd. For the unit-tests, could you run make unit-tests inside the filebeat directory? For the full testsuite, run make testsuite, but it requires python. It would be interesting if these tests pass.

Noebas · January 7, 2016, 8:54am

I also did a dirty trick, but this works. A Script kills filebeat and starts it again evenry minute. This works and i am getting the logs.