Re: Prelude-LML 100%CPU usage after ~3-5 minutes post startup

Hi again all, 

Thanks for the feedback!

Using a fairly basic installation of Karmic Ubuntu 9.10 as well as a very basic installation of prelude-lml I'm able to duplicate (triplicate) this high cpu load situation. Thanks to the earlier e-mails, I established that the error in prewikka was related to the redundancy of md5 function being called in prewikka and post-python2.5.
-> which updated the apache2/error.log
-> which then cycled into un-standardized errors in prelude-lml
A Red-herring for my cpu issue, but an issue in the prewikka package for Ubuntu nonetheless.

The CPU still spikes to 100% at any updates of any of the logfiles analyzed by prelude-lml. An "su -" whether successful or failed, updates /var/log/auth.log - the instant a logfile is updated, the loss of control of prelude-lm occurs.

In a freshly installed VM, the logfiles are very small and the prelude-lml has the apache configuration removed. Although I can see the advantages suggested of using sockets over files, not using sockets does not appear to be causing troubles for others - especially with effectively a default installation.

Starting prelude-lml with the metadata and dry-run flags also results in the same behavior.
prelude-lml --metadata=head,nowrite --dry-run

Below, I've included the suggestions/outputs from Yoann (I could not locate a specific prelude-lml debug package however, 
but did utilize libprelude2-dbg...). 

Any feedback or suggestions are appreciated. 

Kind Regards,
Tim Arneaud
The University of Melbourne, Carlton



Basic install of Ubuntu Karmic 9.10, 


root@ids:~# aptitude search prelude | grep "i "
i A libprelude2                     - Hybrid Intrusion Detection System [ Base l
i   libprelude2-dbg                 - Hybrid Intrusion Detection System [ Debug 
i A libpreludedb0                   - Security Information Management System [ B
i   prelude-lml                     - Hybrid Intrusion Detection System [ Log Mo
i   prelude-manager                 - Hybrid Intrusion Detection System [ Report


Prelude registered agents:
root@ids:~# prelude-admin list
Profile     Permission Issuer AnalyzerID
-------------------------------------
prelude-lml idmef:w 1421472224908806
prelude-manager idmef:w admin:r 1421472224908806

Prelude configuration (apache defaults hashed out):
root@ids:~# grep -v "#" /etc/prelude-lml/prelude-lml.conf 
include = /etc/prelude/default/idmef-client.conf
[prelude]
server-addr = 127.0.0.1
[format=syslog]
time-format = "%b %d %H:%M:%S" 
prefix-regex = "^(?P<timestamp>.{15}) (?P<hostname>\S+) (?:(?P<process>\S+?)(?:\[(?P<pid>[0-9]+)\])?: )?"
file = /var/log/messages
file = /var/log/auth.log
[Pcre]
ruleset=/etc/prelude-lml/ruleset/pcre.rules

Logfile size:
root@ids:~# ls -la /var/log/auth.log 
-rw-r----- 1 root adm 16373 2009-11-27 11:17 /var/log/auth.log
root@ids:~# ls -la /var/log/messages 
-rw-r----- 1 root adm 59418 2009-11-27 10:06 /var/log/messages

GDB Backtrace:
#0  0xb7703430 in __kernel_vsyscall ()
#1  0xb73bfc13 in __lxstat64 () from /lib/tls/i686/cmov/libc.so.6
#2  0x08053a37 in ev_stat_stat ()
#3  0x0805529b in ?? ()
#4  0x08055440 in ?? ()
#5  0x080554ec in ?? ()
#6  0x080566b5 in ev_loop ()
#7  0x0804d8b9 in _start ()


Strace output:
gettimeofday({1259280375, 91106}, NULL) = 0				<- these lines are repeated over slowly until logfiles are updated
select(16, [15], NULL, NULL, {0, 0})    = 0 (Timeout)
time(NULL)                              = 1259280375
clock_gettime(CLOCK_MONOTONIC, {65995, 204922137}) = 0
epoll_wait(3, {}, 64, 999)              = 0
clock_gettime(CLOCK_MONOTONIC, {65996, 205065514}) = 0
clock_gettime(CLOCK_REALTIME, {1259280376, 91516334}) = 0
time(NULL)                              = 1259280376
gettimeofday({1259280376, 91641}, NULL) = 0
select(16, [15], NULL, NULL, {0, 0})    = 0 (Timeout)
time(NULL)                              = 1259280376
clock_gettime(CLOCK_MONOTONIC, {65996, 205457364}) = 0		<- this is the point where I "su -" and the logfile audit.log is updated.
epoll_wait(3, {{EPOLLIN, {u32=7, u64=7}}}, 64, 999) = 1
clock_gettime(CLOCK_MONOTONIC, {65996, 434865307}) = 0
read(7, "\2\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 8192) = 32
lstat64("/var/log/auth.log", {st_mode=S_IFREG|0640, st_size=13689, ...}) = 0
inotify_rm_watch(7, 2)                  = 0
inotify_add_watch(7, "/var/log/auth.log", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 2
lstat64("/var/log/auth.log", {st_mode=S_IFREG|0640, st_size=13689, ...}) = 0
lstat64("/var/log/auth.log", {st_mode=S_IFREG|0640, st_size=13689, ...}) = 0
read(16, "Nov 27 11:06:16 ids su[11108]: p"..., 4096) = 129
gettimeofday({1259280376, 322099}, NULL) = 0
time(NULL)                              = 1259280376
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2183, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2183, ...}) = 0
gettimeofday({1259280376, 322583}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 8000}, ...}) = 0
time(NULL)                              = 1259280376
times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1724664346
write(8, "\2264\0\0\0\0\0\0\326\304E)", 12) = 12
_llseek(8, 0, [0], SEEK_SET)            = 0
gettimeofday({1259280376, 323124}, NULL) = 0
time(NULL)                              = 1259280376
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2183, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2183, ...}) = 0
gettimeofday({1259280376, 323580}, NULL) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 0}, ru_stime={0, 8000}, ...}) = 0
time(NULL)                              = 1259280376
times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 1724664346
write(8, "\3704\0\0\0\0\0\0_\22\361\202", 12) = 12
_llseek(8, 0, [0], SEEK_SET)            = 0
clock_gettime(CLOCK_MONOTONIC, {65996, 437616326}) = 0
epoll_wait(3, {{EPOLLIN, {u32=7, u64=7}}}, 64, 767) = 1
clock_gettime(CLOCK_MONOTONIC, {65996, 437751218}) = 0
read(7, "\2\0\0\0\0\200\0\0\0\0\0\0\0\0\0\0", 8192) = 16
inotify_add_watch(7, "/var/log/auth.log", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 2
lstat64("/var/log/auth.log", {st_mode=S_IFREG|0640, st_size=13689, ...}) = 0
inotify_rm_watch(7, 2)                  = 0
inotify_add_watch(7, "/var/log/auth.log", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 2
lstat64("/var/log/auth.log", {st_mode=S_IFREG|0640, st_size=13689, ...}) = 0
clock_gettime(CLOCK_MONOTONIC, {65996, 438324639}) = 0
epoll_wait(3, {{EPOLLIN, {u32=7, u64=7}}}, 64, 766) = 1
clock_gettime(CLOCK_MONOTONIC, {65996, 438456138}) = 0
read(7, "\2\0\0\0\0\200\0\0\0\0\0\0\0\0\0\0", 8192) = 16				<- at which point onwards the output is repeated endlessly and CPU hits 100%
inotify_add_watch(7, "/var/log/auth.log", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 2
lstat64("/var/log/auth.log", {st_mode=S_IFREG|0640, st_size=13689, ...}) = 0
inotify_add_watch(7, "/var/log/auth.log", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 2
lstat64("/var/log/auth.log", {st_mode=S_IFREG|0640, st_size=13689, ...}) = 0
inotify_add_watch(7, "/var/log/auth.log", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 2
lstat64("/var/log/auth.log", {st_mode=S_IFREG|0640, st_size=13689, ...}) = 0
inotify_add_watch(7, "/var/log/auth.log", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 2
lstat64("/var/log/auth.log", {st_mode=S_IFREG|0640, st_size=13689, ...}) = 0
inotify_add_watch(7, "/var/log/auth.log", IN_MODIFY|IN_ATTRIB|IN_DELETE_SELF|IN_MOVE_SELF|IN_DONT_FOLLOW|IN_MASK_ADD) = 2


_______________________________________________
Prelude-user site list
[email protected]
http://lists.prelude-ids.org/mailman/listinfo/prelude-user