[Oisf-users] Suricata pegs a detect thread and drops packets
Duarte Silva
duarte.silva at serializing.me
Tue Jul 8 15:20:32 UTC 2014
On Tuesday 08 July 2014 16:45:54 Victor Julien wrote:
> On 06/25/2014 06:14 PM, Ivan Ristić wrote:
> > It's possible that LibHTP is the performance bottleneck there. We have a
> >
> > couple of places where we track issues similar to the one you reported:
> > https://redmine.openinfosecfoundation.org/issues/822
> >
> > https://github.com/ironbee/libhtp/issues/56
> >
> > I'll look into it.
> >
> > Thanks for your reports!
>
> Ivan has updated the libhtp 0.5.x branch to address this issue. Can you
> test it?
>
> It's in this branch: https://github.com/ironbee/libhtp/tree/0.5.x
Hi Victor,
I tried the optimization and got a nice segmentation fault in Suricata. It
seems to happen in the first HTTP packet received.
Cheers,
Duarte Silva
>
> Cheers,
> Victor
>
> > On 23/06/2014 15:58, David Vasil wrote:
> >> Anything I should do to tune the list size downward? If so, what
> >> implications does that have for inspection? Thanks!
> >>
> >> -dave
> >>
> >> On Jun 23, 2014 10:56 AM, "Anoop Saldanha" <anoopsaldanha at gmail.com
> >>
> >> <mailto:anoopsaldanha at gmail.com>> wrote:
> >> Dave,
> >>
> >> That's a huge list and that's pretty much the issue without doubt.
> >>
> >> On Mon, Jun 23, 2014 at 8:21 PM, David Vasil <davidvasil at gmail.com
> >>
> >> <mailto:davidvasil at gmail.com>> wrote:
> >> > Sorry about that:
> >> >
> >> > (gdb) info threads
> >> >
> >> > Id Target Id Frame
> >> > 14 Thread 0x7fcdf5621700 (LWP 32689) "RxPFR1"
> >>
> >> 0x00007fcdf998589c in
> >>
> >> > __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
> >> >
> >> > 13 Thread 0x7fcdf4e20700 (LWP 32690) "RxPFR2"
> >>
> >> 0x00007fcdf9241a43 in poll
> >>
> >> > () from /lib/x86_64-linux-gnu/libc.so.6
> >> >
> >> > 12 Thread 0x7fcdd7fff700 (LWP 32691) "Detect1"
> >>
> >> 0x00007fcdf9982d84 in
> >>
> >> > pthread_cond_wait@@GLIBC_2.3.2 () from
> >>
> >> /lib/x86_64-linux-gnu/libpthread.so.0
> >>
> >> > 11 Thread 0x7fcdd77fe700 (LWP 32692) "Detect2"
> >>
> >> 0x00007fcdfa692cdf in
> >>
> >> > htp_list_array_get (l=0x7fcdd0c53190, idx=3446) at htp_list.c:98
> >> >
> >> > 10 Thread 0x7fcdd6ffd700 (LWP 32693) "Detect3"
> >>
> >> 0x00007fcdf9982d84 in
> >>
> >> > pthread_cond_wait@@GLIBC_2.3.2 () from
> >>
> >> /lib/x86_64-linux-gnu/libpthread.so.0
> >>
> >> > 9 Thread 0x7fcdcffff700 (LWP 32694) "Detect4"
> >>
> >> 0x00007fcdf9982d84 in
> >>
> >> > pthread_cond_wait@@GLIBC_2.3.2 () from
> >>
> >> /lib/x86_64-linux-gnu/libpthread.so.0
> >>
> >> > 8 Thread 0x7fcdd67fc700 (LWP 32695) "Detect5"
> >>
> >> 0x00007fcdf9982d84 in
> >>
> >> > pthread_cond_wait@@GLIBC_2.3.2 () from
> >>
> >> /lib/x86_64-linux-gnu/libpthread.so.0
> >>
> >> > 7 Thread 0x7fcdd5ffb700 (LWP 32696) "Detect6"
> >>
> >> 0x00007fcdf9982d84 in
> >>
> >> > pthread_cond_wait@@GLIBC_2.3.2 () from
> >>
> >> /lib/x86_64-linux-gnu/libpthread.so.0
> >>
> >> > 6 Thread 0x7fcdd57fa700 (LWP 32697) "Detect7"
> >>
> >> 0x00007fcdf9982d84 in
> >>
> >> > pthread_cond_wait@@GLIBC_2.3.2 () from
> >>
> >> /lib/x86_64-linux-gnu/libpthread.so.0
> >>
> >> > 5 Thread 0x7fcdd4ff9700 (LWP 32698) "Detect8"
> >>
> >> 0x00007fcdf9982d84 in
> >>
> >> > pthread_cond_wait@@GLIBC_2.3.2 () from
> >>
> >> /lib/x86_64-linux-gnu/libpthread.so.0
> >>
> >> > 4 Thread 0x7fcdcf7fe700 (LWP 32699) "FlowManagerThre"
> >> >
> >> > 0x00007fcdf99830fe in pthread_cond_timedwait@@GLIBC_2.3.2 () from
> >> > /lib/x86_64-linux-gnu/libpthread.so.0
> >> >
> >> > 3 Thread 0x7fcdceffd700 (LWP 32700) "SCPerfWakeupThr"
> >> >
> >> > 0x00007fcdf99830fe in pthread_cond_timedwait@@GLIBC_2.3.2 () from
> >> > /lib/x86_64-linux-gnu/libpthread.so.0
> >> >
> >> > 2 Thread 0x7fcdce7fc700 (LWP 32701) "SCPerfMgmtThrea"
> >> >
> >> > 0x00007fcdf99830fe in pthread_cond_timedwait@@GLIBC_2.3.2 () from
> >> > /lib/x86_64-linux-gnu/libpthread.so.0
> >> > * 1 Thread 0x7fcdfaab2840 (LWP 32668) "Suricata-Main"
> >>
> >> 0x00007fcdf921908d
> >>
> >> > in nanosleep () from /lib/x86_64-linux-gnu/libc.so.6
> >> > (gdb) t 11
> >> > [Switching to thread 11 (Thread 0x7fcdd77fe700 (LWP 32692))]
> >> > #0 0x00007fcdfa692cdf in htp_list_array_get (l=0x7fcdd0c53190,
> >>
> >> idx=3446) at
> >>
> >> > htp_list.c:98
> >> > 98 r = l->elements[i];
> >> > (gdb) print *l
> >> > $1 = {first = 0, last = 8512, max_size = 16384, current_size =
> >> > 8512,
> >> > elements = 0x7fcdd2658c50}
> >> >
> >> > Cooper,
> >> >
> >> > I'll try the dev branch as well.
> >> >
> >> > Thanks,
> >> > -dave
> >> >
> >> >
> >> > On Mon, Jun 23, 2014 at 9:32 AM, Duarte Silva
> >>
> >> <duarte.silva at serializing.me <mailto:duarte.silva at serializing.me>>
> >>
> >> > wrote:
> >> >> On Monday 23 June 2014 09:08:45 David Vasil wrote:
> >> >> > Here is the result after removing all of the -O2's from the
> >> >> > libhtp
> >> >> > makefile
> >> >> > and waiting for a detect thread to hit 100%.
> >> >> >
> >> >> > http://pastebin.com/aHp415HV
> >> >>
> >> >> Hi Dave,
> >> >>
> >> >> the print doesn't say much other than the memory address of the
> >>
> >> variable
> >>
> >> >> :P
> >> >>
> >> >> Instead, could you do a:
> >> >>
> >> >> (gdb) print *l
> >> >>
> >> >> It should print all of the members of the htp_list_array_t
> >>
> >> structure. If
> >>
> >> >> not,
> >> >> do this:
> >> >>
> >> >> (gdb) print l->max_size
> >> >> (gdb) print l->current_size
> >> >>
> >> >> Cheers,
> >> >> Duarte
> >> >>
> >> >> > Also, setting transparent hugepages to always did not seem to
> >>
> >> prevent
> >>
> >> >> > this
> >> >> > from occurring.
> >> >> >
> >> >> > -dave
> >> >> >
> >> >> >
> >> >> > On Fri, Jun 20, 2014 at 10:36 PM, Anoop Saldanha
> >> >> > <anoopsaldanha at gmail.com <mailto:anoopsaldanha at gmail.com>>
> >> >> >
> >> >> > wrote:
> >> >> > > Dave,
> >> >> > >
> >> >> > > Nice! You did manage to catch that thread inside the get()
> >>
> >> function.
> >>
> >> >> > > From the perf-top it indicates that it's the same issue,
> >>
> >> although it
> >>
> >> >> > > would be nice if I could look at the contents of the variable
> >> >> > > "l"
> >> >> > > inside that get() function. Unfortunately from your gdb
> >>
> >> output it
> >>
> >> >> > > looks like you forgot to compile libhtp without(i typed it
> >>
> >> wrongly as
> >>
> >> >> > > "with" in my previous mail, instead of "without", although I
> >> >> > > did
> >> >> > > specify -g3 later on) optimization.
> >> >> > >
> >> >> > > Can you get the output of "print l" inside the get()
> >>
> >> function, but
> >>
> >> >> > > without optimization enabled in the libhtp library.
> >> >> > >
> >> >> > > You will have to rebuild libhtp without optimization. Go to
> >> >> > > your
> >> >> > > libhtp build directory. Run the "configure" command like you
> >>
> >> have
> >>
> >> >> > > before. Before you type "make", search for "Makefile" in the
> >>
> >> libhtp
> >>
> >> >> > > root/base directory and the "htp" subdirectory, and replace
> >>
> >> "-g -O2"
> >>
> >> >> > > with just "-g". Now run the make command. Confirm during
> >>
> >> the build
> >>
> >> >> > > stage on the console that you don't have "-g -o2" with any of
> >>
> >> the gcc
> >>
> >> >> > > commands and instead have just "-g".
> >> >> > >
> >> >> > > You can then do a "make install", OR manually copy the .so
> >> >> > > files
> >> >> > > directory from "htp/.libs/" directory, to replace the libhtp
> >>
> >> libraries
> >>
> >> >> > > that you are linking with suricata.
> >> >> > >
> >> >> > > If you still can't see the symbols inside libhtp's functions
> >>
> >> when you
> >>
> >> >> > > run suricata, your suricata binary is pointing to the
> >>
> >> wrong/old libhtp
> >>
> >> >> > > library.
> >> >> > >
> >> >> > >
> >> >> > > On Sat, Jun 21, 2014 at 12:42 AM, David Vasil
> >>
> >> <davidvasil at gmail.com <mailto:davidvasil at gmail.com>>
> >>
> >> >> > > wrote:
> >> >> > > > I was able to do this after Detect5 hit 100% and stayed
> >>
> >> there. I
> >>
> >> >> > > reverted
> >> >> > >
> >> >> > > > back to my originally compiled suricata 2.0.1 deb package
> >>
> >> (without
> >>
> >> >> > > > --enable-debug) as that flag created a ton of overhead - as
> >> >> > > > you
> >> >> > >
> >> >> > > mentioned,
> >> >> > >
> >> >> > > > probably due to not being compiled with optimization - and
> >>
> >> it also
> >>
> >> >> > > > ended
> >> >> > >
> >> >> > > up
> >> >> > >
> >> >> > > > core dumping several times. I copied the unstripped libhtp
> >>
> >> lib and
> >>
> >> >> > > suricata
> >> >> > >
> >> >> > > > binary (again, without --enable-debug) to the appropriate
> >> >> > > > destinations
> >> >> > >
> >> >> > > and
> >> >> > >
> >> >> > > > was able to see the debugging symbols as expected.
> >>
> >> Attached is a
> >>
> >> >> > > > 'perf
> >> >> > >
> >> >> > > top'
> >> >> > >
> >> >> > > > drilling into the annotated code within htp_list_array_get
> >>
> >> showing
> >>
> >> >> > > > where
> >> >> > >
> >> >> > > the
> >> >> > >
> >> >> > > > time is being spent (I assume). 9d99, not in the
> >>
> >> screenshot, shows
> >>
> >> >> > > > the
> >> >> > > >
> >> >> > > > following:
> >> >> > > > 0.08 : 9d99: repz retq
> >> >> > > >
> >> >> > > > : free(l->elements);
> >> >> > > > : free(l);
> >> >> > > > :
> >> >> > > > : }
> >> >> > > >
> >> >> > > > GDB from this is thread here: http://pastebin.com/3tfjTsL0
> >> >> > > >
> >> >> > > > Thanks!
> >> >> > > > -dave
> >> >> > > >
> >> >> > > >
> >> >> > > > On Fri, Jun 20, 2014 at 9:41 AM, Anoop Saldanha
> >> >> > > > <anoopsaldanha at gmail.com <mailto:anoopsaldanha at gmail.com>
> >> >> > > >
> >> >> > > > wrote:
> >> >> > > >> I don't think --enable-debug compiles it with optimization.
> >> >> > > >> Instead
> >> >> > > >> compile it without optimization, i.e. either -g -O0 or -g
> >> >> > > >> -03.
> >> >> > > >> Copy
> >> >> > > >> the new binaries over, like you previously did. You will
> >>
> >> also have
> >>
> >> >> > > >> to
> >> >> > > >> compile libhtp the same way. You can either specify this
> >>
> >> in the
> >>
> >> >> > > >> environment variable with configure or manually edit the
> >>
> >> configure
> >>
> >> >> > > >> script and the makefiles, replacing all "-g -o2" with just
> >>
> >> "-g".
> >>
> >> >> > > >> 1. You can start suricata, and wait for one of the detect
> >>
> >> threads
> >>
> >> >> > > >> to
> >> >> > > >> hit the 100% cpu utilization mark(make a note of the detect
> >> >> > > >> threadname).
> >> >> > > >> 2. One you see that, attach gdb to the running process,
> >>
> >> and print
> >>
> >> >> > > >> the
> >> >> > > >> threads using "info threads". If you see the offending
> >> >> > > >> thread
> >> >> > > >> stuck
> >> >> > > >> in the libhtp get() function call, switch over to that
> >>
> >> thread using
> >>
> >> >> > > >> "t
> >> >> > > >> <thread_number>" and do a "print l". The symbol "l" is
> >>
> >> inside the
> >>
> >> >> > > >> libhtp get() function call. Unless you have the detect
> >> >> > > >> thread
> >> >> > > >> inside
> >> >> > > >> the libhtp get() function scope that we are trying to
> >>
> >> trace, you
> >>
> >> >> > > >> won't
> >> >> > > >> have the symbol available for printing.
> >> >> > > >> 3. If when you do a "info threads", you don't see any of
> >> >> > > >> the
> >> >> > > >> threads
> >> >> > > >> currently inside htp get() function(gone out of scope at
> >> >> > > >> that
> >> >> > > >> instance
> >> >> > > >> of time t), continue the process in gdb, and keep a tab on
> >> >> > > >> the
> >> >> > > >> threads
> >> >> > > >> with top/htop, till you see the detect thread(s) again hit
> >>
> >> the 100%
> >>
> >> >> > > >> cpu mark, post which you can interrupt the process inside
> >>
> >> gdb again
> >>
> >> >> > > >> and hopefully find the detect thread still inside the
> >>
> >> libhtp get()
> >>
> >> >> > > >> function context.
> >> >> > > >>
> >> >> > > >> With the issue at hand, once the thread gets pegged, you
> >>
> >> should be
> >>
> >> >> > > >> able to zero-in on the thread pretty quickly. In case you
> >>
> >> can't,
> >>
> >> >> > > >> I'll
> >> >> > > >> provide a debug patch to corner the issue.
> >> >> > >
> >> >> > > --
> >> >> > > -------------------------------
> >> >> > > Anoop Saldanha
> >> >> > > http://www.poona.me
> >> >> > > -------------------------------
> >>
> >> --
> >> -------------------------------
> >> Anoop Saldanha
> >> http://www.poona.me
> >> -------------------------------
-------------- next part --------------
SCHTPGenerateNormalizedUri (tx=0x7fffe8794af0, uri=0x65, uri_include_all=0) at app-layer-htp-libhtp.c:147
147 if (uri->path != NULL) {
Missing separate debuginfos, use: debuginfo-install file-libs-5.04-15.el6.x86_64 glibc-2.12-1.132.el6_5.2.x86_64 libcap-ng-0.6.4-3.el6_0.1.x86_64 libpcap-1.4.0-1.20130826git2dbcaa1.el6.x86_64 nspr-4.10.2-1.el6_5.x86_64 nss-3.15.3-6.el6_5.x86_64 nss-softokn-3.14.3-10.el6_5.x86_64 nss-softokn-freebl-3.14.3-10.el6_5.x86_64 nss-util-3.15.3-1.el6_5.x86_64 sqlite-3.6.20-1.el6.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) bt full
#0 SCHTPGenerateNormalizedUri (tx=0x7fffe8794af0, uri=0x65, uri_include_all=0) at app-layer-htp-libhtp.c:147
len = 0
r = <value optimized out>
#1 0x0000000000423c4e in HTPCallbackRequestLine (tx=0x7fffe8794af0) at app-layer-htp.c:2033
tx_ud = <value optimized out>
request_uri_normalized = <value optimized out>
hstate = 0x7fffe8794760
cfg = <value optimized out>
#2 0x00007ffff757258a in htp_hook_run_all (hook=0x824640, user_data=0x7fffe8794af0) at htp_hooks.c:125
callback = <value optimized out>
rc = <value optimized out>
i = <value optimized out>
n = 1
#3 0x00007ffff7578cca in htp_tx_state_request_line (tx=0x7fffe8794af0) at htp_transaction.c:975
rc = <value optimized out>
#4 0x00007ffff7575892 in htp_connp_REQ_LINE (connp=0x7fffe87947b0) at htp_request.c:699
data = 0x7ffff2a07900 "GET /something/services"...
len = 285
#5 0x00007ffff75753c6 in htp_connp_req_data (connp=0x7fffe87947b0, timestamp=<value optimized out>, data=<value optimized out>,
len=<value optimized out>) at htp_request.c:853
rc = <value optimized out>
#6 0x0000000000422561 in HTPHandleRequestData (f=<value optimized out>, htp_state=0x7fffe8794760, pstate=0x7fffe8794730,
input=0x7ffff2a07900 "GET /something/services"..., input_len=<value optimized out>, local_data=<value optimized out>)
at app-layer-htp.c:720
r = -1
ret = 1
hstate = 0x7fffe8794760
__FUNCTION__ = "HTPHandleRequestData"
__PRETTY_FUNCTION__ = "HTPHandleRequestData"
ts = {tv_sec = 1404832454, tv_usec = 0}
#7 0x000000000042715a in AppLayerParserParse (alp_tctx=<value optimized out>, f=0x1746f10, alproto=1, flags=5 '\005', input=<value optimized out>,
input_len=<value optimized out>) at app-layer-parser.c:836
pstate = 0x7fffe8794730
p = 0x7e0150
alstate = 0x7fffe8794760
#8 0x000000000040f6b9 in AppLayerHandleTCPData (tv=0x610eb70, ra_ctx=0x7fffe8014010, p=0x13f9e40, f=0x1746f10, ssn=0x7fffe4794800,
stream=0x7fffe4794850,
data=0x7ffff2a07900 "GET /something/services"..., data_len=488, flags=5 '\005') at app-layer.c:288
app_tctx = <value optimized out>
alproto = 0x1746f84
alproto_otherdir = 0x1746f86
dir = 0 '\000'
data_al_so_far = 0
r = 0
first_data_dir = <value optimized out>
__PRETTY_FUNCTION__ = "AppLayerHandleTCPData"
#9 0x00000000005188ee in StreamTcpReassembleAppLayer (tv=0x610eb70, ra_ctx=0x7fffe8014010, ssn=0x7fffe4794800, stream=0x7fffe4794850, p=0x13f9e40)
at stream-tcp-reassemble.c:3185
flags = <value optimized out>
seg_tail = <value optimized out>
ra_base_seq = 3566577575
data = "GET /something/services"...
data_len = <value optimized out>
payload_offset = <value optimized out>
payload_len = <value optimized out>
next_seq = <value optimized out>
seg = 0x0
__PRETTY_FUNCTION__ = "StreamTcpReassembleAppLayer"
#10 0x0000000000519000 in StreamTcpReassembleHandleSegmentUpdateACK (tv=0x610eb70, ra_ctx=0x7fffe8014010, ssn=0x7fffe4794800, stream=0x7fffe4794850,
p=0x13f9e40) at stream-tcp-reassemble.c:3497
r = 0
#11 0x000000000051966a in StreamTcpReassembleHandleSegment (tv=0x610eb70, ra_ctx=0x7fffe8014010, ssn=0x7fffe4794800, stream=0x7fffe4794808, p=0x13f9e40,
pq=<value optimized out>) at stream-tcp-reassemble.c:3525
opposing_stream = <value optimized out>
#12 0x000000000050ef3c in HandleEstablishedPacketToClient (tv=0x610eb70, p=0x13f9e40, stt=0x7fffe8013920, ssn=0x7fffe4794800, pq=<value optimized out>)
at stream-tcp.c:2091
zerowindowprobe = <value optimized out>
#13 StreamTcpPacketStateEstablished (tv=0x610eb70, p=0x13f9e40, stt=0x7fffe8013920, ssn=0x7fffe4794800, pq=<value optimized out>) at stream-tcp.c:2337
No locals.
#14 0x0000000000512a4f in StreamTcpPacket (tv=0x610eb70, p=0x13f9e40, stt=0x7fffe8013920, pq=0x5274670) at stream-tcp.c:4265
ssn = 0x7fffe4794800
#15 0x0000000000513c9c in StreamTcp (tv=0x610eb70, p=0x13f9e40, data=0x7fffe8013920, pq=0x5274670, postpq=<value optimized out>) at stream-tcp.c:4507
stt = 0x7fffe8013920
ret = TM_ECODE_OK
#16 0x0000000000528788 in TmThreadsSlotVarRun (tv=0x610eb70, p=0x13f9e40, slot=<value optimized out>) at tm-threads.c:559
SlotFunc = <value optimized out>
r = <value optimized out>
s = 0x5274630
extra_p = <value optimized out>
#17 0x0000000000502e6f in TmThreadsSlotProcessPkt (ptv=<value optimized out>) at tm-threads.h:142
r = TM_ECODE_OK
#18 AFPReadFromRing (ptv=<value optimized out>) at source-af-packet.c:871
p = 0x13f9e40
from = <value optimized out>
emergency_flush = 0 '\000'
read_pkts = 1
loop_start = -1
#19 0x00000000005034f1 in ReceiveAFPLoop (tv=0x610eb70, data=0x7fffe80008f0, slot=<value optimized out>) at source-af-packet.c:1217
packet_q_len = <value optimized out>
ptv = 0x7fffe80008f0
fds = {fd = 11, events = 1, revents = 1}
r = <value optimized out>
s = <value optimized out>
last_dump = 1404832454
current_time = {tv_sec = 1404832454, tv_usec = 112072}
__FUNCTION__ = "ReceiveAFPLoop"
#20 0x00000000005283f6 in TmThreadsSlotPktAcqLoop (td=0x610eb70) at tm-threads.c:703
tv = 0x610eb70
s = 0x5754c00
run = <value optimized out>
r = <value optimized out>
slot = <value optimized out>
__FUNCTION__ = "TmThreadsSlotPktAcqLoop"
#21 0x00007ffff584c9d1 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#22 0x00007ffff5395b5d in clone () from /lib64/libc.so.6
No symbol table info available.
More information about the Oisf-users
mailing list