{"issue":{"state":"closed","created_at":"2011-11-22T10:12:35Z","updated_at":"2011-12-09T23:06:45Z","comments":15,"user":{"gravatar_id":"1d8134cdb70b66b4a3a58701f2c87224","id":1212455,"url":"https://api.github.com/users/aval13","avatar_url":"https://secure.gravatar.com/avatar/1d8134cdb70b66b4a3a58701f2c87224?d=https://a248.e.akamai.net/assets.github.com%2Fimages%2Fgravatars%2Fgravatar-140.png","login":"aval13"},"body":"Hello.\r\n\r\nI'm seing some weird behaviour on some barnyard2-1.9 installs on different servers. There are 2 cases:\r\n1. 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.\r\n\r\n2. 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.\r\n\r\nAll 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.\r\n\r\nAll 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).\r\n\r\nAll 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:\r\nconfig reference_file:      /etc/snort/reference.config\r\nconfig classification_file: /etc/snort/classification.config\r\nconfig gen_file:            /etc/snort/gen-msg.map\r\nconfig sid_file:                /etc/snort/sid-msg.map\r\nconfig hostname:        [SERVER_NAME]\r\nconfig interface:       [INTERFACE_NAME]\r\nconfig daemon\r\ninput unified2\r\noutput database: log, mysql, user=[USERNAME] password=[PASSWORD] dbname=snort host=[SQLSRV_IP]\r\n\r\n(Fields like [SERVER_NAME] are just masks in this text).\r\n\r\nThe running processes get the following switches:\r\n/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\r\n\r\nor\r\n\r\n/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\r\n\r\nExample on a one LAN NIC server:\r\n# ps -ef | grep barnyard2 | grep -v grep\r\nroot      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\r\n# ls -lsa /var/log/snort/\r\ntotal 1508\r\n   4 drwxr-xr-x  3 snort snort    4096 Nov 22 06:35 .\r\n   4 drwxr-xr-x 18 root  root     4096 Nov 21 01:00 ..\r\n   4 drwxr-xr-x  2 snort snort    4096 Nov 22 11:29 archive\r\n   4 -rw-------  1 root  root     2056 Nov 22 06:34 barnyard2.waldo\r\n1492 -rw-------  1 snort snort 1522512 Nov 22 11:29 snort.log.1321936501\r\n# ls -lsa /var/log/snort/archive/\r\ntotal 5736\r\n   4 drwxr-xr-x 2 snort snort    4096 Nov 22 11:29 .\r\n   4 drwxr-xr-x 3 snort snort    4096 Nov 22 06:35 ..\r\n5728 -rw------- 1 snort snort 5850756 Nov 22 06:34 snort.log.1321850111\r\n# fuser /var/log/snort/*\r\n/var/log/snort/barnyard2.waldo:  3917\r\n/var/log/snort/snort.log.1321936501:  3917 10113\r\n# fuser /var/log/snort/archive/*\r\n# lsof -p 3917 | grep snort\r\nbarnyard2 3917 root    0r   REG      254,1     2056     17697 /var/log/snort/barnyard2.waldo\r\nbarnyard2 3917 root    6r   REG      254,1  1603336     16873 /var/log/snort/snort.log.1321936501\r\n# ./odlaw.pl -r /var/log/snort/barnyard2.waldo \r\nwaldo: /var/log/snort/barnyard2.waldo\r\n{\r\n directory = /var/log/snort\r\n filebase = snort.log\r\n timestamp = 1321850111\r\n record = 24674\r\n}\r\n# tail -n 200 /var/log/everything/current | grep barnyard2\r\n2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Found pid path directive (/var/run)\r\n2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Running in Continuous mode\r\n2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: \r\n2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]:         --== Initializing Barnyard2 ==--\r\n2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Initializing Input Plugins!\r\n2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Initializing Output Plugins!\r\n2011-11-22T11:29:21.144798+02:00 [SERVER_NAME] barnyard2[3847]: Parsing config file \"/etc/barnyard2/barnyard2.conf\"\r\n2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3847]: Found pid path directive (/var/run)\r\n2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3847]: Log directory = /var/log/barnyard2\r\n2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3847]: Initializing daemon mode\r\n2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3847]: Daemon parent exiting\r\n2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3917]: Daemon initialized, signaled parent pid: 3847\r\n2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3917]: PID path stat checked out ok, PID path set to /var/run\r\n2011-11-22T11:29:29.006802+02:00 [SERVER_NAME] barnyard2[3917]: Writing PID \"3917\" to file \"/var/run/barnyard2_[INTERFACE_NAME].pid\"\r\n2011-11-22T11:29:29.086823+02:00 [SERVER_NAME] monit[6181]: 'barnyard2' restart action done\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: compiled support for (mysql)\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: configured to use mysql\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: schema version = 107\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database:           host = [SERVER_IP]\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database:           user = [USERNAME]\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database:  database name = snort\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database:    sensor name = [SERVER_NAME]:[INTERFACE_NAME]\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database:      sensor id = 1\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database:     sensor cid = 3086063\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database:  data encoding = hex\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database:   detail level = full\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database:     ignore_bpf = no\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: database: using the \"log\" facility\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: \r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]:         --== Initialization Complete ==--\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: Barnyard2 initialization completed successfully (pid=3917)\r\n2011-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\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: Processing new records only.\r\n2011-11-22T11:29:29.276871+02:00 [SERVER_NAME] barnyard2[3917]: Opened spool file '/var/log/snort/snort.log.1321936501'\r\n2011-11-22T11:29:29.286874+02:00 [SERVER_NAME] barnyard2[3917]: Skipped 0 old records\r\n2011-11-22T11:29:29.286874+02:00 [SERVER_NAME] barnyard2[3917]: Waiting for new data\r\n\r\nOn 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.\r\n\r\nThe snort logging is simply set as:\r\n# grep unified2 /etc/snort/snort.conf\r\noutput unified2: filename snort.log, limit 128\r\n\r\nAny 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?\r\n\r\nThank you for your time.\r\n","assignee":{"gravatar_id":"6e0f62289da5000a529e49d968e23c1b","id":420034,"url":"https://api.github.com/users/firnsy","avatar_url":"https://secure.gravatar.com/avatar/6e0f62289da5000a529e49d968e23c1b?d=https://a248.e.akamai.net/assets.github.com%2Fimages%2Fgravatars%2Fgravatar-140.png","login":"firnsy"},"id":2316289,"labels":[],"pull_request":{"patch_url":null,"html_url":null,"diff_url":null},"number":9,"title":"Barnyard2-1.9 waldo file not updated","html_url":"https://github.com/firnsy/barnyard2/issues/9","closed_at":"2011-12-07T22:04:04Z","url":"https://api.github.com/repos/firnsy/barnyard2/issues/9","milestone":null},"action":"created","comment":{"created_at":"2011-12-09T23:06:45Z","updated_at":"2011-12-09T23:06:45Z","user":{"gravatar_id":"1d8134cdb70b66b4a3a58701f2c87224","id":1212455,"url":"https://api.github.com/users/aval13","avatar_url":"https://secure.gravatar.com/avatar/1d8134cdb70b66b4a3a58701f2c87224?d=https://a248.e.akamai.net/assets.github.com%2Fimages%2Fgravatars%2Fgravatar-140.png","login":"aval13"},"body":"I apologize if the \"fluff\" upset people. It will not happen again and i will stick to commenting only the technical part.\r\n\r\nWhich brings me to not agree with your fix again.\r\n\r\nJust adding a line setting record_start to zero does not resolve the issue, because when snort is still running (no logfile rotate) and logging events, on a b2 restart the same logfile will be opened (since it's the same as the one specified in the waldo), but since you set record_start to zero it will cause all the previously processed events to be reprocessed and resent as new events which will cause alot of duplicate key errors in mysql.\r\n\r\nAs I said in my previous posts and i repeat again, the record_start has any meaning only if the same logfile is being opened (no snort rotate), and this logic only applies when ProcessContinuous is first started. This is the reason in my original patch i saved the value of the timestamp ProcessContinuous received and only set record_start to zero if the opened spooler did not match the timestamp from the waldo.\r\n\r\nAs such, i believe that instead of just setting record_start to zero without any checks, the following code will fix any issue regarding to this ticket (the patch is against version 2-1.9 commit e48ae8a693 ):\r\n\r\n- in the beginning as in my original patch\r\n            uint32_t            initial_timestamp = 0;\r\n\r\n            /* save the initial timestamp in case the spooler we knew from the waldo went missing */\r\n            initial_timestamp = timestamp;\r\n\r\n- and on the part after the new spooler file is opened, using your first patch:\r\n\r\n            if (extension != initial_timestamp)\r\n            {\r\n               record_start = 0;\r\n               initial_timestamp = 0;\r\n            }\r\n            spooler->record_idx = 0;\r\n            spoolerWriteWaldo(&barnyard2_conf->waldo, spooler);\r\n\r\nThis way at first we save into initial_timestamp the timestamp that was loaded from the waldo, and then:\r\n- on the first loop, if the loaded waldo timestamp (stored in initial_timestamp) does not match the timestamp in extension (the timestamp of the snort log file that has been opened), then it means we have a new logfile, so we must not skip records, so record_start is set to zero. And set initial_timestamp to 0 to make sure no other match will be made.\r\n- on any later openings of a new logfile, initial_timestamp and extension will never match, so we auto reset record_start and initial_timestamp to zero (no harm will come from this).\r\n\r\nThank you for your time.\r\n","id":3087423,"url":"https://api.github.com/repos/firnsy/barnyard2/issues/comments/3087423"}}