Skip to content
This repository has been archived by the owner on Jan 18, 2024. It is now read-only.

FATAL ERROR: Duplicate entry on INSERT INTO event #120

Closed
Napsty opened this issue Oct 7, 2014 · 6 comments
Closed

FATAL ERROR: Duplicate entry on INSERT INTO event #120

Napsty opened this issue Oct 7, 2014 · 6 comments

Comments

@Napsty
Copy link

Napsty commented Oct 7, 2014

Hi,
I tried to use barnyard2 together with suricata 2.0.4 but everytime barnyard wants to write into the mysql database, it fails:

Oct  7 22:31:39 suricata barnyard2: FATAL ERROR: database mysql_error: Duplicate entry '1-5' for key 'PRIMARY'#012#011SQL=[INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 5, 315, '2014-10-07 22:20:26');]

This was with barnyard2 2.1.13 and with an empty database. I also tried it with barnyard 2.1.12 but with the a similar problem:

Oct  7 22:49:20 suricata barnyard2: FATAL ERROR: database mysql_error: Duplicate entry '1-2' for key 'PRIMARY'#012#011SQL=[INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 2, 313, '2014-10-07 22:20:25');]

My event table looks like this once barnyard2 stopped running (maybe this gives you a hint, but as I said, the database was empty except of the imported schema):

mysql> select * from event;
+-----+-----+-----------+---------------------+
| sid | cid | signature | timestamp           |
+-----+-----+-----------+---------------------+
|   1 |   1 |       313 | 2014-10-07 22:20:25 |
|   1 |   2 |       313 | 2014-10-07 22:20:25 |
|   1 |   3 |       313 | 2014-10-07 22:20:25 |
+-----+-----+-----------+---------------------+

Any help or idea how to fix that is greatly appreciated.

OS: Debian 7 Wheezy (MySQL 5.5 installed through apt)
Suricata IDS 2.0.4 installed from source
Barnyard2 2.1.13 (and 2.1.12) installed from https://github.com/firnsy/barnyard
@binf
Copy link
Collaborator

binf commented Oct 7, 2014

InnoDB or MyIASM?

Seem's like your ither using MyIASM or running two by2 instance with the
same sid and obviously it violate
the PK integrity check.

Make sure you do not run a process in console and one in background for
example.

Cheers,

On Tue, Oct 7, 2014 at 4:57 PM, Claudio Kuenzler notifications@github.com
wrote:

Hi,
I tried to use barnyard2 together with suricata 2.0.4 but everytime
barnyard wants to write into the mysql database, it fails:

Oct 7 22:31:39 suricata barnyard2: FATAL ERROR: database mysql_error: Duplicate entry '1-5' for key 'PRIMARY'#12#011SQL=[INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 5, 315, '2014-10-07 22:20:26');]

This was with barnyard2 2.1.13 and with an empty database. I also tried it
with barnyard 2.1.12 but with the a similar problem:

Oct 7 22:49:20 suricata barnyard2: FATAL ERROR: database mysql_error: Duplicate entry '1-2' for key 'PRIMARY'#12#011SQL=[INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 2, 313, '2014-10-07 22:20:25');]

My event table looks like this once barnyard2 stopped running (maybe this
gives you a hint, but as I said, the database was empty except of the
imported schema):

mysql> select * from event;
+-----+-----+-----------+---------------------+
| sid | cid | signature | timestamp |
+-----+-----+-----------+---------------------+
| 1 | 1 | 313 | 2014-10-07 22:20:25 |
| 1 | 2 | 313 | 2014-10-07 22:20:25 |
| 1 | 3 | 313 | 2014-10-07 22:20:25 |
+-----+-----+-----------+---------------------+

Any help or idea how to fix that is greatly appreciated.

OS: Debian 7 Wheezy (MySQL 5.5 installed through apt)
Suricata IDS 2.0.4 installed from source
Barnyard2 2.1.13 (and 2.1.12) installed from
https://github.com/firnsy/barnyard

—
Reply to this email directly or view it on GitHub
#120.

@Napsty
Copy link
Author

Napsty commented Oct 8, 2014

Hey binf,
I was already hoping that your hint about MyISAM would solve the problem, but the database and tables are already set to InnoDB:

mysql> SELECT `ENGINE` FROM `information_schema`.`TABLES`   WHERE `TABLE_SCHEMA`='db' AND `TABLE_NAME`='event';
+--------+
| ENGINE |
+--------+
| InnoDB |
+--------+
1 row in set (0.00 sec)

... where "db" is the db name by2 is supposed to write into.

If you mean two by2 processes with "two by2 instance with the same sid" then I'm certain, that only one process was started. I verified this while tailing the syslog and in another terminal verified the number of processes.

@Napsty
Copy link
Author

Napsty commented Oct 8, 2014

Here's additional information when I start barnyard (I emptied the database again). Hope this helps.

Oct  8 19:51:19 suricata barnyard2: #012#012+[ Signature Suppress list ]+#012----------------------------
Oct  8 19:51:19 suricata barnyard2: +[No entry in Signature Suppress List]+
Oct  8 19:51:19 suricata barnyard2: ----------------------------#012+[ Signature Suppress list ]+#012
Oct  8 19:51:23 suricata barnyard2: Barnyard2 spooler: Event cache size set to [2048]
Oct  8 19:51:23 suricata barnyard2: Log directory = /var/log
Oct  8 19:51:23 suricata barnyard2: INFO database: Defaulting Reconnect/Transaction Error limit to 10
Oct  8 19:51:23 suricata barnyard2: INFO database: Defaulting Reconnect sleep time to 5 second
Oct  8 19:51:23 suricata barnyard2: INFO database: Defaulting Reconnect/Transaction Error limit to 10
Oct  8 19:51:23 suricata barnyard2: INFO database: Defaulting Reconnect sleep time to 5 second
Oct  8 19:51:23 suricata barnyard2: Initializing daemon mode
Oct  8 19:51:23 suricata barnyard2: Daemon parent exiting
Oct  8 19:51:23 suricata barnyard2: Daemon initialized, signaled parent pid: 8635
Oct  8 19:51:23 suricata barnyard2: PID path stat checked out ok, PID path set to /var/run/
Oct  8 19:51:23 suricata barnyard2: Writing PID "8636" to file "/var/run//barnyard2_eth0.pid"
Oct  8 19:51:38 suricata barnyard2: Node unique name is: suricata:eth0#012
Oct  8 19:51:38 suricata barnyard2: [ClassificationPullDataStore()]: No Classification found in database ...
Oct  8 19:51:38 suricata barnyard2: [SignaturePullDataStore()]: No signature found in database ...
Oct  8 19:51:38 suricata barnyard2: [SystemPullDataStore()]: No System found in database ...
Oct  8 19:51:38 suricata barnyard2: [ReferencePullDataStore()]: No Reference found in database ...
Oct  8 19:52:56 suricata barnyard2: [SignatureReferencePullDataStore()]: No Reference found in database ...
Oct  8 19:52:56 suricata barnyard2: database: compiled support for (mysql)
Oct  8 19:52:56 suricata barnyard2: database: configured to use mysql
Oct  8 19:52:56 suricata barnyard2: database: schema version = 107
Oct  8 19:52:56 suricata barnyard2: database:           host = localhost
Oct  8 19:52:56 suricata barnyard2: database:           user = root
Oct  8 19:52:56 suricata barnyard2: database:  database name = db
Oct  8 19:52:56 suricata barnyard2: database:    sensor name = suricata:eth0
Oct  8 19:52:56 suricata barnyard2: database:      sensor id = 1
Oct  8 19:52:56 suricata barnyard2: database:     sensor cid = 1
Oct  8 19:52:56 suricata barnyard2: database:  data encoding = hex
Oct  8 19:52:56 suricata barnyard2: database:   detail level = full
Oct  8 19:52:56 suricata barnyard2: database:     ignore_bpf = no
Oct  8 19:52:56 suricata barnyard2: database: using the "log" facility
Oct  8 19:53:11 suricata barnyard2: Node unique name is: suricata:eth0#012
Oct  8 19:53:15 suricata barnyard2: [SignatureReferencePullDataStore()]: No Reference found in database ...
Oct  8 19:53:15 suricata barnyard2: database: compiled support for (mysql)
Oct  8 19:53:15 suricata barnyard2: database: configured to use mysql
Oct  8 19:53:15 suricata barnyard2: database: schema version = 107
Oct  8 19:53:15 suricata barnyard2: database:           host = localhost
Oct  8 19:53:15 suricata barnyard2: database:           user = root
Oct  8 19:53:15 suricata barnyard2: database:  database name = db
Oct  8 19:53:15 suricata barnyard2: database:    sensor name = suricata:eth0
Oct  8 19:53:15 suricata barnyard2: database:      sensor id = 1
Oct  8 19:53:15 suricata barnyard2: database:     sensor cid = 2
Oct  8 19:53:15 suricata barnyard2: database:  data encoding = hex
Oct  8 19:53:15 suricata barnyard2: database:   detail level = full
Oct  8 19:53:15 suricata barnyard2: database:     ignore_bpf = no
Oct  8 19:53:15 suricata barnyard2: database: using the "alert" facility
Oct  8 19:53:15 suricata barnyard2:
Oct  8 19:53:15 suricata barnyard2:         --== Initialization Complete ==--
Oct  8 19:53:15 suricata barnyard2: Barnyard2 initialization completed successfully (pid=8636)
Oct  8 19:53:15 suricata barnyard2: WARNING: Ignoring corrupt/truncated waldofile '/var/log/suricata/waldo.file'
Oct  8 19:53:15 suricata barnyard2: Opened spool file '/var/log/suricata/unified2.alert.1412790648'
Oct  8 19:53:15 suricata barnyard2: INFO [dbProcessSignatureInformation()]: [Event: 1] with [gid: 1] [sid: 2200074] [rev: 1] [classification: 0] [priority: 3] Signature Message -> "[SURICATA TCPv4 invalid checksum]"#012#011 was not found in barnyard2 signature cache, this could mean its is the first time the signature is processed, and will be inserted#012#011 in the database with the above information, this message should only be printed once for each signature that is not  present in the database#012#011 The new inserted signature will not have its information present in the sig_reference table,it should be present on restart#012#011 if the information is present in the sid-msg.map file. #012#011 You can allways update the message via a SQL query if you want it to be displayed correctly by your favorite interface#012
Oct  8 19:53:15 suricata barnyard2: FATAL ERROR: database mysql_error: Duplicate entry '1-2' for key 'PRIMARY'#012#011SQL=[INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 2, 315, '2014-10-08 19:50:48');]
Oct  8 19:53:15 suricata barnyard2: Barnyard2 exiting
Oct  8 19:53:15 suricata barnyard2: database: Closing connection to database "db"
Oct  8 19:53:15 suricata barnyard2: database: Closing connection to database "db"
Oct  8 19:53:15 suricata barnyard2: ===============================================================================
Oct  8 19:53:15 suricata barnyard2: Record Totals:
Oct  8 19:53:15 suricata barnyard2:    Records:           4
Oct  8 19:53:15 suricata barnyard2:    Events:           2 (50.000%)
Oct  8 19:53:15 suricata barnyard2:    Packets:           2 (50.000%)
Oct  8 19:53:15 suricata barnyard2:    Unknown:           0 (0.000%)
Oct  8 19:53:15 suricata barnyard2:    Suppressed:           0 (0.000%)
Oct  8 19:53:15 suricata barnyard2: ===============================================================================
Oct  8 19:53:15 suricata barnyard2: Packet breakdown by protocol (includes rebuilt packets):
Oct  8 19:53:15 suricata barnyard2:       ETH: 2          (100.000%)
Oct  8 19:53:15 suricata barnyard2:   ETHdisc: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:      VLAN: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:      IPV6: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:   IP6 EXT: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:   IP6opts: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:   IP6disc: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:       IP4: 2          (100.000%)
Oct  8 19:53:15 suricata barnyard2:   IP4disc: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:     TCP 6: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:     UDP 6: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:     ICMP6: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:   ICMP-IP: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:       TCP: 2          (100.000%)
Oct  8 19:53:15 suricata barnyard2:       UDP: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:      ICMP: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:   TCPdisc: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:   UDPdisc: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:   ICMPdis: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:      FRAG: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:    FRAG 6: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:       ARP: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:     EAPOL: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:   ETHLOOP: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:       IPX: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:     OTHER: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:   DISCARD: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2: InvChkSum: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:    S5 G 1: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:    S5 G 2: 0          (0.000%)
Oct  8 19:53:15 suricata barnyard2:     Total: 2
Oct  8 19:53:15 suricata barnyard2: ===============================================================================
Oct  8 19:53:15 suricata barnyard2: Closing spool file '/var/log/suricata/unified2.alert.1412790648'. Read 4 records

At the same time I was checking for the processes (only one is running... until the FATAL ERROR hits by2):

root@suricata:/var/log/suricata# date;  ps aux | grep barn
Wed Oct  8 19:53:05 CEST 2014
root      8636 25.1  8.9 135536 91000 ?        Rs   19:51   0:25 barnyard2 -c /etc/barnyard2.conf -d /var/log/suricata -f unified2.alert -v
root      8669  0.0  0.0   7832   876 pts/0    S+   19:53   0:00 grep barn
root@suricata:/var/log/suricata# date;  ps aux | grep barn
Wed Oct  8 19:53:07 CEST 2014
root      8636 26.5  9.3 139496 94960 ?        Rs   19:51   0:27 barnyard2 -c /etc/barnyard2.conf -d /var/log/suricata -f unified2.alert -v
root      8672  0.0  0.0   7832   876 pts/0    S+   19:53   0:00 grep barn
root@suricata:/var/log/suricata# date;  ps aux | grep barn
Wed Oct  8 19:53:08 CEST 2014
root      8636 27.4  9.6 142664 98128 ?        Rs   19:51   0:28 barnyard2 -c /etc/barnyard2.conf -d /var/log/suricata -f unified2.alert -v
root      8675  0.0  0.0   7832   876 pts/0    R+   19:53   0:00 grep barn
root@suricata:/var/log/suricata# date;  ps aux | grep barn
Wed Oct  8 19:53:12 CEST 2014
root      8636 29.8 10.5 151560 107296 ?       Rs   19:51   0:32 barnyard2 -c /etc/barnyard2.conf -d /var/log/suricata -f unified2.alert -v
root      8678  0.0  0.0   7832   876 pts/0    S+   19:53   0:00 grep barn
root@suricata:/var/log/suricata# date;  ps aux | grep barn
Wed Oct  8 19:53:14 CEST 2014
root      8636 30.9 10.5 151560 107296 ?       Rs   19:51   0:34 barnyard2 -c /etc/barnyard2.conf -d /var/log/suricata -f unified2.alert -v
root      8681  0.0  0.0   7832   880 pts/0    R+   19:53   0:00 grep barn
root@suricata:/var/log/suricata# date;  ps aux | grep barn
Wed Oct  8 19:53:15 CEST 2014
root      8684  0.0  0.0   7832   876 pts/0    S+   19:53   0:00 grep barn

@Napsty
Copy link
Author

Napsty commented Oct 8, 2014

OK, I think I found something very interesting while I was stracing barnyard. It occurred to me, that two mysql connections were established by by2. I enabled the general query log and this confirmed it to me. I attach the output below. You see connection number 47 from by2 does the job with querying existing signatures, etc... but then suddenly another Connect arrives (48) which basically does the same queries once again. Note that connection 47 is still connected...
Later at the end you see the new INSERT INTO where both connections try to do the inserts at the same time ... until connection 47 tries to insert the already existing "1, 11" values.
Shouldn't the first connection 47 be quit before making another connect to the database?

141008 20:39:39    47 Connect   root@localhost on db
                   47 Query     set autocommit=0
141008 20:39:54    47 Query     SELECT vseq FROM `schema`
                   47 Query     SELECT sid   FROM sensor  WHERE hostname = 'suricata:eth0'    AND interface  AND filter IS NULL
                   47 Query     SELECT last_cid   FROM sensor  WHERE sid = 1
                   47 Query     SELECT MAX(cid) FROM data WHERE sid='1'
                   47 Query     SELECT MAX(cid) FROM event WHERE sid='1'
                   47 Query     SELECT MAX(cid) FROM icmphdr WHERE sid='1'
                   47 Query     SELECT MAX(cid) FROM iphdr WHERE sid='1'
                   47 Query     SELECT MAX(cid) FROM opt WHERE sid='1'
                   47 Query     SELECT MAX(cid) FROM tcphdr WHERE sid='1'
                   47 Query     SELECT MAX(cid) FROM udphdr WHERE sid='1'
                   47 Query     BEGIN
                   47 Query     UPDATE sensor SET last_cid = 10 WHERE sid = 1
                   47 Query     COMMIT
                   47 Query     SELECT last_cid   FROM sensor  WHERE sid = 1
                   47 Query     SELECT sig_class_id, sig_class_name FROM sig_class ORDER BY sig_class_id ASC
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     SELECT sig_id, sig_sid, sig_gid,sig_rev, sig_class_id, sig_priority, sig_nam
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     SELECT ref_system_id, ref_system_name FROM reference_system
                   47 Query     SELECT ref_id, ref_system_id, ref_tag FROM reference
141008 20:39:58    47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     COMMIT
                   47 Query     SELECT ref_id, sig_id, ref_seq FROM sig_reference ORDER BY sig_id,ref_seq
                   48 Connect   root@localhost on db
                   48 Query     set autocommit=0
141008 20:40:13    48 Query     SELECT vseq FROM `schema`
                   48 Query     SELECT sid   FROM sensor  WHERE hostname = 'suricata:eth0'    AND interface  AND filter IS NULL
                   48 Query     SELECT last_cid   FROM sensor  WHERE sid = 1
                   48 Query     SELECT MAX(cid) FROM data WHERE sid='1'
                   48 Query     SELECT MAX(cid) FROM event WHERE sid='1'
                   48 Query     SELECT MAX(cid) FROM icmphdr WHERE sid='1'
                   48 Query     SELECT MAX(cid) FROM iphdr WHERE sid='1'
                   48 Query     SELECT MAX(cid) FROM opt WHERE sid='1'
                   48 Query     SELECT MAX(cid) FROM tcphdr WHERE sid='1'
                   48 Query     SELECT MAX(cid) FROM udphdr WHERE sid='1'
                   48 Query     BEGIN
                   48 Query     UPDATE sensor SET last_cid = 11 WHERE sid = 1
                   48 Query     COMMIT
                   48 Query     SELECT last_cid   FROM sensor  WHERE sid = 1
                   48 Query     SELECT sig_class_id, sig_class_name FROM sig_class ORDER BY sig_class_id ASC
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     SELECT sig_id, sig_sid, sig_gid,sig_rev, sig_class_id, sig_priority, sig_nam
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     SELECT ref_system_id, ref_system_name FROM reference_system
                   48 Query     SELECT ref_id, ref_system_id, ref_tag FROM reference
141008 20:40:17    48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     COMMIT
                   48 Query     SELECT ref_id, sig_id, ref_seq FROM sig_reference ORDER BY sig_id,ref_seq
                   48 Query     BEGIN
                   48 Query     INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 11, 315, '2014-10
                   48 Query     INSERT INTO tcphdr (sid, cid, tcp_sport, tcp_dport, tcp_seq, tcp_ack, tcp_of) VALUES (1,11,48879,80,0,0,5,0,0,0,37352,0)
                   48 Query     INSERT INTO iphdr (sid, cid, ip_src, ip_dst, ip_ver, ip_hlen, ip_tos, ip_lenum) VALUES (1,11,3232264325,3232264327,4,5,0,204,0,0,0,0,6,22479)
                   48 Query     INSERT INTO data (sid,cid,data_payload) VALUES (1,11,'474554202F63666964652F85454502F312E310D0A436F6E6E656374696F6E3A204B6565702D416C6976650D0A486F73743A203139322E3136382E3131322E3133 303020284E696B746F2F322E312E3629202845766173696F6E733A4E6F6E65292028546573743A303033303638290D0A0D0A')
                   48 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 10, 315, '2014-1
                   47 Query     INSERT INTO tcphdr (sid, cid, tcp_sport, tcp_dport, tcp_seq, tcp_ack, tcp_o ) VALUES (1,10,48879,80,0,0,5,0,0,0,37352,0)
                   47 Query     INSERT INTO iphdr (sid, cid, ip_src, ip_dst, ip_ver, ip_hlen, ip_tos, ip_le um) VALUES (1,10,3232264325,3232264327,4,5,0,204,0,0,0,0,6,22479)
                   47 Query     INSERT INTO data (sid,cid,data_payload) VALUES (1,10,'474554202F63666964652 85454502F312E310D0A436F6E6E656374696F6E3A204B6565702D416C6976650D0A486F73743A203139322E3136382E3131322E3133 303020284E696B746F2F322E312E3629202845766173696F6E733A4E6F6E65292028546573743A303033303638290D0A0D0A')
                   47 Query     COMMIT
                   48 Query     BEGIN
                   48 Query     INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 12, 315, '2014-1
                   48 Query     INSERT INTO tcphdr (sid, cid, tcp_sport, tcp_dport, tcp_seq, tcp_ack, tcp_o ) VALUES (1,12,48879,80,0,0,5,0,0,0,53576,0)
                   48 Query     INSERT INTO iphdr (sid, cid, ip_src, ip_dst, ip_ver, ip_hlen, ip_tos, ip_le um) VALUES (1,12,3232264325,3232264327,4,5,0,204,0,0,0,0,6,22479)
                   48 Query     INSERT INTO data (sid,cid,data_payload) VALUES (1,12,'474554202F43464944452 85454502F312E310D0A436F6E6E656374696F6E3A204B6565702D416C6976650D0A486F73743A203139322E3136382E3131322E3133 303020284E696B746F2F322E312E3629202845766173696F6E733A4E6F6E65292028546573743A303033303639290D0A0D0A')
                   48 Query     COMMIT
                   47 Query     BEGIN
                   47 Query     INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 11, 315, '2014-1
                   47 Query     ROLLBACK
                   47 Query     BEGIN
                   47 Query     UPDATE sensor SET last_cid = 10 WHERE sid = 1
                   47 Query     COMMIT
                   47 Quit
                   48 Query     BEGIN
                   48 Query     UPDATE sensor SET last_cid = 12 WHERE sid = 1
                   48 Query     COMMIT
                   48 Quit

@binf
Copy link
Collaborator

binf commented Oct 8, 2014

You have two process running at the same time.
Start by2 in console and you will not have the issue, then fix your startup
script.

Barnyard2 by it self only generate one connection unless you defined two
database output plugin which could also cause that especialy if both use
the same configuration (check that also)

Cheers.

On Wed, Oct 8, 2014 at 2:47 PM, Claudio Kuenzler notifications@github.com
wrote:

OK, I think I found something very interesting while I was stracing
barnyard. It occurred to me, that two mysql connections were established by
by2. I enabled the general query log and this confirmed it to me. I attach
the output below. You see connection number 47 from by2 does the job with
querying existing signatures, etc... but then suddenly another Connect
arrives (48) which basically does the same queries once again. Note that
connection 47 is still connected...
Later at the end you see the new INSERT INTO where both connections try to
do the inserts at the same time ... until connection 47 tries to insert the
already existing "1, 11" values.
Shouldn't the first connection 47 be quit before making another connect to
the database?

141008 20:39:39 47 Connect root@localhost on db
47 Query set autocommit=0
141008 20:39:54 47 Query SELECT vseq FROM schema
47 Query SELECT sid FROM sensor WHERE hostname = 'suricata:eth0' AND interface AND filter IS NULL
47 Query SELECT last_cid FROM sensor WHERE sid = 1
47 Query SELECT MAX(cid) FROM data WHERE sid='1'
47 Query SELECT MAX(cid) FROM event WHERE sid='1'
47 Query SELECT MAX(cid) FROM icmphdr WHERE sid='1'
47 Query SELECT MAX(cid) FROM iphdr WHERE sid='1'
47 Query SELECT MAX(cid) FROM opt WHERE sid='1'
47 Query SELECT MAX(cid) FROM tcphdr WHERE sid='1'
47 Query SELECT MAX(cid) FROM udphdr WHERE sid='1'
47 Query BEGIN
47 Query UPDATE sensor SET last_cid = 10 WHERE sid = 1
47 Query COMMIT
47 Query SELECT last_cid FROM sensor WHERE sid = 1
47 Query SELECT sig_class_id, sig_class_name FROM sig_class ORDER BY sig_class_id ASC
47 Query BEGIN
47 Query COMMIT
47 Query SELECT sig_id, sig_sid, sig_gid,sig_rev, sig_class_id, sig_priority, sig_nam
47 Query BEGIN
47 Query COMMIT
47 Query SELECT ref_system_id, ref_system_name FROM reference_system
47 Query SELECT ref_id, ref_system_id, ref_tag FROM reference
141008 20:39:58 47 Query BEGIN
47 Query COMMIT
47 Query BEGIN
47 Query COMMIT
47 Query BEGIN
47 Query COMMIT
47 Query BEGIN
47 Query COMMIT
47 Query BEGIN
47 Query COMMIT
47 Query BEGIN
47 Query COMMIT
47 Query BEGIN
47 Query COMMIT
47 Query BEGIN
47 Query COMMIT
47 Query BEGIN
47 Query COMMIT
47 Query BEGIN
47 Query COMMIT
47 Query SELECT ref_id, sig_id, ref_seq FROM sig_reference ORDER BY sig_id,ref_seq
48 Connect root@localhost on db
48 Query set autocommit=0
141008 20:40:13 48 Query SELECT vseq FROM schema
48 Query SELECT sid FROM sensor WHERE hostname = 'suricata:eth0' AND interface AND filter IS NULL
48 Query SELECT last_cid FROM sensor WHERE sid = 1
48 Query SELECT MAX(cid) FROM data WHERE sid='1'
48 Query SELECT MAX(cid) FROM event WHERE sid='1'
48 Query SELECT MAX(cid) FROM icmphdr WHERE sid='1'
48 Query SELECT MAX(cid) FROM iphdr WHERE sid='1'
48 Query SELECT MAX(cid) FROM opt WHERE sid='1'
48 Query SELECT MAX(cid) FROM tcphdr WHERE sid='1'
48 Query SELECT MAX(cid) FROM udphdr WHERE sid='1'
48 Query BEGIN
48 Query UPDATE sensor SET last_cid = 11 WHERE sid = 1
48 Query COMMIT
48 Query SELECT last_cid FROM sensor WHERE sid = 1
48 Query SELECT sig_class_id, sig_class_name FROM sig_class ORDER BY sig_class_id ASC
48 Query BEGIN
48 Query COMMIT
48 Query SELECT sig_id, sig_sid, sig_gid,sig_rev, sig_class_id, sig_priority, sig_nam
48 Query BEGIN
48 Query COMMIT
48 Query SELECT ref_system_id, ref_system_name FROM reference_system
48 Query SELECT ref_id, ref_system_id, ref_tag FROM reference
141008 20:40:17 48 Query BEGIN
48 Query COMMIT
48 Query BEGIN
48 Query COMMIT
48 Query BEGIN
48 Query COMMIT
48 Query BEGIN
48 Query COMMIT
48 Query BEGIN
48 Query COMMIT
48 Query BEGIN
48 Query COMMIT
48 Query BEGIN
48 Query COMMIT
48 Query BEGIN
48 Query COMMIT
48 Query BEGIN
48 Query COMMIT
48 Query BEGIN
48 Query COMMIT
48 Query SELECT ref_id, sig_id, ref_seq FROM sig_reference ORDER BY sig_id,ref_seq
48 Query BEGIN
48 Query INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 11, 315, '2014-10
48 Query INSERT INTO tcphdr (sid, cid, tcp_sport, tcp_dport, tcp_seq, tcp_ack, tcp_of) VALUES (1,11,48879,80,0,0,5,0,0,0,37352,0)
48 Query INSERT INTO iphdr (sid, cid, ip_src, ip_dst, ip_ver, ip_hlen, ip_tos, ip_lenum) VALUES (1,11,3232264325,3232264327,4,5,0,204,0,0,0,0,6,22479)
48 Query INSERT INTO data (sid,cid,data_payload) VALUES (1,11,'474554202F63666964652F85454502F312E310D0A436F6E6E656374696F6E3A204B6565702D416C6976650D0A486F73743A203139322E3136382E3131322E3133 303020284E696B746F2F322E312E3629202845766173696F6E733A4E6F6E65292028546573743A303033303638290D0A0D0A')
48 Query COMMIT
47 Query BEGIN
47 Query INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 10, 315, '2014-1
47 Query INSERT INTO tcphdr (sid, cid, tcp_sport, tcp_dport, tcp_seq, tcp_ack, tcp_o ) VALUES (1,10,48879,80,0,0,5,0,0,0,37352,0)
47 Query INSERT INTO iphdr (sid, cid, ip_src, ip_dst, ip_ver, ip_hlen, ip_tos, ip_le um) VALUES (1,10,3232264325,3232264327,4,5,0,204,0,0,0,0,6,22479)
47 Query INSERT INTO data (sid,cid,data_payload) VALUES (1,10,'474554202F63666964652 85454502F312E310D0A436F6E6E656374696F6E3A204B6565702D416C6976650D0A486F73743A203139322E3136382E3131322E3133 303020284E696B746F2F322E312E3629202845766173696F6E733A4E6F6E65292028546573743A303033303638290D0A0D0A')
47 Query COMMIT
48 Query BEGIN
48 Query INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 12, 315, '2014-1
48 Query INSERT INTO tcphdr (sid, cid, tcp_sport, tcp_dport, tcp_seq, tcp_ack, tcp_o ) VALUES (1,12,48879,80,0,0,5,0,0,0,53576,0)
48 Query INSERT INTO iphdr (sid, cid, ip_src, ip_dst, ip_ver, ip_hlen, ip_tos, ip_le um) VALUES (1,12,3232264325,3232264327,4,5,0,204,0,0,0,0,6,22479)
48 Query INSERT INTO data (sid,cid,data_payload) VALUES (1,12,'474554202F43464944452 85454502F312E310D0A436F6E6E656374696F6E3A204B6565702D416C6976650D0A486F73743A203139322E3136382E3131322E3133 303020284E696B746F2F322E312E3629202845766173696F6E733A4E6F6E65292028546573743A303033303639290D0A0D0A')
48 Query COMMIT
47 Query BEGIN
47 Query INSERT INTO event (sid,cid,signature,timestamp) VALUES (1, 11, 315, '2014-1
47 Query ROLLBACK
47 Query BEGIN
47 Query UPDATE sensor SET last_cid = 10 WHERE sid = 1
47 Query COMMIT
47 Quit
48 Query BEGIN
48 Query UPDATE sensor SET last_cid = 12 WHERE sid = 1
48 Query COMMIT
48 Quit

—
Reply to this email directly or view it on GitHub
#120 (comment).

@Napsty
Copy link
Author

Napsty commented Oct 9, 2014

Hey binf,

I started barnyard like this, so there is no second process (as documented above):

 barnyard2 -c /etc/barnyard2.conf -d /var/log/suricata -f unified2.alert -v

However your hint about the "two database output plugin" was just excellent! Indeed I have uncommented both mysql entries in /etc/barnyard2.conf:

# database: log to a variety of databases
# ----------------------------------------------------------------------------
#
# Purpose: This output module provides logging ability to a variety of databases
# See doc/README.database for additional information.
#
# Examples:
output database: log, mysql, user=root password=XXXX dbname=db host=localhost
output database: alert, mysql, user=root password=XXXX dbname=db host=localhost
#   output database: log, odbc, user=snort dbname=snort
#   output database: log, mssql, dbname=snort user=snort password=test
#   output database: log, oracle, dbname=snort user=snort password=test
#

So once I commented the "log" line again, barnyard ran through without error and keeps running :-)

Thanks a lot for your help and your time for responding!

@Napsty Napsty closed this as completed Oct 9, 2014
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@binf @Napsty