Re: Unified2 logging bug in snort 2.9.4 (Build 40)

[elof () sentor se]

Hi Bhagya.

I have tried to get a pcap which can reproduce the error.
I sniffed millions of packets and waited for a missing packet in the 
unified2 file, then I terminated the tcpdump process.

When replaying the tcpdump file to snort (using the exact same config) it
does NOT show any issue.


However, I *think* I've found the cause of the bug. I don't know if it is 
FreeBSD or snort that is to blame though.


Here's the environment:
I'm running FreeBSD 9.1 amd64 on a machine with 8192 MB RAM.

CPU: Intel(R) Xeon(R) CPU E3-1230 V2 @ 3.30GHz (3300.10-MHz K8-class CPU)
FreeBSD/SMP: Multiprocessor System Detected: 8 CPUs
FreeBSD/SMP: 1 package(s) x 4 core(s) x 2 SMT threads

It has 4 em NICs and 4 igb NICs.

igb0: Bound queue 0 to cpu 0
igb0: Bound queue 1 to cpu 1
igb0: Bound queue 2 to cpu 2
igb0: Bound queue 3 to cpu 3
igb0: Bound queue 4 to cpu 4
igb0: Bound queue 5 to cpu 5
igb0: Bound queue 6 to cpu 6
igb0: Bound queue 7 to cpu 7
igb1: Bound queue 0 to cpu 0
igb1: Bound queue 1 to cpu 1
igb1: Bound queue 2 to cpu 2
igb1: Bound queue 3 to cpu 3
igb1: Bound queue 4 to cpu 4
igb1: Bound queue 5 to cpu 5
igb1: Bound queue 6 to cpu 6
igb1: Bound queue 7 to cpu 7
igb2: Bound queue 0 to cpu 0
igb2: Bound queue 1 to cpu 1
igb2: Bound queue 2 to cpu 2
igb2: Bound queue 3 to cpu 3
igb2: Bound queue 4 to cpu 4
igb2: Bound queue 5 to cpu 5
igb2: Bound queue 6 to cpu 6
igb2: Bound queue 7 to cpu 7
igb3: Bound queue 0 to cpu 0
igb3: Bound queue 1 to cpu 1
igb3: Bound queue 2 to cpu 2
igb3: Bound queue 3 to cpu 3
igb3: Bound queue 4 to cpu 4
igb3: Bound queue 5 to cpu 5
igb3: Bound queue 6 to cpu 6
igb3: Bound queue 7 to cpu 7

I've read that FreeBSD + many cores + many igb NICs exhaust the mbufs (or 
something), so I've increased the kern.ipc.nmbclusters=40000 a little bit.


Now, the *real* change I did was this:
When snort were missing packet data in the unified2 file, I had a huge 
bpf-buffer and identical daq buffer size:

/etc/sysctl.conf:
net.bpf.maxbufsize=1067630080

snort.conf:
config daq: pcap
config daq_var: buffer_size=1067630080



The only change I did a few hours ago was to reduce the bpf.maxbufsize and 
reboot the machine:

/etc/sysctl.conf:
net.bpf.maxbufsize=67630080

Snort daq still ask for 1067630080 but only get 67630080 bytes from the 
system.

During these hours, there has been no missing packet data in the unified2 
file according to barnyard2. There are normally a couple of warnings every 
hour.

Now that I run u2spewfoo on the unified2 file I see three events without 
any packet data (out of 330 events in total). In /var/log/ I *don't* see 
any complaint from barnyard2 even though there are missing packet data. 
Strange!


Well, my conclusion so far is that not using a huge bpf/daq buffer lowered 
the amount of missing packets in unified2.

I will let this run as this until monday.
On monday I will increase the kern.ipc.nmbclusters to see if the 
"missing-packets-in-unified2-problem" goes away.

/Elof


On Wed, 13 Mar 2013, Bhagya Bantwal wrote:

> Thank you for reporting this issue. We did recently fix an issue
> similar to this. If you send us your pcap and conf, we can confirm
> that it is the same issue.
>
> On Wed, Mar 13, 2013 at 9:25 AM,  <elof () sentor se> wrote:
> > Hi!
> >
> > I found a bug in my snort (Version 2.9.4 GRE (Build 40)) and wonder if you
> > need more data about it, or if it is already reported or being fixed.
> >
> > I don't want to waste lots of hours creating a bug report for something that
> > is already known... :-)
> >
> >
> >
> > Issue:
> > snort don't always log the event packet data to unified2, only the event
> > itself.
> >
> >
> > Example:
> > snort.conf:output unified2: filename snort.unified2
> > snort.conf:output alert_fast: snort.alert
> >
> > Snort logs all events to both snort.alert (ascii) and to unified2.
> >
> >
> > * I start snort (no logfiles exists prior to this)
> > * 9 events are triggered
> > * I terminate snort
> >
> > snort.alert show these 9 lines:
> > 1 03/12/13-18:29:02.090781  [**] [1:2008066:6]  <mon0> ET USER_AGENTS
> > Suspicious Blank User-Agent (descriptor but no string) [**] [Classification:
> > A Network Trojan was detected] [Priority: 1] {TCP} 10.100.3.139:57261 ->
> > 10.23.16.22:80
> > 2 03/12/13-18:30:05.160641  [**] [1:2008066:6]  <mon0> ET USER_AGENTS
> > Suspicious Blank User-Agent (descriptor but no string) [**] [Classification:
> > A Network Trojan was detected] [Priority: 1] {TCP} 212.188.183.73:56842 ->
> > 193.189.143.34:80
> > 3 03/12/13-18:30:05.160515  [**] [1:2008066:6]  <mon0> ET USER_AGENTS
> > Suspicious Blank User-Agent (descriptor but no string) [**] [Classification:
> > A Network Trojan was detected] [Priority: 1] {TCP} 10.100.3.139:57168 ->
> > 193.189.143.34:80
> > 4 03/12/13-18:31:05.167982  [**] [1:2008066:6]  <mon0> ET USER_AGENTS
> > Suspicious Blank User-Agent (descriptor but no string) [**] [Classification:
> > A Network Trojan was detected] [Priority: 1] {TCP} 212.188.183.73:56842 ->
> > 193.189.143.34:80
> > 5 03/12/13-18:31:05.167859  [**] [1:2008066:6]  <mon0> ET USER_AGENTS
> > Suspicious Blank User-Agent (descriptor but no string) [**] [Classification:
> > A Network Trojan was detected] [Priority: 1] {TCP} 10.100.3.139:57168 ->
> > 193.189.143.34:80
> > 6 03/12/13-18:32:05.176776  [**] [1:2008066:6]  <mon0> ET USER_AGENTS
> > Suspicious Blank User-Agent (descriptor but no string) [**] [Classification:
> > A Network Trojan was detected] [Priority: 1] {TCP} 212.188.183.73:56842 ->
> > 193.189.143.34:80
> > 7 03/12/13-18:32:05.176652  [**] [1:2008066:6]  <mon0> ET USER_AGENTS
> > Suspicious Blank User-Agent (descriptor but no string) [**] [Classification:
> > A Network Trojan was detected] [Priority: 1] {TCP} 10.100.3.139:57168 ->
> > 193.189.143.34:80
> > 8 03/12/13-18:35:05.226355  [**] [1:2008066:6]  <mon0> ET USER_AGENTS
> > Suspicious Blank User-Agent (descriptor but no string) [**] [Classification:
> > A Network Trojan was detected] [Priority: 1] {TCP} 212.188.183.73:60351 ->
> > 193.189.143.34:80
> > 9 03/12/13-18:35:05.226230  [**] [1:2008066:6]  <mon0> ET USER_AGENTS
> > Suspicious Blank User-Agent (descriptor but no string) [**] [Classification:
> > A Network Trojan was detected] [Priority: 1] {TCP} 10.100.3.139:57388 ->
> > 193.189.143.34:80
> >
> >
> > 'u2spewfoo snort.unified2.1363109305' show this in the unified2 file:
> > (Event)
> >         sensor id: 0    event id: 1     event second: 1363109342 event
> > microsecond: 90781
> >         sig id: 2008066 gen id: 1       revision: 6      classification: 21
> >         priority: 1     ip source: 10.100.3.139 ip destination: 10.23.16.22
> >         src port: 57261 dest port: 80   protocol: 6     impact_flag: 0
> > blocked: 0
> >
> > Packet
> >         sensor id: 0    event id: 1     event second: 1363109342
> >         packet second: 1363109342       packet microsecond: 90781
> >         linktype: 1     packet_length: 415
> > [    0] 00 00 5E 00 01 10 3C D9 2B 6A 5D 60 08 00 45 00  ..^...<.+j]`..E.
> > [   16] 01 91 18 7C 40 00 80 06 B8 CF 0A 64 03 8B 0A 17  ...|@......d....
> > [   32] 10 16 DF AD 00 50 91 5B 61 9C D4 A9 E5 7A 50 18  .....P.[a....zP.
> > [   48] 01 04 08 2D 00 00 47 45 54 20 2F 67 6F 2F 68 6F  ...-..GET /go/ho
> > [   64] 6D 65 20 48 54 54 50 2F 31 2E 31 0D 0A 48 6F 73  me HTTP/1.1..Hos
> > ...snip...
> >
> > (Event)
> >         sensor id: 0    event id: 2     event second: 1363109405 event
> > microsecond: 160641
> >         sig id: 2008066 gen id: 1       revision: 6      classification: 21
> >         priority: 1     ip source: 212.188.183.73       ip destination:
> > 193.189.143.34
> >         src port: 56842 dest port: 80   protocol: 6     impact_flag: 0
> > blocked: 0
> >
> > (Event)
> >         sensor id: 0    event id: 3     event second: 1363109405 event
> > microsecond: 160515
> >         sig id: 2008066 gen id: 1       revision: 6      classification: 21
> >         priority: 1     ip source: 10.100.3.139 ip destination:
> > 193.189.143.34
> >         src port: 57168 dest port: 80   protocol: 6     impact_flag: 0
> > blocked: 0
> >
> > (Event)
> >         sensor id: 0    event id: 4     event second: 1363109465 event
> > microsecond: 167982
> >         sig id: 2008066 gen id: 1       revision: 6      classification: 21
> >         priority: 1     ip source: 212.188.183.73       ip destination:
> > 193.189.143.34
> >         src port: 56842 dest port: 80   protocol: 6     impact_flag: 0
> > blocked: 0
> >
> > (Event)
> >         sensor id: 0    event id: 5     event second: 1363109465 event
> > microsecond: 167859
> >         sig id: 2008066 gen id: 1       revision: 6      classification: 21
> >         priority: 1     ip source: 10.100.3.139 ip destination:
> > 193.189.143.34
> >         src port: 57168 dest port: 80   protocol: 6     impact_flag: 0
> > blocked: 0
> >
> > (Event)
> >         sensor id: 0    event id: 6     event second: 1363109525 event
> > microsecond: 176776
> >         sig id: 2008066 gen id: 1       revision: 6      classification: 21
> >         priority: 1     ip source: 212.188.183.73       ip destination:
> > 193.189.143.34
> >         src port: 56842 dest port: 80   protocol: 6     impact_flag: 0
> > blocked: 0
> >
> > (Event)
> >         sensor id: 0    event id: 7     event second: 1363109525 event
> > microsecond: 176652
> >         sig id: 2008066 gen id: 1       revision: 6      classification: 21
> >         priority: 1     ip source: 10.100.3.139 ip destination:
> > 193.189.143.34
> >         src port: 57168 dest port: 80   protocol: 6     impact_flag: 0
> > blocked: 0
> >
> > (Event)
> >         sensor id: 0    event id: 8     event second: 1363109705 event
> > microsecond: 226355
> >         sig id: 2008066 gen id: 1       revision: 6      classification: 21
> >         priority: 1     ip source: 212.188.183.73       ip destination:
> > 193.189.143.34
> >         src port: 60351 dest port: 80   protocol: 6     impact_flag: 0
> > blocked: 0
> >
> > Packet
> >         sensor id: 0    event id: 8     event second: 1363109705
> >         packet second: 1363109705       packet microsecond: 226355
> >         linktype: 1     packet_length: 1066
> > [    0] 00 00 0C 07 AC 01 90 E2 BA 1A 4B 98 08 00 45 00  ..........K...E.
> > [   16] 04 1C 26 5B 40 00 7F 06 F4 9A D4 BC B7 49 C1 BD  ..&[@........I..
> > [   32] 8F 22 EB BF 00 50 36 9D 09 53 4E FC 08 31 50 18  ."...P6..SN..1P.
> > [   48] 01 00 57 3E 00 00 50 4F 53 54 20 2F 61 70 69 2F  ..W>..POST /api/
> > ...snip...
> >
> > (Event)
> >         sensor id: 0    event id: 9     event second: 1363109705 event
> > microsecond: 226230
> >         sig id: 2008066 gen id: 1       revision: 6      classification: 21
> >         priority: 1     ip source: 10.100.3.139 ip destination:
> > 193.189.143.34
> >         src port: 57388 dest port: 80   protocol: 6     impact_flag: 0
> > blocked: 0
> >
> > Packet
> >         sensor id: 0    event id: 9     event second: 1363109705
> >         packet second: 1363109705       packet microsecond: 226230
> >         linktype: 1     packet_length: 1066
> > [    0] 00 00 5E 00 01 10 3C D9 2B 6A 5D 60 08 00 45 00  ..^...<.+j]`..E.
> > [   16] 04 1C 26 5B 40 00 80 06 71 B2 0A 64 03 8B C1 BD  ..&[@...q..d....
> > [   32] 8F 22 E0 2C 00 50 36 9D 09 53 4E FC 08 31 50 18  .".,.P6..SN..1P.
> > [   48] 01 00 E0 E8 00 00 50 4F 53 54 20 2F 61 70 69 2F  ......POST /api/
> > ...snip...
> >
> >
> >
> > Where did the packet data for events 2-7 go???
> > In event 1, 8 and 9 the packet data is logged correctly but events 2-7 have
> > no packet data logged even though it is the same signature that trigger.
> > Strange!
> >
> >
> >
> >
> > Having a snort that don't log security events properly is quite bad...
> > A 'MAJOR' bug imho.
> >
> >
> > Anyhow, this happen a few times every day, but not in such a manner that I
> > can easily tcpdump the traffic and create a test-pcap.
> >
> > /Elof
>
> ------------------------------------------------------------------------------
> Everyone hates slow websites. So do we.
> Make your web apps faster with AppDynamics
> Download AppDynamics Lite for free today:
> http://p.sf.net/sfu/appdyn_d2d_mar
> _______________________________________________
> Snort-devel mailing list
> Snort-devel () lists sourceforge net
> https://lists.sourceforge.net/lists/listinfo/snort-devel
> Archive:
> http://sourceforge.net/mailarchive/forum.php?forum_name=snort-devel
>
> Please visit http://blog.snort.org for the latest news about Snort!

------------------------------------------------------------------------------
Everyone hates slow websites. So do we.
Make your web apps faster with AppDynamics
Download AppDynamics Lite for free today:
http://p.sf.net/sfu/appdyn_d2d_mar
_______________________________________________
Snort-devel mailing list
Snort-devel () lists sourceforge net
https://lists.sourceforge.net/lists/listinfo/snort-devel
Archive:
http://sourceforge.net/mailarchive/forum.php?forum_name=snort-devel

Please visit http://blog.snort.org for the latest news about Snort!