Barnyard2 100% CPU
-
When I run this SQL, it takes less than two seconds to return data:
SELECT sig_id, sig_sid, sig_gid,sig_rev, sig_class_id, sig_priority, sig_name FROM signature
The row count for my signature table is 461,236. I'm a DBA during my day job, so I'm not convinced that this is the problem….unless it was having trouble pulling unique rows from the signature table and having to do index scans, but I'd expect to see this in the trace.
I can probably test this, what populates the signature table? Are the number of rows determined by the rulesets?
-
I don't know the Barnyard2 code very well, but I do recall that it seemed to get tripped up if the order of references for a given SID changes. For example, in a rules update it may be that a new reference was added for a given SID. If the reference was added to the end of the old list, then things are OK. But if the new reference was inserted into the old list and thus the original order of references in the rule changed, that seems to trip up Barnyard2 when it is calculating a primary key for the SID Reference table. At least that's what I remember off the top of my head without going back and diving into the code again.
The scenario above would kick off the "duplicate primary key" error and cause a Barnyard2 shutdown. Something in the same bug could be at the root of the 100% CPU utilization churning as well.
Bill
-
Tonight I'm going to kick off a more thorough trace to see if it's having problems retrieving the rows you're talking about. I'll keep everybody informed.
-
Today I let Barnyard run for a solid 6 hours, and it churned at 100% the entire time. I ran a MySQL trace for the entire duration, and this is all that came through. The longest duration query was just under 4 seconds.
/usr/local/libexec/mysqld, Version: 5.1.73-log (FreeBSD port: mysql51-server-5.1.73_2). started with:
Tcp port: 0 Unix socket: (null)
Time Id Command ArgumentUser@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000055 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373088;
set autocommit=0;Time: 151217 11:26:18
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000032 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373178;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.001034 Lock_time: 0.000955 Rows_sent: 1 Rows_examined: 1
SET timestamp=1450373178;
SELECT vseq FROMschema;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000014 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1450373178;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000922 Lock_time: 0.000717 Rows_sent: 1 Rows_examined: 1
SET timestamp=1450373178;
SELECT sid FROM sensor WHERE hostname = 'router.Example.com:re0' AND interface = 're0' AND detail = 1 AND encoding = 0 AND filter IS NULL;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1450373178;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000144 Lock_time: 0.000052 Rows_sent: 1 Rows_examined: 1
SET timestamp=1450373178;
SELECT last_cid FROM sensor WHERE sid = 1;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000013 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1450373178;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.308946 Lock_time: 0.308691 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373178;
SELECT MAX(cid) FROM data WHERE sid='1';User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373178;
administrator command: Ping;
Time: 151217 11:26:19
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.813862 Lock_time: 0.813663 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373179;
SELECT MAX(cid) FROM event WHERE sid='1';User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373179;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.001157 Lock_time: 0.001100 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373179;
SELECT MAX(cid) FROM icmphdr WHERE sid='1';User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373179;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.398204 Lock_time: 0.398012 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373179;
SELECT MAX(cid) FROM iphdr WHERE sid='1';User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373179;
administrator command: Ping;
Time: 151217 11:26:20
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.242931 Lock_time: 0.242716 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373180;
SELECT MAX(cid) FROM opt WHERE sid='1';User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000010 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.363021 Lock_time: 0.362832 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373180;
SELECT MAX(cid) FROM tcphdr WHERE sid='1';User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.049907 Lock_time: 0.049723 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373180;
SELECT MAX(cid) FROM udphdr WHERE sid='1';User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000011 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000024 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373180;
BEGIN;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000010 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000170 Lock_time: 0.000036 Rows_sent: 0 Rows_examined: 1
SET timestamp=1450373180;
UPDATE sensor SET last_cid = 1310188 WHERE sid = 1;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000008 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 1
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000611 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373180;
COMMIT;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000008 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000098 Lock_time: 0.000022 Rows_sent: 1 Rows_examined: 1
SET timestamp=1450373180;
SELECT last_cid FROM sensor WHERE sid = 1;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000486 Lock_time: 0.000382 Rows_sent: 38 Rows_examined: 38
SET timestamp=1450373180;
SELECT sig_class_id, sig_class_name FROM sig_class ORDER BY sig_class_id ASC;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 38 Rows_examined: 38
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000008 Lock_time: 0.000000 Rows_sent: 38 Rows_examined: 38
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000016 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373180;
BEGIN;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373180;
administrator command: Ping;
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000013 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373180;
COMMIT;User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 0.000009 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1450373180;
administrator command: Ping;
Time: 151217 11:26:24
User@Host: sa[sa] @ localhost [127.0.0.1]
Query_time: 3.906478 Lock_time: 0.000023 Rows_sent: 466133 Rows_examined: 466133
SET timestamp=1450373184;
SELECT sig_id, sig_sid, sig_gid,sig_rev, sig_class_id, sig_priority, sig_name FROM signature; -
In case anyone is interested, Suricata is available with pfSense release 2.2.6. Barnyard2 doesn't have the 100% CPU problem when used with Suricata instead of Snort.
-
I still do have the error with suricata and the new version of Pfsense
-
Interesting…..so you're using Suricata and Barnyard and seeing 100% Barnyard usage?
You don't have both Surcata and Snort enabled do you?
-
Interesting…..so you're using Suricata and Barnyard and seeing 100% Barnyard usage?
You don't have both Surcata and Snort enabled do you?
Unfortunetly I have only Suricata and Barnyard2 on. nothing as snort in process.
I am going to try to restart during the week see if it's changing anything.
-
I know this is an old thread, but I was having some unrelated issues with Suricata and decided to switch to the latest version of Snort (3.2.9.6_1 on pfSense 2.4.3) and it appears to no longer have the 100% CPU issue.
-
I know this is an old thread, but I was having some unrelated issues with Suricata and decided to switch to the latest version of Snort (3.2.9.6_1 on pfSense 2.4.3) and it appears to no longer have the 100% CPU issue.
I bet it will come back (the 100% CPU utilization issue). It's a problem within the Barnyard2 code, and that code has not been updated on FreeBSD for several years.
Bill
-
We'll have to wait and see. I'll keep an eye on it.
-
It's been at least a week and I haven't seen the issue reoccur.
One thing to note is that I started with a fresh database. I didn't see any trouble SQL when looking at this originally, but I'm wondering if there was "bad" data in my DB which was causing Barnyard2 to chew through information that it couldn't necessarily handle.
I'll try to keep everyone posted as I build up more data from Snort….it's been a fun challenge. :D
-
It's been at least a week and I haven't seen the issue reoccur.
One thing to note is that I started with a fresh database. I didn't see any trouble SQL when looking at this originally, but I'm wondering if there was "bad" data in my DB which was causing Barnyard2 to chew through information that it couldn't necessarily handle.
I'll try to keep everyone posted as I build up more data from Snort….it's been a fun challenge. :D
What I determined in my research is that as data accumlates Barnyard2 starts to have issues with its SQL statements. Another thing that would pop up would be primary key violation errors if the order of REFERENCES in a rule changed or if a new REFERENCE was added. So both problems are related to how Barnyard2 interracts with MySQL.
Bill
-
I may have stumbled across a root cause.
I enabled the Snort VRT rules, and as soon as I did CPU usage shot up through the roof and stayed there. Disabling VRT and restarting Snort corrected it.
I can't remember if the VRT rules are available in Suricata. If they aren't, that may explain why I wasn't seeing the problem with Barnyard when using that instead of Snort.
What's different about VRT? Is there something with that ruleset that could cause this?
I'll keep an eye on things and let you guys know how things progress.
And as always, thanks bmeeks for your contributions :D
