Filebeat on pfSense (freebsd-386) only reads logs at startup

Elastic Stack Beats
1

On pfSense 2.2 (32-bit), filebeat will only read the log files once when it starts up. It appears everything works correctly for the first read -- everything reaches the stack like I expect. After that, no additional logs ever come, just these entries in filebeat's own logging output:

2016/08/19 15:25:04.118205 logp.go:223: INFO No non-zero metrics in the last 30s
2016/08/19 15:25:34.075001 logp.go:223: INFO No non-zero metrics in the last 30s
2016/08/19 15:26:04.075166 logp.go:223: INFO No non-zero metrics in the last 30s
etc.

These are busy logs, so this shouldn't be happening. These are also normal linear, ascii logs. Not the pfsense binary, circular system logs. So no issues, there.

I have been using binaries from https://beats-nightlies.s3.amazonaws.com/index.html?prefix=jenkins/filebeat/ -- which might be related. I couldn't find any "stable version" binaries for freebsd-386.

What can I do?

2

Could you set the log level to debug and share the output? This should give us some additional hints on what is going on. Could you also share your config file?

As we don't have any official builds for freebsd, the nighly builds are the best way to go.

3

(Sorry for the delay -- I was out of the office when you replied)

Yes, absolutely. Here is the config file, with a couple unimport organization-specific bits redacted.

filebeat:
  prospectors:
    -
      paths:
        - /var/log/xxxxxx.log # redacted
      input_type: log
      document_type: log
    -
      paths:
        - /usr/local/xxxxx.log # redacted
      input_type: log
      document_type: log
    -
      paths:
        - /var/log/ram/dhcpd.log
      input_type: log
      document_type: dhcpd
    -
      paths:
        - /var/log/ram/filter.log
      input_type: log
      document_type: filter
    -
      paths:
        - /var/log/ram/gateways.log
      input_type: log
      document_type: gateways
    -
      paths:
        - /var/log/ram/ipsec.log
      input_type: log
      document_type: ipsec
    -
      paths:
        - /var/log/ram/l2tps.log
      input_type: log
      document_type: l2tps
    -
      paths:
        - /var/log/ram/lighttpd.log
      input_type: log
      document_type: lighttpd
    -
      paths:
        - /var/log/ram/ntpd.log
      input_type: log
      document_type: ntpd
    -
      paths:
        - /var/log/ram/openvpn.log
      input_type: log
      document_type: openvpn
    -
      paths:
        - /var/log/ram/poes.log
      input_type: log
      document_type: poes
    -
      paths:
        - /var/log/ram/portalauth.log
      input_type: log
      document_type: portalauth
    -
      paths:
        - /var/log/ram/ppp.log
      input_type: log
      document_type: ppp
    -
      paths:
        - /var/log/ram/pptps.log
      input_type: log
      document_type: pptps
    -
      paths:
        - /var/log/ram/relayd.log
      input_type: log
      document_type: relayd
    -
      paths:
        - /var/log/ram/resolver.log
      input_type: log
      document_type: resolver
    -
      paths:
        - /var/log/ram/routing.log
      input_type: log
      document_type: routing
    -
      paths:
        - /var/log/ram/system.log
      input_type: log
      document_type: system
    -
      paths:
        - /var/log/ram/vpn.log
      input_type: log
      document_type: vpn
    -
      paths:
        - /var/log/ram/wireless.log
      input_type: log
      document_type: wireless
  # General settings
  registry_file: /usr/local/libexec/filebeat_registry

output:
  logstash:
    hosts: ["xxxxxxxxxx:xxxx"] # redacted
    bulk_max_size: 1024
    tls:
      certificate_authorities: ["/etc/ssl/filebeat/xxxxx.crt"]  # redacted

Your forum software limits the size of posts to 5000 characters, so I'll have to post the other stuff in different post(s).

4

Here is the output when I run filebeat with the extra -d '*' option (that was the only way to turn on debugging that I found -- is that what you wanted?).

2016/08/24 22:49:44.057145 beat.go:263: INFO Home path: [/usr/local/bin] Config path: [/usr/local/bin] Data path: [/usr/local/bin/data] Logs path: [/usr/local/bin/logs]
2016/08/24 22:49:44.057269 beat.go:174: INFO Setup Beat: filebeat; Version: 5.0.0-alpha6-git3850d0e
2016/08/24 22:49:44.057427 logp.go:210: INFO Metrics logging every 30s
2016/08/24 22:49:44.058897 logstash.go:96: INFO Max Retries set to: 3
2016/08/24 22:49:44.059074 outputs.go:106: INFO Activated logstash as output plugin.
2016/08/24 22:49:44.059403 publish.go:301: INFO Publisher name: xxxxxx # redacted
2016/08/24 22:49:44.059851 async.go:63: INFO Flush Interval set to: 1s
2016/08/24 22:49:44.059894 async.go:64: INFO Max Bulk Size set to: 1024
2016/08/24 22:49:44.060452 beat.go:204: INFO filebeat start running.
2016/08/24 22:49:44.060651 registrar.go:61: INFO Registry file set to: /usr/local/libexec/filebeat_registry
2016/08/24 22:49:44.060859 registrar.go:94: INFO Loading registrar data from /usr/local/libexec/filebeat_registry
2016/08/24 22:49:44.060966 registrar.go:106: ERR Error decoding states: EOF
2016/08/24 22:49:44.061050 registrar.go:162: ERR Error loading state: EOF
2016/08/24 22:49:44.061093 filebeat.go:80: ERR Could not start registrar: EOF
2016/08/24 22:49:44.061302 crawler.go:35: INFO Loading Prospectors: 20
2016/08/24 22:49:44.061445 publish.go:101: INFO Start sending events to output
2016/08/24 22:49:44.061531 prospector_log.go:40: INFO Load previous states from registry into memory
2016/08/24 22:49:44.061577 prospector_log.go:53: INFO Previous states loaded: 0
2016/08/24 22:49:44.061594 spooler.go:67: INFO Starting spooler: spool_size: 2048; idle_timeout: 5s
2016/08/24 22:49:44.061964 prospector_log.go:40: INFO Load previous states from registry into memory
2016/08/24 22:49:44.062000 prospector_log.go:53: INFO Previous states loaded: 0
[snipped a bunch of extremely similar lines here]
2016/08/24 22:49:44.068674 prospector_log.go:53: INFO Previous states loaded: 0
2016/08/24 22:49:44.068896 crawler.go:47: INFO Loading Prospectors completed. Number of prospectors: 20
2016/08/24 22:49:44.069055 prospector.go:94: INFO Starting prospector of type: log
2016/08/24 22:49:44.069372 prospector.go:94: INFO Starting prospector of type: log
2016/08/24 22:49:44.069498 crawler.go:62: INFO All prospectors are initialised and running with 0 states to persist
2016/08/24 22:49:44.069652 prospector.go:94: INFO Starting prospector of type: log
2016/08/24 22:49:44.069945 log.go:45: INFO Harvester started for file: /var/log/xxxxx.log  # redacted
2016/08/24 22:49:44.070477 log.go:45: INFO Harvester started for file: /var/log/ram/gateways.log
2016/08/24 22:49:44.070618 log.go:45: INFO Harvester started for file: /var/log/ram/wireless.log
2016/08/24 22:49:44.070681 prospector.go:94: INFO Starting prospector of type: log
2016/08/24 22:49:44.070795 prospector.go:94: INFO Starting prospector of type: log
[snipped a bunch of extremely similar "Harvester started" lines so the post would come in under the 5000 character limit for this forum]
2016/08/24 22:49:44.082004 log.go:45: INFO Harvester started for file: /var/log/ram/relayd.log
2016/08/24 22:49:44.083343 prospector.go:94: INFO Starting prospector of type: log
2016/08/24 22:49:44.084494 log.go:45: INFO Harvester started for file: /var/log/ram/dhcpd.log
2016/08/24 22:50:14.059580 logp.go:221: INFO Non-zero metrics in the last 30s: libbeat.logstash.publish.read_bytes=5975 libbeat.publisher.published_events=4076 filebeat.harvester.started=20 filebeat.harvester.open_files=20 filebeat.harvester.running=20 libbeat.logstash.publish.write_bytes=173692 publish.events=4096 libbeat.logstash.published_and_acked_events=4076 libbeat.logstash.call_count.PublishEvents=4
2016/08/24 22:50:44.059405 logp.go:223: INFO No non-zero metrics in the last 30s
2016/08/24 22:51:14.081502 logp.go:223: INFO No non-zero metrics in the last 30s
2016/08/24 22:51:44.059395 logp.go:223: INFO No non-zero metrics in the last 30s
2016/08/24 22:52:14.059542 logp.go:223: INFO No non-zero metrics in the last 30s

You will notice that it was publishing events initially, and then for the next couple minutes...nothing. I watched the logs during that time. Several of them were quite busy with entries every second or two.

I would be happy to try just about anything at this point. I'm getting close to giving up and trying to interface with logstash directly via python.

5

I tried with today's latest build, but no change in behavior.

I did notice something interesting, though. I'm not actually getting all of the logs at startup. I'm only getting exactly 4076 of them. 20 less than 4096. That seems suspiciously like some kind of hit-a-limit problem.

6

I spotted the following lines:

It seems there is something strange happening with the registrar. Not sure if this could be a problem related to access rights to the registry file. Could you remove the registry file and start filebeat from scratch again to see if you get the same output?

When you refer to logs: Are you referring to 4096 log files or log lines? If log files, I'm thinking if there could be an issue with ulimit and the maximum of file handler that can be opened.

How often does pfsense rotate the log file? As you report the issue happens on startup, this "should" not have an impact I would think but it is good to know.

For debugging: The above is perfect. There is also and option logging.level: debug for the config file which could be used. For larger outputs feel free to also post a link to a gist.

7

I confirmed that the problem was the location of the registry file (/usr/local/libexec). Dunno what was so special about that location, but the process couldn't write there (even though permissions said it could). I changed the registry file location and now everything is working great.

Thank you so much!!!

8

This topic was automatically closed after 21 days. New replies are no longer allowed.