Hello.
We're running a OSSEC 2.5.1 server with about 10 clients (also 2.5.1).
Lately we noticed that on the OSSEC server the ossec-analysisd is using one
full CPU core for hours on every ossec services restart. Since due to
different changes to the server the ossec services had to be stopped
temporarily, at first we thought it was catching up on the data the agents
started to send once the services were back up. However, today the services
were down less than 30 minutes (compared to 9 days a while ago), and now
analysisd keeps using one processor core at 100% for more than 2 hours
since it started.
I searched about anything similar but only found an issue like this which
was reported on ossec 2.3.1 and reportedly fixed (some bug about fts-queue
of 4 MB).
I straced the ossec-analysisd and it seems to
randomly-seeking-and-4K-block-reading the file
/var/ossec/queue/syscheck/syscheck which has 230 MB.
In internal_options.conf analysisd.debug is set to 1 but so far in the log
only the usual rules loading entries are present,
According to "When the unexpected happens" page in 2.6.0 documentation:
- the ossec version reported is:
OSSEC HIDS 2.5.1 - Trend Micro Inc.
- /etc/ossec-init.conf is:
DIRECTORY="/var/ossec"
VERSION="v2.5.1"
DATE="Fri Mar 11 11:34:51 EET 2011"
TYPE="server"
- /var/ossec/etc/ossec.conf is:
<!-- OSSEC Server config -->
<ossec_config>
<global>
<email_notification>yes</email_notification>
<email_to>[SNIP]</email_to>
<smtp_server>127.0.0.1</smtp_server>
<email_from>[SNIP]</email_from>
</global>
<rules>
<include>rules_config.xml</include>
<include>pam_rules.xml</include>
<include>sshd_rules.xml</include>
<include>telnetd_rules.xml</include>
<include>syslog_rules.xml</include>
<include>arpwatch_rules.xml</include>
<include>symantec-av_rules.xml</include>
<include>symantec-ws_rules.xml</include>
<include>pix_rules.xml</include>
<include>named_rules.xml</include>
<include>smbd_rules.xml</include>
<include>vsftpd_rules.xml</include>
<include>pure-ftpd_rules.xml</include>
<include>proftpd_rules.xml</include>
<include>ms_ftpd_rules.xml</include>
<include>ftpd_rules.xml</include>
<include>hordeimp_rules.xml</include>
<include>roundcube_rules.xml</include>
<include>wordpress_rules.xml</include>
<include>cimserver_rules.xml</include>
<include>vpopmail_rules.xml</include>
<include>vmpop3d_rules.xml</include>
<include>courier_rules.xml</include>
<include>web_rules.xml</include>
<include>apache_rules.xml</include>
<include>nginx_rules.xml</include>
<include>php_rules.xml</include>
<include>mysql_rules.xml</include>
<include>postgresql_rules.xml</include>
<include>ids_rules.xml</include>
<include>squid_rules.xml</include>
<include>firewall_rules.xml</include>
<include>cisco-ios_rules.xml</include>
<include>netscreenfw_rules.xml</include>
<include>sonicwall_rules.xml</include>
<include>postfix_rules.xml</include>
<include>sendmail_rules.xml</include>
<include>imapd_rules.xml</include>
<include>mailscanner_rules.xml</include>
<include>dovecot_rules.xml</include>
<include>ms-exchange_rules.xml</include>
<include>racoon_rules.xml</include>
<include>vpn_concentrator_rules.xml</include>
<include>spamd_rules.xml</include>
<include>msauth_rules.xml</include>
<include>mcafee_av_rules.xml</include>
<include>trend-osce_rules.xml</include>
<include>ms-se_rules.xml</include>
<!-- <include>policy_rules.xml</include> -->
<include>zeus_rules.xml</include>
<include>solaris_bsm_rules.xml</include>
<include>vmware_rules.xml</include>
<include>ms_dhcp_rules.xml</include>
<include>asterisk_rules.xml</include>
<include>ossec_rules.xml</include>
<include>attack_rules.xml</include>
<include>local_rules.xml</include>
</rules>
<syscheck>
<!-- Frequency that syscheck is executed -- default every 20 hours -->
<!-- override -- 24 hours -->
<frequency>86400</frequency>
<!-- change - auto_ignore yes to ignore logfiles that change often -->
<auto_ignore>yes</auto_ignore>
<!-- Directories to check (perform all possible verifications) -->
<directories realtime="yes" report_changes="yes"
check_all="yes">/etc</directories>
<directories realtime="yes"
check_all="yes">/usr/bin,/usr/sbin</directories>
<directories realtime="yes" check_all="yes">/bin,/sbin</directories>
<directories realtime="yes" check_all="yes">/lib,/usr/lib</directories>
<directories realtime="yes"
check_all="yes">/storage/backup_storage</directories>
<!-- Files/directories to ignore -->
<ignore>/etc/mtab</ignore>
<ignore>/etc/adjtime</ignore>
</syscheck>
<rootcheck>
<scanall>yes</scanall>
<frequency>43200</frequency>
<rootkit_files>/var/ossec/etc/shared/rootkit_files.txt</rootkit_files>
<rootkit_trojans>/var/ossec/etc/shared/rootkit_trojans.txt</rootkit_trojans>
</rootcheck>
<global>
<white_list>127.0.0.1</white_list>
<white_list>10.5.5.1</white_list>
<white_list>10.5.5.41</white_list>
<white_list>10.5.5.60</white_list>
</global>
<remote>
<connection>secure</connection>
<local_ip>10.5.11.247</local_ip>
<!-- local_ip>172.16.25.1</local_ip -->
</remote>
<alerts>
<log_alert_level>1</log_alert_level>
<email_alert_level>7</email_alert_level>
</alerts>
<command>
<name>host-deny</name>
<executable>host-deny.sh</executable>
<expect>srcip</expect>
<timeout_allowed>yes</timeout_allowed>
</command>
<command>
<name>firewall-drop</name>
<executable>firewall-drop.sh</executable>
<expect>srcip</expect>
<timeout_allowed>yes</timeout_allowed>
</command>
<command>
<name>disable-account</name>
<executable>disable-account.sh</executable>
<expect>user</expect>
<timeout_allowed>yes</timeout_allowed>
</command>
<!-- Active Response Config -->
<active-response>
<disabled>yes</disabled>
<!-- This response is going to execute the host-deny
- command for every event that fires a rule with
- level (severity) >= 6.
- The IP is going to be blocked for 600 seconds.
-->
<command>host-deny</command>
<location>local</location>
<level>6</level>
<timeout>600</timeout>
</active-response>
<active-response>
<disabled>yes</disabled>
<!-- Firewall Drop response. Block the IP for
- 600 seconds on the firewall (iptables,
- ipfilter, etc).
-->
<command>firewall-drop</command>
<location>local</location>
<level>6</level>
<timeout>600</timeout>
</active-response>
<!-- Files to monitor (localfiles) -->
<localfile>
<log_format>syslog</log_format>
<location>/var/log/everything/current</location>
</localfile>
<localfile>
<log_format>syslog</log_format>
<location>/var/log/mail/current</location>
</localfile>
<localfile>
<log_format>apache</log_format>
<location>/var/log/apache2/access_log</location>
</localfile>
<localfile>
<log_format>apache</log_format>
<location>/var/log/apache2/error_log</location>
</localfile>
<database_output>
<hostname>127.0.0.1</hostname>
<username>ossecuser</username>
<password>[SNIP]</password>
<database>ossec</database>
<type>mysql</type>
</database_output>
</ossec_config>
- /var/ossec/log/ossec.log (relevant stop-and-then-start-part):
2012/04/20 01:43:50 ossec-syscheckd: INFO: Starting syscheck scan.
2012/04/20 12:09:39 ossec-monitord(1225): INFO: SIGNAL Received. Exit
Cleaning...
2012/04/20 12:09:39 ossec-remoted(1225): INFO: SIGNAL Received. Exit
Cleaning...
2012/04/20 12:09:39 ossec-syscheckd(1225): INFO: SIGNAL Received. Exit
Cleaning...
2012/04/20 12:09:39 ossec-logcollector(1225): INFO: SIGNAL Received. Exit
Cleaning...
2012/04/20 12:09:39 ossec-analysisd(1225): INFO: SIGNAL Received. Exit
Cleaning...
2012/04/20 12:09:39 ossec-maild(1225): INFO: SIGNAL Received. Exit
Cleaning...
2012/04/20 12:09:39 ossec-dbd(1225): INFO: SIGNAL Received. Exit Cleaning...
2012/04/20 12:37:38 ossec-testrule: INFO: Reading local decoder file.
2012/04/20 12:37:38 ossec-execd(1350): INFO: Active response disabled.
Exiting.
2012/04/20 12:37:38 ossec-dbd: Connected to database 'ossec' at '127.0.0.1'.
2012/04/20 12:37:38 ossec-maild: INFO: Started (pid: 10069).
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading local decoder file.
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'rules_config.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'pam_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'sshd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'telnetd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'syslog_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'arpwatch_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'symantec-av_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'symantec-ws_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'pix_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'named_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'smbd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'vsftpd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'pure-ftpd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'proftpd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'ms_ftpd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'ftpd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'hordeimp_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'roundcube_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'wordpress_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'cimserver_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'vpopmail_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'vmpop3d_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'courier_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'web_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'apache_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'nginx_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'php_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'mysql_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'postgresql_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'ids_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'squid_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'firewall_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'cisco-ios_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'netscreenfw_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'sonicwall_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'postfix_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'sendmail_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'imapd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'mailscanner_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'dovecot_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'ms-exchange_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'racoon_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'vpn_concentrator_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'spamd_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'msauth_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'mcafee_av_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'trend-osce_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'ms-se_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'zeus_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'solaris_bsm_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'vmware_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'ms_dhcp_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'asterisk_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'ossec_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'attack_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Reading rules file:
'local_rules.xml'
2012/04/20 12:37:38 ossec-analysisd: INFO: Total rules enabled: '1118'
2012/04/20 12:37:38 ossec-analysisd: INFO: Ignoring file: '/etc/mtab'
2012/04/20 12:37:38 ossec-analysisd: INFO: Ignoring file: '/etc/adjtime'
2012/04/20 12:37:38 ossec-analysisd: INFO: Started (pid: 10077).
2012/04/20 12:37:38 ossec-remoted: INFO: Started (pid: 10086).
2012/04/20 12:37:38 ossec-remoted: INFO: Started (pid: 10087).
2012/04/20 12:37:38 ossec-rootcheck: System audit file not configured.
2012/04/20 12:37:38 ossec-remoted(4111): INFO: Maximum number of agents
allowed: '255'.
2012/04/20 12:37:38 ossec-remoted(1410): INFO: Reading authentication keys
file.
2012/04/20 12:37:38 ossec-monitord: INFO: Started (pid: 10096).
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for agent
[SNIP]: '1146:5776'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '878:7604'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '1204:3794'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '1085:940'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '3082:2962'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '796:5765'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '21537:9092'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '694:4859'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '112:9159'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '4019:5375'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '1349:7873'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '716:6514'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '37758:4614'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning counter for
agent [SNIP]: '31:4971'.
2012/04/20 12:37:38 ossec-remoted: INFO: Assigning sender counter: 68:7158
2012/04/20 12:37:40 ossec-dbd: INFO: Started (pid: 10064).
2012/04/20 12:37:42 ossec-syscheckd: INFO: Started (pid: 10090).
2012/04/20 12:37:42 ossec-rootcheck: INFO: Started (pid: 10090).
2012/04/20 12:37:42 ossec-syscheckd: INFO: Monitoring directory: '/etc'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Monitoring directory: '/usr/bin'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Monitoring directory:
'/usr/sbin'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Monitoring directory: '/bin'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Monitoring directory: '/sbin'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Monitoring directory: '/lib'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Monitoring directory: '/usr/lib'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Monitoring directory:
'/storage/backup_storage'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Directory set for real time
monitoring: '/etc'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Directory set for real time
monitoring: '/usr/bin'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Directory set for real time
monitoring: '/usr/sbin'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Directory set for real time
monitoring: '/bin'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Directory set for real time
monitoring: '/sbin'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Directory set for real time
monitoring: '/lib'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Directory set for real time
monitoring: '/usr/lib'.
2012/04/20 12:37:42 ossec-syscheckd: INFO: Directory set for real time
monitoring: '/storage/backup_storage'.
2012/04/20 12:37:44 ossec-logcollector(1950): INFO: Analyzing file:
'/var/log/everything/current'.
2012/04/20 12:37:44 ossec-logcollector(1950): INFO: Analyzing file:
'/var/log/mail/current'.
2012/04/20 12:37:44 ossec-logcollector(1950): INFO: Analyzing file:
'/var/log/apache2/access_log'.
2012/04/20 12:37:44 ossec-logcollector(1950): INFO: Analyzing file:
'/var/log/apache2/error_log'.
2012/04/20 12:37:44 ossec-logcollector: INFO: Started (pid: 10081).
2012/04/20 12:38:44 ossec-syscheckd: INFO: Starting syscheck scan
(forwarding database).
2012/04/20 12:38:44 ossec-syscheckd: INFO: Starting syscheck database
(pre-scan).
2012/04/20 12:38:44 ossec-syscheckd: INFO: Initializing real time file
monitoring (not started).
- kernel version
Linux [servername] 2.6.34-gentoo-r6-version1 #1 SMP Tue Sep 28 14:18:15
EEST 2010 i686 Intel(R) Core(TM) i3 CPU 530 @ 2.93GHz GenuineIntel GNU/Linux
The distro is Gentoo, and the machine is a i3-530 (1st gen, HT-disabled)
with 4 GB of RAM (3 GB is used for caching by the kernel).
Does anybody else noticed this kind of problem before? If so, any idea how
can we make analysisd stop using CPU for hours on each ossec services
restart?
Thank you for your time.
