firnsy/barnyard2 — Issue #9: Barnyard2-1.9 waldo file not updated
Author: aval13
Created: 2011-11-22 10:12:35+00:00
State: open

Hello.

I'm seing some weird behaviour on some barnyard2-1.9 installs on different servers. There are 2 cases:
1. servers with one LAN NIC only. Some barnyards keep updating the waldo file as they process the events and work flawlessly, other barnyards have a "stuck" waldo file which mentions a file they already moved to archive, although the process has a fd opened to the current snort log (which is correct). Restarting the barnyard process does not update the waldo file. Running with the -n switch also has no effect whatsoever.

2. servers with one LAN and one WAN NICs. The barnyard which processes the LAN snort log file works correctly (as the ones mentioned above). The barnyard on the WAN snort log either behaves like the "stuck waldo file" as above, or the waldo file mentions an archived file which no longer exists. Also, the barnyard process for the WAN has a fd opened for the current snort log file.

All the barnyards above which are "stuck" do NOT send any events. Using the -n switch does get mentioned at startup, but no events are being sent and the waldo file is not updated. I've tried the -v switch but nothing more detailed gets logged in syslog. Also, there is no log file whatsoever in the folder specified by -l switch.

All the barnyards are "Version 2.1.9 (Build 263)", source downloaded via "firnsy/barnyard2" -> Tags -> v2-1.9 (aka commit e48ae8a693e17822422bd38ba46026b682833ecf as far as i can tell).

All the barnyards use their own .conf (aka 2 barnyards on the system -> 2 conf files). They are minimaly configured, the only lines in the configs are:
config reference_file: /etc/snort/reference.config
config classification_file: /etc/snort/classification.config
config gen_file: /etc/snort/gen-msg.map
config sid_file: /etc/snort/sid-msg.map
config hostname: [SERVER_NAME]
config interface: [INTERFACE_NAME]
config daemon
input unified2
output database: log, mysql, user=[USERNAME] password=[PASSWORD] dbname=snort host=[SQLSRV_IP]

(Fields like [SERVER_NAME] are just masks in this text).

The running processes get the following switches:
/usr/bin/barnyard2 --pid-path /var/run --nolock-pidfile -D -c /etc/barnyard2/barnyard2.conf -d /var/log/snort -w /var/log/snort/barnyard2.waldo -f snort.log -l /var/log/barnyard2 -a /var/log/snort/archive

or

/usr/bin/barnyard2 --pid-path /var/run --nolock-pidfile -D -c /etc/barnyard2/barnyard2.conf -d /var/log/snort -n -w /var/log/snort/barnyard2.waldo -f snort.log -l /var/log/barnyard2 -a /var/log/snort/archive

Example on a one LAN NIC server:
# ps -ef | grep barnyard2 | grep -v grep
root 3917 1 0 11:29 ? 00:00:00 /usr/bin/barnyard2 --pid-path /var/run --nolock-pidfile -D -c /etc/barnyard2/barnyard2.conf -d /var/log/snort -n -w /var/log/snort/barnyard2.waldo -f snort.log -l /var/log/barnyard2 -a /var/log/snort/archive
# ls -lsa /var/log/snort/
total 1508
4 drwxr-xr-x 3 snort snort 4096 Nov 22 06:35 .
4 drwxr-xr-x 18 root root 4096 Nov 21 01:00 ..
4 drwxr-xr-x 2 snort snort 4096 Nov 22 11:29 archive
4 -rw------- 1 root root 2056 Nov 22 06:34 barnyard2.waldo
1492 -rw------- 1 snort snort 1522512 Nov 22 11:29 snort.log.1321936501
# ls -lsa /var/log/snort/archive/
total 5736
4 drwxr-xr-x 2 snort snort 4096 Nov 22 11:29 .
4 drwxr-xr-x 3 snort snort 4096 Nov 22 06:35 ..
5728 -rw------- 1 snort snort 5850756 Nov 22 06:34 snort.log.1321850111
# fuser /var/log/snort/*
/var/log/snort/barnyard2.waldo: 3917
/var/log/snort/snort.log.1321936501: 3917 10113
# fuser /var/log/snort/archive/*
# lsof -p 3917 | grep snort
barnyard2 3917 root 0r REG 254,1 2056 17697 /var/log/snort/barnyard2.waldo
barnyard2 3917 root 6r REG 254,1 1603336 16873 /var/log/snort/snort.log.1321936501
# ./odlaw.pl -r /var/log/snort/barnyard2.waldo
waldo: /var/log/snort/barnyard2.waldo
{
directory = /var/log/snort
filebase = snort.log
timestamp = 1321850111
record = 24674
}
# tail -n 200 /var/log/everything/current | grep barnyard2
2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Found pid path directive (/var/run)
2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Running in Continuous mode
2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]:
2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: --== Initializing Barnyard2 ==--
2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Initializing Input Plugins!
2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Initializing Output Plugins!
2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Parsing config file "/etc/barnyard2/barnyard2.conf"
2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3847]: Found pid path directive (/var/run)
2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3847]: Log directory = /var/log/barnyard2
2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3847]: Initializing daemon mode
2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3847]: Daemon parent exiting
2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3917]: Daemon initialized, signaled parent pid: 3847
2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3917]: PID path stat checked out ok, PID path set to /var/run
2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3917]: Writing PID "3917" to file "/var/run/barnyard2_[INTERFACE_NAME].pid"
2011-11-22T11:29:29.086823+02:00 [SERVER_NAME] monit[6181]: 'barnyard2' restart action done
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: compiled support for (mysql)
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: configured to use mysql
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: schema version = 107
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: host = [SERVER_IP]
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: user = [USERNAME]
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: database name = snort
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: sensor name = [SERVER_NAME]:[INTERFACE_NAME]
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: sensor id = 1
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: sensor cid = 3086063
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: data encoding = hex
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: detail level = full
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: ignore_bpf = no
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: using the "log" facility
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]:
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: --== Initialization Complete ==--
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: Barnyard2 initialization completed successfully (pid=3917)
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: Using waldo file '/var/log/snort/barnyard2.waldo':#012 spool directory = /var/log/snort#012 spool filebase = snort.log#012 time_stamp = 1321850111#012 record_idx = 24674
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: Processing new records only.
2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: Opened spool file '/var/log/snort/snort.log.1321936501'
2011-11-22T11:29:29.286874+02:00 [SERVER_NAME] barnyard2[3917]: Skipped 0 old records
2011-11-22T11:29:29.286874+02:00 [SERVER_NAME] barnyard2[3917]: Waiting for new data

On any further barnyard2 restarts, the waldo will remain unchanged, the same data reported in syslog, and no events sent. A tail -f on the snort.log.[TIMESTAMP] does show data being added.

The snort logging is simply set as:
# grep unified2 /etc/snort/snort.conf
output unified2: filename snort.log, limit 128

Any idea how can i force barnyard to log debug data in a log so i can figure out what it happening? Has anybody seen this behaviour before?

Thank you for your time.