[Snort-devel] Bugreport - 60 second timeout before shutdown

Jason Wallace jason.r.wallace at ...2499...
Thu May 6 08:43:10 EDT 2010


I noticed this a while back. Just assumed it was normal behavior. I
added a pause to the init.d script when shutting down to work around
it.

Wally

On Thu, May 6, 2010 at 8:36 AM,  <elof at ...969...> wrote:
>
> No, this has nothing to do with syslogd. The snort process simply don't die
> as quickly as it used to.
>
> I've tracked the problem down to this:
> The more signatures you have, the longer it takes for snort to shutdown.
>
>
> ...so my first assumption that there were a 60 second timeout is false.
> However, in prior snort versions, the process always died immediately after
> I killed it. Now the process take seconds or even a minute to shut down.
>
> When restarting the snort service, it is a huge difference between having to
> wait 0.5 seconds or 60 seconds. So although this is not a bug, it is still a
> big inconvenience that I hope can be removed so that snort service restarts
> will be swift again.
>
>
> Example:
> I start snort v2.8.4.1 (Build 38) and then kill it. The process immediately
> disappear.
> I start snort v2.8.5.2 (Build 121) on the same machine, using virtually the
> same configuration as the snort above. After I kill this process, it takes
> 63 seconds before it is gone.
>
> The same test, using the same configuration, on a much faster machine give:
> 2.8.4.1 - immediately disappear
> 2.8.5.2 - disappear after 14 seconds
>
>
>
> Not only does it take a long time for the process to terminate, it
> apparently also use a lot of CPU when dying.
>
> Example of a snort process running:
> USER    PID %CPU %MEM  STAT STARTED      TIME COMMAND
> snort 13194  0.0 58.6  Ss   Tue12PM   0:34.46 snort -q -D -c snort.conf
> snort 13194  0.0 58.6  Ss   Tue12PM   0:34.46 snort -q -D -c snort.conf
> snort 13194  0.0 58.6  Ss   Tue12PM   0:34.46 snort -q -D -c snort.conf
> snort 13194  0.0 58.6  Ss   Tue12PM   0:34.46 snort -q -D -c snort.conf
> snort 13194  0.0 58.6  Ss   Tue12PM   0:34.48 snort -q -D -c snort.conf
>
> The sniffer NIC have very little traffic, so the snort process is sleeping
> and its CPU usage is 0.0.
>
> Now I kill pid 13194. (See how the CPU rises)
>
> snort 13194  0.0 58.8  DLs  Tue12PM   0:34.49 snort -q -D -c snort.conf
> snort 13194  0.1 59.8  DLs  Tue12PM   0:34.50 snort -q -D -c snort.conf
> snort 13194  0.2 62.2  Rs   Tue12PM   0:35.05 snort -q -D -c snort.conf
> snort 13194  3.0 64.8  DLs  Tue12PM   0:35.53 snort -q -D -c snort.conf
> snort 13194  7.0 67.1  DLs  Tue12PM   0:36.06 snort -q -D -c snort.conf
> snort 13194  8.9 67.7  Rs   Tue12PM   0:36.63 snort -q -D -c snort.conf
> snort 13194 11.4 69.1  Rs   Tue12PM   0:37.26 snort -q -D -c snort.conf
> snort 13194 13.1 69.0  DLs  Tue12PM   0:37.60 snort -q -D -c snort.conf
> snort 13194 13.2 69.0  RLs  Tue12PM   0:37.79 snort -q -D -c snort.conf
> snort 13194 13.4 70.1  DLs  Tue12PM   0:38.00 snort -q -D -c snort.conf
> snort 13194 13.3 70.0  Rs   Tue12PM   0:38.53 snort -q -D -c snort.conf
> snort 13194 16.8 70.5  Rs   Tue12PM   0:39.62 snort -q -D -c snort.conf
> snort 13194 20.8 70.5  Rs   Tue12PM   0:40.67 snort -q -D -c snort.conf
> snort 13194 24.5 70.8  Rs   Tue12PM   0:41.69 snort -q -D -c snort.conf
> snort 13194 28.1 70.9  Rs   Tue12PM   0:42.74 snort -q -D -c snort.conf
> snort 13194 31.4 71.2  Rs   Tue12PM   0:43.79 snort -q -D -c snort.conf
> snort 13194 34.6 72.0  DLs  Tue12PM   0:44.08 snort -q -D -c snort.conf
> snort 13194 32.4 72.2  DLs  Tue12PM   0:44.10 snort -q -D -c snort.conf
> snort 13194 31.7 72.1  DLs  Tue12PM   0:44.30 snort -q -D -c snort.conf
> snort 13194 30.8 72.8  DLs  Tue12PM   0:44.44 snort -q -D -c snort.conf
> snort 13194 29.8 73.1  DLs  Tue12PM   0:44.55 snort -q -D -c snort.conf
> snort 13194 28.8 73.1  DLs  Tue12PM   0:44.67 snort -q -D -c snort.conf
> snort 13194 27.7 73.2  DLs  Tue12PM   0:44.74 snort -q -D -c snort.conf
> snort 13194 26.8 73.5  DLs  Tue12PM   0:44.86 snort -q -D -c snort.conf
> snort 13194 25.9 74.2  DLs  Tue12PM   0:45.02 snort -q -D -c snort.conf
> snort 13194 24.6 74.7  DLs  Tue12PM   0:45.16 snort -q -D -c snort.conf
> snort 13194 24.0 75.0  DLs  Tue12PM   0:45.28 snort -q -D -c snort.conf
> snort 13194 23.0 74.8  DLs  Tue12PM   0:45.38 snort -q -D -c snort.conf
> snort 13194 22.5 75.2  DLs  Tue12PM   0:45.49 snort -q -D -c snort.conf
> snort 13194 21.6 75.0  DLs  Tue12PM   0:45.62 snort -q -D -c snort.conf
> snort 13194 21.0 75.3  Rs   Tue12PM   0:45.78 snort -q -D -c snort.conf
> snort 13194 20.6 75.2  DLs  Tue12PM   0:46.00 snort -q -D -c snort.conf
> snort 13194 20.5 75.5  DLs  Tue12PM   0:46.21 snort -q -D -c snort.conf
> snort 13194 20.2 75.5  DLs  Tue12PM   0:46.36 snort -q -D -c snort.conf
> snort 13194 19.8 75.8  DLs  Tue12PM   0:46.51 snort -q -D -c snort.conf
> snort 13194 19.4 75.6  DLs  Tue12PM   0:46.67 snort -q -D -c snort.conf
> snort 13194 19.3 75.5  DLs  Tue12PM   0:46.82 snort -q -D -c snort.conf
> snort 13194 19.0 75.7  DLs  Tue12PM   0:46.97 snort -q -D -c snort.conf
> snort 13194 18.8 75.6  DLs  Tue12PM   0:47.07 snort -q -D -c snort.conf
> snort 13194 18.3 75.7  DLs  Tue12PM   0:47.14 snort -q -D -c snort.conf
> snort 13194 18.3 75.8  DLs  Tue12PM   0:47.21 snort -q -D -c snort.conf
> snort 13194 17.7 76.0  DLs  Tue12PM   0:47.26 snort -q -D -c snort.conf
> snort 13194 17.2 75.7  DLs  Tue12PM   0:47.32 snort -q -D -c snort.conf
> snort 13194 17.2 75.8  DLs  Tue12PM   0:47.41 snort -q -D -c snort.conf
> snort 13194 16.9 75.7  DLs  Tue12PM   0:47.51 snort -q -D -c snort.conf
> snort 13194 16.7 75.7  DLs  Tue12PM   0:47.60 snort -q -D -c snort.conf
> snort 13194 16.3 75.8  DLs  Tue12PM   0:47.66 snort -q -D -c snort.conf
> snort 13194 16.3 75.8  DLs  Tue12PM   0:47.74 snort -q -D -c snort.conf
> snort 13194 16.1 75.8  DLs  Tue12PM   0:47.84 snort -q -D -c snort.conf
> snort 13194 16.2 75.8  DLs  Tue12PM   0:47.92 snort -q -D -c snort.conf
> snort 13194 16.2 75.7  DLs  Tue12PM   0:48.00 snort -q -D -c snort.conf
> snort 13194 15.9 75.8  DLs  Tue12PM   0:48.10 snort -q -D -c snort.conf
> snort 13194 15.7 75.8  DLs  Tue12PM   0:48.18 snort -q -D -c snort.conf
> snort 13194 15.6 75.8  Rs   Tue12PM   0:48.27 snort -q -D -c snort.conf
> snort 13194 15.6 75.7  DLs  Tue12PM   0:48.33 snort -q -D -c snort.conf
> snort 13194 15.2 75.7  DLs  Tue12PM   0:48.40 snort -q -D -c snort.conf
> snort 13194 14.9 75.9  DLs  Tue12PM   0:48.49 snort -q -D -c snort.conf
> snort 13194 14.9 75.7  DLs  Tue12PM   0:48.55 snort -q -D -c snort.conf
> snort 13194 14.8 75.9  DLs  Tue12PM   0:48.61 snort -q -D -c snort.conf
> snort 13194 14.4 75.7  DLs  Tue12PM   0:48.66 snort -q -D -c snort.conf
> snort 13194 14.4 75.6  DLs  Tue12PM   0:48.73 snort -q -D -c snort.conf
> snort 13194 14.4 75.7  DLs  Tue12PM   0:48.78 snort -q -D -c snort.conf
> snort 13194 14.1 75.8  DLs  Tue12PM   0:48.83 snort -q -D -c snort.conf
>
> After ~60 seconds, pid 13194 finally terminate and snort exits.
>
> S   Marks a process that is sleeping for less than about 20 seconds.
> s   The process is a session leader.
> D   Marks a process in disk (or other short term, uninterruptible) wait.
> L   Marks a process that is waiting to acquire a lock.
> R   Marks a runnable process.
>
>
>
> The waiting after the statistics have been printed. Example:
>
> ...blah blah...
> ...blah blah...
>        --== Initialization Complete ==--
>
>   ,,_     -*> Snort! <*-
>  o"  )~   Version 2.8.5.2 (Build 121)
>   ''''    By Martin Roesch & The Snort Team:
> http://www.snort.org/snort/snort-team
>           Copyright (C) 1998-2009 Sourcefire, Inc., et al.
>           Using PCRE version: 8.00 2009-10-19
>
>           Rules Engine: SF_SNORT_DETECTION_ENGINE  Version 1.11  <Build 17>
>           Preprocessor Object: SF_SSLPP  Version 1.1  <Build 3>
>           Preprocessor Object: SF_SSH  Version 1.1  <Build 2>
>           Preprocessor Object: SF_SMTP  Version 1.1  <Build 8>
>           Preprocessor Object: SF_FTPTELNET  Version 1.2  <Build 12>
>           Preprocessor Object: SF_DNS  Version 1.1  <Build 3>
>           Preprocessor Object: SF_DCERPC2  Version 1.0  <Build 2>
>           Preprocessor Object: SF_DCERPC  Version 1.1  <Build 5>
>           Preprocessor Object: SF_Dynamic_Example_Preprocessor  Version 1.0
>  <Build 1>
> Not Using PCAP_FRAMES
> ^C*** Caught Int-Signal
> Run time prior to being shutdown was 80.729902 seconds
> ===============================================================================
> Packet Wire Totals:
>   Received:          936
>   Analyzed:          923 (98.611%)
> ...blah blah...
> ...blah blah...
> ===============================================================================
> dcerpc2 Preprocessor Statistics
>  Total sessions: 0
> ===============================================================================
> ===============================================================================
> <<<<<<< here it hang for 60 seconds >>>>>>>
> Snort exiting
>
>
>
>
> If I have 12000 signatures, it hangs for 14 seconds before the process dies.
> If I add 1000 more signatures (13000 in total), it hangs for 34 seconds. Yet
> another 1000 signatures = 62 seconds and so on...
>
>
> /Elof
>
>
>
>
>
>
> On Wed, 5 May 2010, Leon Ward wrote:
>
>> This is likely a function of your syslogd (kindly trying to coalesce
>> events for you), not Snort itself.
>>
>> Check the status of the pid via ps after sending it the TERM.
>>
>> -Leon
>>
>> On 3 May 2010 13:03,  <elof at ...969...> wrote:
>>>
>>> I run snort v2.8.5.2 as a daemon (chrooted, with different uid/gid and
>>> with several output plugins activated, including database).
>>>
>>> When I run 'kill <pid>', I immediately get syslog messages indicating
>>> that
>>> snort is going down (closing db connection, dumping stats, etc).
>>>
>>> However, the process don't die until 60 seconds later. See the
>>> timestamps of the last two syslog rows:
>>>
>>>
>>> May  3 13:48:05 snortbox snort[97227]:            UDP Port Filter
>>> May  3 13:48:05 snortbox snort[97227]:                    Dropped: 0
>>> May  3 13:48:05 snortbox snort[97227]:                  Inspected: 0
>>> May  3 13:48:05 snortbox snort[97227]:                    Tracked: 0
>>> May  3 13:48:05 snortbox snort[97227]: ==============================
>>> May  3 13:48:05 snortbox snort[97227]: ==============================
>>> May  3 13:48:05 snortbox snort[97227]: dcerpc2 Preprocessor Statistics
>>> May  3 13:48:05 snortbox snort[97227]: ==============================
>>> May  3 13:48:05 snortbox snort[97227]: ==============================
>>> May  3 13:48:05 snortbox snort[97227]: Could not remove pid file
>>> /var/run//snort_eth0.pid: No such file or directory
>>> May  3 13:49:04 snortbox snort[97227]: Snort exiting
>>>
>>>
>>>
>>> ------------------------------------------------------------------------------
>>> _______________________________________________
>>> Snort-devel mailing list
>>> Snort-devel at lists.sourceforge.net
>>> https://lists.sourceforge.net/lists/listinfo/snort-devel
>>>
>
> ------------------------------------------------------------------------------
>
> _______________________________________________
> Snort-devel mailing list
> Snort-devel at lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/snort-devel
>
>




More information about the Snort-devel mailing list