Perl Issue After Yesterday's ELSA Updates

[Damon Rouse]

I noticed this last night after running the ELSA updates, I seem to have hundreds of perl process that are getting spawned. They are eating up RAM and clogging MySQL connections.

Whenever I try to run a query in ELSA, it get the following error:

cannot connect to dbi:mysql:database=syslog;port=3306: Too many connections at /opt/elsa/web/lib/SyncMysql.pm line 18.

drouse@essso:/$ pgrep -c perl
119

I've rebooted and things are fine for 20-30 minutes and then perl starts spawning processes again. I don't use Snorby, so I disabled it following the instructions on the Wiki...But that didn't help either.

Any ideas? Thanks!
Damon

[Doug Burks]

Is it cron.pl?

Have you checked the log files in /nsm/elsa/data/elsa/log/ for additional clues?

> --
> You received this message because you are subscribed to the Google Groups "security-onion" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to security-onio...@googlegroups.com.
> To post to this group, send email to securit...@googlegroups.com.
> Visit this group at http://groups.google.com/group/security-onion.
> For more options, visit https://groups.google.com/d/optout.



--
Doug Burks
Need Security Onion Training or Commercial Support?
http://securityonionsolutions.com

[Damon Rouse]

Yes, it looks to be cron.pl. I'll check the log and report back.

sudo ps aux | grep perl

root 1517 0.0 0.0 4396 608 ? Ss 20:03 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

Little over a hundred of these

Thanks Doug

[Damon Rouse]

Here are some tails for the logs in that location

drouse@essso:/nsm/elsa/data/elsa/log$ sudo tail web.log
* ERROR [2015/06/11 23:22:04] /opt/elsa/web/cron.pl (96) main:: 24354 [undef]
Error: Internal error at /opt/elsa/web/lib/Utils.pm line 147
* TRACE [2015/06/11 23:22:04] /opt/elsa/web/cron.pl (99) main:: 24354 [undef]
cron.pl finished.
* ERROR [2015/06/11 23:26:12] /opt/elsa/web/lib/Utils.pm (142) Utils::_dbh_error_handler 32158 [undef]
DBI connect('database=elsa_web','elsa',...) failed: Too many connections QUERY:
* ERROR [2015/06/11 23:26:12] /opt/elsa/web/cron.pl (96) main:: 32158 [undef]
Error: Internal error at /opt/elsa/web/lib/Utils.pm line 147
* TRACE [2015/06/11 23:26:12] /opt/elsa/web/cron.pl (99) main:: 32158 [undef]
cron.pl finished.

drouse@essorgso:/nsm/elsa/data/elsa/log$ sudo tail node.log
* DEBUG [2015/06/11 23:35:22] /opt/elsa/web/../node//Indexer.pm (254) Indexer::rotate_logs 33164 [undef]
Deleted /nsm/elsa/data/elsa/tmp/buffers//1434065599.87979
* TRACE [2015/06/11 23:35:22] /opt/elsa/web/../node//Indexer.pm (1782) Indexer::_get_lock 33164 [undef]
Locked directory
* WARN [2015/06/11 23:35:22] /opt/elsa/web/../node//Indexer.pm (803) Indexer::_check_consolidate 33164 [undef]
All permanent indexes used and none to consolidate, we will have to overwrite a permanent index.
* TRACE [2015/06/11 23:35:22] /opt/elsa/web/../node//Indexer.pm (1805) Indexer::_release_lock 33164 [undef]
Unlocked directory
* TRACE [2015/06/11 23:35:22] /opt/elsa/web/../node//Indexer.pm (1782) Indexer::_get_lock 33164 [undef]
Locked query

[Doug Burks]

Do you have any archive queries?
mysql -uroot -Delsa_web -e 'select * from query_log where archive=1;'

[Damon Rouse]

Yes, just looks like the alerts I have setup and the 2 queries I was trying when I received the too many mysql connections error.

[James Taylor]

I upgraded yesterday and had what seems like the same issues with 100's of the cron.pl running I was not sure what was going on but everything stopped working, SGUIL, OSSEC, ELSA snort etc.

This morning I disabled all of my alerts and rebooted and it ran successful for 6 hours will check again tomorrow.

[Doug Burks]

Have you tried canceling those 2 queries?

[namobud...@gmail.com]

How could I see ELSA queries in the queue and clear them from the command line? I have a huge amount of perl processes killing my CPU too? I rebooted and they're still there.

On Friday, June 12, 2015 at 6:49:10 AM UTC-4, Doug Burks wrote:
> Have you tried canceling those 2 queries?
>

[Doug Burks]

mysql -uroot -Delsa_web -e 'select * from query_log where archive=1;'

[namobud...@gmail.com]

How can I delete them if I find them?

Thanks,

[Doug Burks]

The safest way to cancel currently running queries is through the ELSA
web interface itself:
- click the ELSA menu
- click "Active Queries"

If that doesn't work, you can try deleting the entries from the table
manually. However, you might want to back up the mysql table before
making any manual modifications. Once you've backed it up, then do
something like the following:
delete from query_log where archive=1;

Then reboot.

[namobud...@gmail.com]

It says no queries are running in the ELSA menu, but I have a huge number of Perl processes running due to the ELSA issues, any idea about how to fix these?

Thanks!

[Doug Burks]

What was the output when you ran the following command?

mysql -uroot -Delsa_web -e 'select * from query_log where archive=1;'

[namobud...@gmail.com]

ERROR 1040 (HY000): Too many connections

So I am wondering if this is confirming that the issue is a server bottleneck. I'm in the process of turning of PRADS and SANCP.

[Damon Rouse]

I don't see any active queries in the ELSA interface. I was getting same too many connections error too when looking, so rebooted. This gave me about 10 mins of normal activity until the perl processes killed everything again. 

You received this message because you are subscribed to a topic in the Google Groups "security-onion" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/security-onion/xF9v3RfNnaM/unsubscribe.
To unsubscribe from this group and all its topics, send an email to security-onio...@googlegroups.com.

[Doug Burks]

Try disabling the cron entry as follows:

- edit /etc/cron.d/elsa
- comment out the final line
- restart cron:
sudo service cron restart
- reboot:
sudo reboot
- run mysql command:

mysql -uroot -Delsa_web -e 'select * from query_log where archive=1;'

Don't forget that you'll need to re-enable the cron entry once these
issues are resolved!

[Jeff Nucciarone]

I'm seeing the same problems with lots of perl scripts nailed at full CPU hogging all resources.

Currently I am at 73 pairs of this and a system load approaching 50. My 24 cores are getting overwhelmed.

root 31905 0.0 0.0 4396 608 ? Ss 14:10 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 31908 65.7 0.1 298388 95748 ? R 14:10 18:12 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

I tried manually running one of these without piping output to /dev/null and it just hung there.

I have no active archive queries.

mysql -uroot -Delsa_web -e 'select * from query_log where archive=1;'

give me 27 lines of output:

qid uid query system timestamp num_results milliseconds archive
125 3 {"query_string":"site:csd-k1000 class=BRO_HTTP bro_http.status_code=\\"302\\" archive:1","query_meta_params":{"limit":100,"archive":1,"timezone_offset":240,"start":"2014-03-13 16:41:26"}} 02014-03-25 13:44:37 100 337 1
126 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 240,\n "limit" : 100,\n "start" : "1394743286"\n },\n "query_string" : "site:csd-k1000 class=BRO_HTTP bro_http.status_code=\\"302\\" archive:1"\n}\n 0 2014-03-25 13:44:37 100 4294967295 1
219 3 {"query_string":"10.255.4.206 class=BRO_HTTP BRO_HTTP.method=POST archive:1","query_meta_params":{"limit":100,"archive":1,"timezone_offset":240,"start":"2014-03-24 11:44:22"}} 0 2014-03-26 15:47:35 77 1491 1
220 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 240,\n "limit" : 100,\n "start" : "1395675862"\n },\n "query_string" : "10.255.4.206 class=BRO_HTTP BRO_HTTP.method=POST archive:1"\n}\n 0 2014-03-26 15:47:36 77 2165927000 1
5807 3 {"query_string":"10.176.13.244 class=\\"BRO_HTTP\\" groupby:site limit:250 archive:1","query_meta_params":{"limit":100,"archive":1,"timezone_offset":240,"start":"2014-07-01 00:00:00"}} 02014-10-20 13:55:24 261 807 1
5808 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 240,\n "limit" : 100,\n "start" : "1404187200"\n },\n "query_string" : "10.176.13.244 class=\\"BRO_HTTP\\" groupby:site limit:250 archive:1"\n}\n 0 2014-10-20 13:55:24 11 4294967295 1
5809 3 {"query_string":"10.176.13.244 class=\\"BRO_HTTP\\" groupby:site limit:250 archive:1","query_meta_params":{"limit":100,"archive":1,"groupby":[],"timezone_offset":240,"start":"NaN-NaN-NaN NaN:NaN:NaN"}} 0 2014-10-20 13:56:35 257 1112 1
5810 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 240,\n "limit" : 100,\n "start" : "14400"\n },\n "query_string" : "10.176.13.244 class=\\"BRO_HTTP\\" groupby:site limit:250 archive:1"\n}\n 0 2014-10-20 13:56:36 7 4294967295 1
5915 3 {"query_string":"10.32.8.201 class=BRO_HTTP limit:250 \\"www.elf.cz\\" archive:1","query_meta_params":{"limit":100,"archive":1,"timezone_offset":240,"start":"2014-07-01 00:00:00"}} 0 2014-10-21 13:58:16 250 482 1
5916 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 240,\n "limit" : 100,\n "start" : "1404187200"\n },\n "query_string" : "10.32.8.201 class=BRO_HTTP limit:250 \\"www.elf.cz\\" archive:1"\n}\n 0 2014-10-21 13:58:16 0 4294967295 1
5975 3 {"query_string":"10.176.13.244 class=\\"BRO_HTTP\\" ts1.explicit.bing.net limit:11000","query_meta_params":{"archive":1,"limit":100,"timezone_offset":240,"start":"2014-07-01 00:00:00"}} 02014-10-24 15:34:18 10718 231 1
5976 1 {\n "query_meta_params" : {\n "timezone_offset" : 240,\n "limit" : 100,\n "start" : "1404187200"\n },\n "query_string" : "10.176.13.244 class=\\"BRO_HTTP\\" ts1.explicit.bing.net limit:11000"\n}\n 0 2014-10-24 15:34:18 0 320000 1
6779 3 {"query_string":"10.248.17.204 -class=BRO_HTTP fxz101 class=BRO_SYSLOG limit:20000","query_meta_params":{"limit":100,"timezone_offset":240,"start":"2014-10-26 00:00:00","end":"2014-10-27 00:00:00"}} 0 2014-11-05 21:58:13 19032 369 1
6780 1 {\n "query_meta_params" : {\n "timezone_offset" : 240,\n "limit" : 100,\n "end" : 1414382400,\n "start" : "1414296000"\n },\n "query_string" : "10.248.17.204 -class=BRO_HTTP fxz101 class=BRO_SYSLOG limit:20000"\n}\n 0 2014-11-05 21:58:13 0 28993000 1
7499 3 {"query_string":"10.32.8.153 class=\\"BRO_HTTP\\" limit::200","query_meta_params":{"limit":100,"timezone_offset":300,"start":"2014-12-05 00:45:10"}} 0 2014-12-05 19:13:53 200 231 1
7500 1 {\n "query_meta_params" : {\n "timezone_offset" : 300,\n "limit" : 100,\n "start" : "1417758310"\n },\n "query_string" : "10.32.8.153 class=\\"BRO_HTTP\\" limit::200"\n}\n 0 2014-12-05 19:13:54 80 171000 1
9551 3 {"query_string":"10.176.13.244 class=BRO_HTTP groupby:site archive:1","query_meta_params":{"limit":100,"archive":1,"timezone_offset":300,"start":"2014-90-15 00:00:00","end":"2014-09-15 23:59:59"}} 0 2015-02-24 21:30:36 100 890 1
9552 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 300,\n "limit" : 100,\n "end" : 1410843599,\n "start" : "18000"\n },\n "query_string" : "10.176.13.244 class=BRO_HTTP groupby:site archive:1"\n}\n 0 2015-02-24 21:30:36 -1 NULL 1
9553 3 {"query_string":"10.176.13.244 class=BRO_HTTP groupby:site archive:1","query_meta_params":{"limit":100,"archive":1,"groupby":[],"timezone_offset":300,"start":"2014-09-15 00:00:00","end":"2014-09-15 12:00:00"}} 0 2015-02-24 21:38:46 0 296311000 1
9554 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 300,\n "limit" : 100,\n "end" : 1410800400,\n "start" : "1410757200"\n },\n "query_string" : "10.176.13.244 class=BRO_HTTP groupby:site archive:1"\n}\n 0 2015-02-24 21:38:46 0 189761000 1
9559 3 {"query_string":"10.176.13.244 class=BRO_HTTP groupby:site limit:250 archive:1","query_meta_params":{"archive":1,"limit":100,"groupby":[],"timezone_offset":300,"start":"2014-09-15 00:00:00","end":"2014-09-15 23:59:59"}} 0 2015-02-24 22:03:25 0 465 1
9560 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 300,\n "limit" : 100,\n "end" : 1410843599,\n "start" : "1410757200"\n },\n "query_string" : "10.176.13.244 class=BRO_HTTP groupby:site limit:250 archive:1"\n}\n 0 2015-02-24 22:03:25 0 398102000 1
9571 3 {"query_string":" 10.176.14.122 class=BRO_HTTP groupby:site archive:1","query_meta_params":{"limit":100,"timezone_offset":300,"start":"2014-11-01 00:00:00","end":"2014-11-04 00:00:00"}} 02015-02-25 14:44:27 106 436 1
9572 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 300,\n "limit" : 100,\n "end" : 1415077200,\n "start" : "1414818000"\n },\n "query_string" : " 10.176.14.122 class=BRO_HTTP groupby:site archive:1"\n}\n 0 2015-02-25 14:44:27 6 629510000 1
9573 3 {"query_string":" 10.176.14.122 class=BRO_HTTP groupby:site archive:1","query_meta_params":{"limit":100,"groupby":[],"archive":1,"timezone_offset":300,"start":"2014-11-01 00:00:00","end":"2014-11-03 00:00:00"}} 0 2015-02-25 14:46:16 12 315 1
9574 1 {\n "query_meta_params" : {\n "archive" : 1,\n "timezone_offset" : 300,\n "limit" : 100,\n "end" : 1414990800,\n "start" : "1414818000"\n },\n "query_string" : " 10.176.14.122 class=BRO_HTTP groupby:site archive:1"\n}\n 0 2015-02-25 14:46:17 4 292866000 1


I don't think these are active scans.

mysqld is up to 100%, likely working on the backlog of events stacked up since the SSL issue took pcap_agent and snort_agent offline for the past 18 hours.

It does not look like I am seeing these issues onthe sensor nodes, just the master.

Frustrated that a routine update has caused major havoc on my work schedule. As Sir Toppam Hat used to say "You are causing confusion and delay!"

[namobud...@gmail.com]

Thanks Doug,

What does this entry (cron job) actually do?

[Doug Burks]

On Fri, Jun 12, 2015 at 10:43 AM, Jeff Nucciarone
<jeff.nu...@gmail.com> wrote:
> Frustrated that a routine update has caused major havoc on my work schedule. As Sir Toppam Hat used to say "You are causing confusion and delay!"

Again, I understand your frustration, but comments like this are unnecessary.
Please be patient while we work through these issues. Thanks.

You can temporarily disable the cron job as described earlier in this
thread (don't forget to re-enable it after we resolve the issues).

Have you checked the log files in /nsm/elsa/data/elsa/log/ for additional clues?

[Doug Burks]

cron.pl does a few things. The main thing is that it loads buffers
into MySQL so we'll need to re-enable that cron job once we get the
issues resolved. For more information, please see
/opt/elsa/web/cron.pl.

[Jeff Nucciarone]

On Friday, June 12, 2015 at 10:50:26 AM UTC-4, Doug Burks wrote:
> On Fri, Jun 12, 2015 at 10:43 AM, Jeff Nucciarone
> <jeff.nu...@gmail.com> wrote:
> > Frustrated that a routine update has caused major havoc on my work schedule. As Sir Toppam Hat used to say "You are causing confusion and delay!"
>
> Again, I understand your frustration, but comments like this are unnecessary.
> Please be patient while we work through these issues. Thanks.

What, you're not a fan of Thomas the Tank Engine?

[Doug Burks]

On Fri, Jun 12, 2015 at 10:58 AM, Jeff Nucciarone

<jeff.nu...@gmail.com> wrote:
> On Friday, June 12, 2015 at 10:50:26 AM UTC-4, Doug Burks wrote:
>> On Fri, Jun 12, 2015 at 10:43 AM, Jeff Nucciarone
>> <jeff.nu...@gmail.com> wrote:
>> > Frustrated that a routine update has caused major havoc on my work schedule. As Sir Toppam Hat used to say "You are causing confusion and delay!"
>>
>> Again, I understand your frustration, but comments like this are unnecessary.
>> Please be patient while we work through these issues. Thanks.
>
> What, you're not a fan of Thomas the Tank Engine?

Everybody loves Thomas the Tank Engine! :)

However, Thomas is not helping us resolve these issues any faster.

Are you able to provide any clues from the log files in
/nsm/elsa/data/elsa/log/?

[namobud...@gmail.com]

This command:

mysql -uroot -Delsa_web -e 'select * from query_log where archive=1;'

after stopping the cron.pl cron job kicked back 5 queries.

[Doug Burks]

Can you provide the full output?

[namobud...@gmail.com]

Here you go, please note redacted info:

sudo mysql -uroot -Delsa_web -e 'select * from query_log where archive=1;'
+-----+-----+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------+---------------------+-------------+--------------+---------+

| qid | uid | query | system | timestamp | num_results | milliseconds | archive |

+-----+-----+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------+---------------------+-------------+--------------+---------+
| 293 | 3 | {"query_string":"class=BRO_DNS dstport=\"redacted\" dstip=\"redacted\" limit:230000","query_meta_params":{"start_time":"2015-05-01 15:03:06","limit":100,"timezone_offset":0,"start":"2015-05-01 15:03:06"}} | 0 | 2015-05-28 15:06:33 | 460000 | 274 | 1 |
| 294 | 1 | {
"query_meta_params" : {
"timezone_offset" : 0,
"start_time" : "2015-05-01 15:03:06",
"limit" : 100,
"start" : "1430492586"
},
"query_string" : "class=BRO_DNS dstport=\"redacted\" dstip=\"redacted\" limit:230000"
}
| 0 | 2015-05-28 15:06:34 | 0 | 45000 | 1 |
| 301 | 3 | {"query_string":"class=BRO_DNS dstport=\"redacted\" dstip=\"redacted\" limit:50000","query_meta_params":{"start_time":"2015-05-01 15:03:06","limit":100,"timezone_offset":0,"start":"2015-05-01 15:03:06"}} | 0 | 2015-05-28 15:07:30 | 100000 | 207 | 1 |
| 302 | 1 | {
"query_meta_params" : {
"timezone_offset" : 0,
"start_time" : "2015-05-01 15:03:06",
"limit" : 100,
"start" : "1430492586"
},
"query_string" : "class=BRO_DNS dstport=\"redacted\" dstip=\"redacted\" limit:50000"
}
| 0 | 2015-05-28 15:07:30 | 0 | 57000 | 1 |
| 309 | 3 | {"query_string":"class=BRO_DNS dstport=\"redacted\" dstip=\"redacted\" limit:100000","query_meta_params":{"start_time":"2015-05-27 15:07:51","limit":100,"timezone_offset":0,"start":"2015-05-27 15:07:51"}} | 0 | 2015-05-28 15:08:22 | 153583 | 259 | 1 |
| 310 | 1 | {
"query_meta_params" : {
"timezone_offset" : 0,
"start_time" : "2015-05-27 15:07:51",
"limit" : 100,
"start" : "1432739271"
},
"query_string" : "class=BRO_DNS dstport=\"redacted\" dstip=\"redacted\" limit:100000"
}
| 0 | 2015-05-28 15:08:22 | 0 | 45000 | 1 |
+-----+-----+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------+---------------------+-------------+--------------+---------+

[Doug Burks]

Do you have any ELSA alerts?
- click ELSA
- click Alerts

You can also check the log files in /nsm/elsa/data/elsa/log/ for
additional clues.

[Jeff Nucciarone]

> >
> > What, you're not a fan of Thomas the Tank Engine?
>
> Everybody loves Thomas the Tank Engine! :)
>
> However, Thomas is not helping us resolve these issues any faster.

yes, but I always quote Sir Toppam Hat.

As for the logs, they're over in the other thread.

A lot of these in web.log:

* ERROR [2015/06/12 14:13:40] /opt/elsa/web/lib/Utils.pm (142) Utils::_dbh_error_handler 869 [undef]

and these in node log:

SQL_ERROR: DBD::mysql::st execute failed: MySQL server has gone away, query: INSERT INTO buffers (filename, start, end) VALUES (?,?,?) at /opt/elsa/node/elsa.pl line 216, <STDIN> line 5152683.
* ERROR [2015/06/12 14:59:20] /opt/elsa/node/Indexer.pm (350) Indexer::initial_validate_directory 2431 [undef]
* ERROR [2015/06/12 14:59:20] /opt/elsa/node/Indexer.pm (350) Indexer::initial_validate_directory 2431 [undef]
* ERROR [2015/06/12 15:00:50] /opt/elsa/node/Indexer.pm (3060) Indexer::_get_index_schema 2431 [undef]
* ERROR [2015/06/12 15:00:51] /opt/elsa/node/Indexer.pm (3060) Indexer::_get_index_schema 2431 [undef]
* ERROR [2015/06/12 15:03:01] /opt/elsa/node/Indexer.pm (1312) Indexer::load_records 2431 [undef]
* ERROR [2015/06/12 15:03:01] /opt/elsa/node/Indexer.pm (1312) Indexer::load_records 2431 [undef]
* ERROR [2015/06/12 15:03:23] /opt/elsa/node/Indexer.pm (1312) Indexer::load_records 2431 [undef]
* ERROR [2015/06/12 15:09:53] /opt/elsa/node/Indexer.pm (3060) Indexer::_get_index_schema 2431 [undef]
* ERROR [2015/06/12 15:09:53] /opt/elsa/node/Indexer.pm (3060) Indexer::_get_index_schema 2431 [undef]
* ERROR [2015/06/12 15:09:56] /opt/elsa/node/Indexer.pm (3060) Indexer::_get_index_schema 2431 [undef]
* ERROR [2015/06/12 15:10:13] /opt/elsa/node/Indexer.pm (3060) Indexer::_get_index_schema 2431 [undef]
* ERROR [2015/06/12 15:10:20] /opt/elsa/node/elsa.pl (295) main::_process_batch 2431 [undef]
* ERROR [2015/06/12 15:10:20] /opt/elsa/node/elsa.pl (295) main::_process_batch 2431 [undef]


I have 27 entries from the mysql output. There should be 0 active queries so I'm not sure where they came from. Likely orphaned from something I ran a long time ago?

[Doug Burks]

Copying my reply from the other thread:

> node.log has a lot of these. Sending just a snippet:
>
> * ERROR [2015/06/12 14:33:33] /opt/elsa/web/cron.pl (64) main:: 2571 [undef]
> * ERROR [2015/06/12 14:33:33] /opt/elsa/web/cron.pl (64) main:: 1737 [undef]
> * ERROR [2015/06/12 14:33:33] /opt/elsa/web/cron.pl (64) main:: 2382 [undef]
> * ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 3630 [undef]
> * ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 2516 [undef]
> * ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 2459 [undef]
> * ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 3185 [undef]
> * ERROR [2015/06/12 14:33:38] /opt/elsa/web/cron.pl (64) main:: 5023 [undef]

Let's focus in on these.

Was this a simple "grep -i error node.log"?

If so, is there any additional detail on the following lines?
grep -i error -A2 node.log

> --
> You received this message because you are subscribed to the Google Groups "security-onion" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to security-onio...@googlegroups.com.
> To post to this group, send email to securit...@googlegroups.com.
> Visit this group at http://groups.google.com/group/security-onion.
> For more options, visit https://groups.google.com/d/optout.

[namobud...@gmail.com]

No alerts found. What's the overall effect on the Security Onion (and ELSA/BRO) posture by disabling the cron.pl file?

Thanks,

[Doug Burks]

cron.pl does a few things. The main thing is that it loads buffers
into MySQL so we'll need to re-enable that cron job once we get the
issues resolved. For more information, please see
/opt/elsa/web/cron.pl.

[Jeff Nucciarone]

On Friday, June 12, 2015 at 11:38:56 AM UTC-4, Doug Burks wrote:
> Copying my reply from the other thread:
>

Here's my response from the other thread so that we can move and keep this discussion here:

Inline

On Friday, June 12, 2015 at 11:10:21 AM UTC-4, Doug Burks wrote:

> On Fri, Jun 12, 2015 at 11:07 AM, Jeff Nucciarone
> <jeff.nu...@gmail.com> wrote:
> > node.log has a lot of these. Sending just a snippet:
> >
> > * ERROR [2015/06/12 14:33:33] /opt/elsa/web/cron.pl (64) main:: 2571 [undef]
> > * ERROR [2015/06/12 14:33:33] /opt/elsa/web/cron.pl (64) main:: 1737 [undef]
> > * ERROR [2015/06/12 14:33:33] /opt/elsa/web/cron.pl (64) main:: 2382 [undef]
> > * ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 3630 [undef]
> > * ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 2516 [undef]
> > * ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 2459 [undef]
> > * ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 3185 [undef]
> > * ERROR [2015/06/12 14:33:38] /opt/elsa/web/cron.pl (64) main:: 5023 [undef]
>
> Let's focus in on these.
>
> Was this a simple "grep -i error node.log"?
>

yes

> If so, is there any additional detail on the following lines?
> grep -i error -A2 node.log
>

If I just run the grep I get 9488 lines of glorious output. A lot to wade thru considering you're fighting something like 3 different fires at the moment.

If I zero in on the last error message from above, I get this:

* ERROR [2015/06/12 14:33:38] /opt/elsa/web/cron.pl (64) main:: 5023 [undef]

Another cron.pl script is querying, exiting
* WARN [2015/06/12 14:33:38] /opt/elsa/node/Reader.pm (369) Reader::parse_line 2649 [undef]

I'm guessing this doesn't get us much (Another cron.pl script is querying, exiting) as there were 70+ scripts running.

If I strip out references to the other running scripts and just look at the rime stamp 14:33:xx I see these:

* ERROR [2015/06/12 14:32:19] /opt/elsa/node/elsa.pl (295) main::_process_batch 2649 [undef]
Unable to parse log line: . Only parsed into:
$VAR1 = [
--
Total errors: 1 (%0.00173451511629924)
* DEBUG [2015/06/12 14:32:38] /opt/elsa/node/elsa.pl (318) main::_process_batch 2649 [undef]
file size for file /nsm/elsa/data/elsa/tmp/buffers//1434119498.59198 is 20380262
--

* ERROR [2015/06/12 14:33:33] /opt/elsa/web/cron.pl (64) main:: 2571 [undef]

* DEBUG [2015/06/12 14:33:33] /opt/elsa/web/../node//Indexer.pm (145) Indexer::_get_current_archive_size 2516 [undef]
--

* ERROR [2015/06/12 14:33:33] /opt/elsa/web/cron.pl (64) main:: 1737 [undef]

* TRACE [2015/06/12 14:33:33] /opt/elsa/web/../node//Indexer.pm (1805) Indexer::_release_lock 2382 [undef]
--

* ERROR [2015/06/12 14:33:33] /opt/elsa/web/cron.pl (64) main:: 2382 [undef]

* WARN [2015/06/12 14:33:33] /opt/elsa/web/../node//Indexer.pm (803) Indexer::_check_consolidate 3630 [undef]
--

* ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 3630 [undef]

* TRACE [2015/06/12 14:33:34] /opt/elsa/web/../node//Indexer.pm (1782) Indexer::_get_lock 2459 [undef]
--

* ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 2516 [undef]

* WARN [2015/06/12 14:33:34] /opt/elsa/web/../node//Indexer.pm (803) Indexer::_check_consolidate 2459 [undef]
--

* ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 2459 [undef]

* WARN [2015/06/12 14:33:34] /opt/elsa/web/../node//Indexer.pm (803) Indexer::_check_consolidate 3185 [undef]
--

* ERROR [2015/06/12 14:33:34] /opt/elsa/web/cron.pl (64) main:: 3185 [undef]

* WARN [2015/06/12 14:33:34] /opt/elsa/node/Reader.pm (369) Reader::parse_line 2649 [undef]
--

* ERROR [2015/06/12 14:33:38] /opt/elsa/web/cron.pl (64) main:: 5023 [undef]

* WARN [2015/06/12 14:33:38] /opt/elsa/node/Reader.pm (369) Reader::parse_line 2649 [undef]
--
Total errors: 0 (%0)
* DEBUG [2015/06/12 14:33:38] /opt/elsa/node/elsa.pl (318) main::_process_batch 2649 [undef]
file size for file /nsm/elsa/data/elsa/tmp/buffers//1434119558.59848 is 19215902

I dumped the results to a file but it is much too large to post here. Is there an alternative location I can dump these and other log files to make it easier on you? Do you use box or something similar?

[James Taylor]

Just FYI Doug. My box ran all night just fine but after re enabling my alerts a bunch of cron.pl begin again and required reboot could be bad timing but did seem like the alerts began to spawn those.


but still getting these errors in node.log

* ERROR [2015/06/12 16:24:29] /opt/elsa/node/elsa.pl (295) main::_process_batch 2736 [undef]
* ERROR [2015/06/12 16:24:29] /opt/elsa/node/elsa.pl (295) main::_process_batch 2736 [undef]
* ERROR [2015/06/12 16:24:29] /opt/elsa/node/elsa.pl (295) main::_process_batch 2736 [undef]
* ERROR [2015/06/12 16:24:29] /opt/elsa/node/elsa.pl (295) main::_process_batch 2736 [undef]
* ERROR [2015/06/12 16:24:29] /opt/elsa/node/elsa.pl (295) main::_process_batch 2736 [undef]

[Doug Burks]

OK, sound like James has confirmed that his cron.pl issues are caused
by his ELSA alerts.

Others in this thread, have you checked to see if you have any alerts
configured in ELSA? (click the ELSA menu, then click Alerts)

[Damon Rouse]

Disabling the cron seems to have done the trick for me. My system has been up and stable for a few hours now.

When I run: mysql -uroot -Delsa_web -e 'select * from query_log where archive=1;'

I still see all my searches run against my archive...they date back over a year which seems to be what the query should return.

D

[Doug Burks]

Disabling the cron is not a permanent solution as you need that cron
job to import data into ELSA. We need to determine the root cause of
this issue so that you can re-enable the cron job.

Have you checked to see if you have any alerts

configured in ELSA? (click the ELSA menu, then click Alerts)

[Damon Rouse]

All my alerts are still active, never disabled them. I was able to delete a few I no longer needed, but still have about 20 active.

I can test an alert and see if they still trigger if you want.

[Doug Burks]

Can you try disabling your alerts and then re-enabling your cron job?

[Damon Rouse]

Yup, realize disabling the cron is just a temp fix.

Sure, but what's the best way to disable my alerts? I looked through the thread but can't seen to find that info.

Thanks

[namobud...@gmail.com]

FYI:

I have no ELSA alerts setup and I was experiencing the issue until I disabled the cron job, so there maybe other factors involved. It sounds like so new data will be imported into ELSA until this issue is fixed.

This might be time consuming, but what about installing a SO VM image from the pre-problem ISO (known good image), and then updating to the current problematic ELSA and scanning the system for changes.

I noticed the perl system-pegging issue after I updated in the last few days.

[James Taylor]

Running this test again and has been about 20 -30 minutes with all my alerts enabled and I am only seeing 2 cron.pl and they are behaving nicely.

So alerts may just be a coincidence.

[Doug Burks]

- go into the ELSA web interface

- click the ELSA menu

- click Alerts
- for each alert, click Enabled, then change to Disabled, and then click Save

[Damon Rouse]

Gotcha...sorry, duh!  Just to confirm, you want me to disable my alerts, then re-enable the cron correct?

Here's my perl process info with my alerts currently still active and the cron disabled.  

drouse@essorgso:~$ sudo ps aux | grep perl

[sudo] password for drouse: 

root      2994  0.0  0.0   4396   612 ?        S    17:48   0:00 /bin/sh -c perl /opt/elsa/node/elsa.pl -c /etc/elsa_node.conf

root      2995  5.3  0.1 244604 70796 ?        S    17:48   2:44 perl /opt/elsa/node/elsa.pl -c /etc/elsa_node.conf

drouse   22757  0.0  0.0  13608   928 pts/0    S+   18:39   0:00 grep perl

drouse@essorgso:~$ pgrep -c perl

1

You received this message because you are subscribed to a topic in the Google Groups "security-onion" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/security-onion/xF9v3RfNnaM/unsubscribe.
To unsubscribe from this group and all its topics, send an email to security-onio...@googlegroups.com.

[Doug Burks]

Yes, please disable your alerts and then re-enable your cron.

[namobud...@gmail.com]

Is there anything I could look at which might help, as I never had ELSA alerts enabled and I am experiencing the perl script cron job issue.

Also, since I disabled the cron job the system performance returned to normal, so we might not have had a hardware bottleneck after all.

[James Taylor]

Alright try not to confuse the issue this is FYI..

but I am now seeing them climb and they go up each time I get this when tailing web.log... Not sure if this means anything.



* TRACE [2015/06/12 19:04:16] /opt/elsa/web/cron.pl (82) main::__ANON__ 20716 [undef]
Ran 0 queries in 0.129647970199585 seconds.
* TRACE [2015/06/12 19:04:16] /opt/elsa/web/../node//Indexer.pm (1805) Indexer::_release_lock 20716 [undef]
Unlocked query
* TRACE [2015/06/12 19:04:16] /opt/elsa/web/cron.pl (88) main::__ANON__ 20716 [undef]
Running archive queries...
* ERROR [2015/06/12 19:04:16] /opt/elsa/web/lib/Utils.pm (142) Utils::_dbh_error_handler 20716 [undef]
DBD::mysql::st execute failed: Unknown column 'pid' in 'field list' QUERY: SELECT qid, pid FROM query_log WHERE archive=1 AND NOT ISNULL(pid) AND num_results=-1


=========================================
root 19701 0.0 0.0 4396 612 ? Ss 19:00 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 19712 96.8 0.1 298528 96176 ? R 19:00 3:52 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 20411 0.0 0.0 4396 604 ? Ss 19:01 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 20414 93.8 0.1 295224 92824 ? R 19:01 2:48 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 20525 0.0 0.0 4396 612 ? Ss 19:02 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 20528 94.8 0.1 295268 92888 ? R 19:02 1:53 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 20641 0.0 0.0 4396 612 ? Ss 19:03 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 20643 89.1 0.1 295160 92724 ? R 19:03 0:53 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 20712 0.0 0.0 4396 608 ? Ss 19:04 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 20716 0.0 0.0 54272 11320 ? R 19:04 0:00 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 20737 0.0 0.0 13604 940 pts/1 S+ 19:04 0:00 grep --color=auto perl
root 24151 0.0 0.0 4396 604 ? S 16:26 0:00 /bin/sh -c perl /opt/elsa/node/elsa.pl -c /etc/elsa_node.conf
root 24152 3.3 0.0 219552 45672 ? S 16:26 5:18 perl /opt/elsa/node/elsa.pl -c /etc/elsa_node.conf

[Damon Rouse]

Ok Doug...I disabled all my alerts, re-enabled the cron, restarted cron and rebooted.  The perl process have started coming back and have eaten up all my RAM in the last 15 minutes

drouse@essorgso:~$ pgrep -c perl

10

drouse@essorgso:~$ sudo ps aux | grep perl

root      2983  0.0  0.0   4396   612 ?        S    18:55   0:00 /bin/sh -c perl /opt/elsa/node/elsa.pl -c /etc/elsa_node.conf

root      2984  4.2  0.0 219636 45676 ?        S    18:55   0:39 perl /opt/elsa/node/elsa.pl -c /etc/elsa_node.conf

root      3359  0.0  0.0   4396   608 ?        Ss   18:56   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root      3366  0.6  0.0 241756 56844 ?        S    18:56   0:06 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root      4980  0.0  0.0   4396   612 ?        Ss   18:57   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root      4982 72.2  0.1 294632 92268 ?        R    18:57  10:10 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root     12410  0.0  0.0   4396   608 ?        Ss   19:04   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root     12412 88.1  0.1 294248 91884 ?        R    19:04   6:14 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root     13283  0.0  0.0   4396   608 ?        Ss   19:05   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root     13291 89.8  0.1 294424 92056 ?        R    19:05   5:28 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root     14645  0.0  0.0   4396   612 ?        Ss   19:06   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root     14648 84.5  0.1 294688 92312 ?        R    19:06   4:17 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root     15511  0.0  0.0   4396   612 ?        Ss   19:07   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root     15512 83.8  0.1 294424 92052 ?        R    19:07   3:25 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root     16373  0.0  0.0   4396   612 ?        Ss   19:08   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root     16375 75.3  0.1 294516 92156 ?        R    19:08   2:19 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root     17237  0.0  0.0   4396   608 ?        Ss   19:09   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root     17240 68.8  0.1 294424 92052 ?        R    19:09   1:26 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root     18112  0.0  0.0   4396   608 ?        Ss   19:10   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root     18117 26.5  0.1 294424 92052 ?        R    19:10   0:17 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root     19451  0.0  0.0   4396   608 ?        Ss   19:11   0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root     19453 19.8  0.0 241392 56272 ?        S    19:11   0:00 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

drouse   19480  0.0  0.0  13608   928 pts/0    S+   19:11   0:00 grep perl

Just refreshed and now have 13 perl processes

[James Taylor]

Do you see this in your web.log?  Not sure what it means but it is one for one with my processed spawning?

* TRACE [2015/06/12 19:04:16] /opt/elsa/web/cron.pl (82) main::__ANON__ 20716 [undef]
Ran 0 queries in 0.129647970199585 seconds.
* TRACE [2015/06/12 19:04:16] /opt/elsa/web/../node//Indexer.pm (1805) Indexer::_release_lock 20716 [undef]
Unlocked query
* TRACE [2015/06/12 19:04:16] /opt/elsa/web/cron.pl (88) main::__ANON__ 20716 [undef]
Running archive queries...
* ERROR [2015/06/12 19:04:16] /opt/elsa/web/lib/Utils.pm (142) Utils::_dbh_error_handler 20716 [undef]
DBD::mysql::st execute failed: Unknown column 'pid' in 'field list' QUERY: SELECT qid, pid FROM query_log WHERE archive=1 AND NOT ISNULL(pid) AND num_results=-1

E-Mail to and from me, in connection with the transaction
of public business, is subject to the Wyoming Public Records
Act and may be disclosed to third parties.

[Damon Rouse]

Quick update

Things seem to have stabilized a bit int he past few minutes even though my perl processes continue to increase. About 20 GB of RAM have freed up and I haven't seen any of the other symptoms like too many mysql connections.

For your info:

drouse@essorgso:~$ pgrep -c perl

23

drouse@essorgso:~$ sudo ps aux | grep perl
root 2983 0.0 0.0 4396 612 ? S 18:55 0:00 /bin/sh -c perl /opt/elsa/node/elsa.pl -c /etc/elsa_node.conf

root 2984 5.1 0.0 219636 45676 ? R 18:55 1:28 perl /opt/elsa/node/elsa.pl -c /etc/elsa_node.conf

root 3359 0.0 0.0 4396 608 ? Ss 18:56 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 3366 29.3 0.1 294628 92276 ? R 18:56 8:12 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root 4980 0.0 0.0 4396 612 ? Ss 18:57 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 4982 85.2 0.1 294632 92268 ? R 18:57 23:00 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root 12410 0.0 0.0 4396 608 ? Ss 19:04 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 12412 95.5 0.1 294248 91884 ? R 19:04 19:04 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root 13283 0.0 0.0 4396 608 ? Ss 19:05 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 13291 96.4 0.1 294424 92056 ? R 19:05 18:17 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root 14645 0.0 0.0 4396 612 ? Ss 19:06 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 14648 95.2 0.1 294688 92312 ? R 19:06 17:07 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root 15511 0.0 0.0 4396 612 ? Ss 19:07 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 15512 95.7 0.1 294424 92052 ? R 19:07 16:15 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root 16373 0.0 0.0 4396 612 ? Ss 19:08 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 16375 94.9 0.1 294516 92156 ? R 19:08 15:09 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root 17237 0.0 0.0 4396 608 ? Ss 19:09 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 17240 95.3 0.1 294424 92052 ? R 19:09 14:15 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root 18112 0.0 0.0 4396 608 ? Ss 19:10 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 18117 93.9 0.1 294424 92052 ? R 19:10 13:07 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf

root 19451 0.0 0.0 4396 608 ? Ss 19:11 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

root 19453 93.0 0.1 294688 92320 ? R 19:11 12:03 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 20319 0.0 0.0 4396 612 ? Ss 19:12 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 20320 91.3 0.1 294424 92060 ? R 19:12 10:55 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 21167 0.0 0.0 4396 608 ? Ss 19:13 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 21170 91.9 0.1 294516 92132 ? R 19:13 10:05 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 22110 0.0 0.0 4396 608 ? Ss 19:14 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 22113 89.4 0.1 294688 92324 ? R 19:14 8:55 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 23033 0.0 0.0 4396 612 ? Ss 19:15 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 23038 87.4 0.1 294520 92144 ? R 19:15 7:50 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 24884 0.0 0.0 4396 608 ? Ss 19:16 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 24887 84.7 0.1 294688 92316 ? R 19:16 6:44 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 25539 0.0 0.0 4396 608 ? Ss 19:17 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 25543 80.8 0.1 294516 92148 ? R 19:17 5:37 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 26320 0.0 0.0 4396 612 ? Ss 19:18 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 26321 77.8 0.1 294696 92332 ? R 19:18 4:38 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 27250 0.0 0.0 4396 608 ? Ss 19:19 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 27254 69.6 0.1 294520 92152 ? R 19:19 3:27 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 28224 0.0 0.0 4396 612 ? Ss 19:20 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 28227 96.0 0.1 294680 92316 ? R 19:20 3:48 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 29661 0.0 0.0 4396 608 ? Ss 19:21 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 29667 42.6 0.1 294688 92324 ? R 19:21 1:15 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 29775 0.0 0.0 4396 612 ? Ss 19:22 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 29776 91.9 0.1 294432 92040 ? R 19:22 1:48 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
root 30701 0.0 0.0 4396 608 ? Ss 19:23 0:00 /bin/sh -c perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1
root 30702 6.4 0.0 241656 56676 ? S 19:23 0:03 perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf
drouse 30825 0.0 0.0 13608 924 pts/0 S+ 19:23 0:00 grep perl

[Doug Burks]

On Fri, Jun 12, 2015 at 3:06 PM, James Taylor <jtay...@gmail.com> wrote:
> Alright try not to confuse the issue this is FYI..
>
> but I am now seeing them climb and they go up each time I get this when tailing web.log... Not sure if this means anything.
>
>
>
> * TRACE [2015/06/12 19:04:16] /opt/elsa/web/cron.pl (82) main::__ANON__ 20716 [undef]
> Ran 0 queries in 0.129647970199585 seconds.
> * TRACE [2015/06/12 19:04:16] /opt/elsa/web/../node//Indexer.pm (1805) Indexer::_release_lock 20716 [undef]
> Unlocked query
> * TRACE [2015/06/12 19:04:16] /opt/elsa/web/cron.pl (88) main::__ANON__ 20716 [undef]
> Running archive queries...
> * ERROR [2015/06/12 19:04:16] /opt/elsa/web/lib/Utils.pm (142) Utils::_dbh_error_handler 20716 [undef]
> DBD::mysql::st execute failed: Unknown column 'pid' in 'field list' QUERY: SELECT qid, pid FROM query_log WHERE archive=1 AND NOT ISNULL(pid) AND num_results=-1

This looks like an important clue. I checked a new installation and
it does have the pid column whereas an upgrade installation does not.
Tracking down the database schema update now...

[Damon Rouse]

Last 2 tails of the web.log for me are below

* DEBUG [2015/06/12 19:50:19] /opt/elsa/web/lib/Controller.pm (909) Controller::_get_schedule_actions 41527 [undef]

plugin: Connector::StreamGrep, desc: Grep streams for each record

* TRACE [2015/06/12 19:50:19] /opt/elsa/web/cron.pl (82) main::__ANON__ 41527 [undef]

Ran 0 queries in 0.147433042526245 seconds.

* TRACE [2015/06/12 19:50:19] /opt/elsa/web/../node//Indexer.pm (1805) Indexer::_release_lock 41527 [undef]

Unlocked query

* TRACE [2015/06/12 19:50:19] /opt/elsa/web/cron.pl (88) main::__ANON__ 41527 [undef]

Running archive queries...

* ERROR [2015/06/12 19:50:19] /opt/elsa/web/lib/Utils.pm (142) Utils::_dbh_error_handler 41527 [undef]

DBD::mysql::st execute failed: Unknown column 'pid' in 'field list' QUERY: SELECT qid, pid FROM query_log WHERE archive=1 AND NOT ISNULL(pid) AND num_results=-1

* DEBUG [2015/06/12 19:52:25] /opt/elsa/web/lib/Controller.pm (909) Controller::_get_schedule_actions 42127 [undef]

plugin: Connector::StreamGrep, desc: Grep streams for each record

* TRACE [2015/06/12 19:52:25] /opt/elsa/web/cron.pl (82) main::__ANON__ 42127 [undef]

Ran 0 queries in 0.237276077270508 seconds.

* TRACE [2015/06/12 19:52:25] /opt/elsa/web/../node//Indexer.pm (1805) Indexer::_release_lock 42127 [undef]

Unlocked query

* TRACE [2015/06/12 19:52:25] /opt/elsa/web/cron.pl (88) main::__ANON__ 42127 [undef]

Running archive queries...

* ERROR [2015/06/12 19:52:25] /opt/elsa/web/lib/Utils.pm (142) Utils::_dbh_error_handler 42127 [undef]

DBD::mysql::st execute failed: Unknown column 'pid' in 'field list' QUERY: SELECT qid, pid FROM query_log WHERE archive=1 AND NOT ISNULL(pid) AND num_results=-1

[Damon Rouse]

My latest update, still with all alerts disabled and the cron enabled.

System is getting bogged down now

drouse@essorgso:~$ pgrep -c perl

74
drouse@essorgso:~$ sudo tail /nsm/elsa/data/elsa/log/web.log
[sudo] password for drouse:
* ERROR [2015/06/12 20:15:26] /opt/elsa/web/cron.pl (96) main:: 393 [undef]

Error: Internal error at /opt/elsa/web/lib/Utils.pm line 147

* TRACE [2015/06/12 20:15:26] /opt/elsa/web/cron.pl (99) main:: 393 [undef]
cron.pl finished.
* ERROR [2015/06/12 20:16:19] /opt/elsa/web/lib/Utils.pm (142) Utils::_dbh_error_handler 949 [undef]

DBI connect('database=elsa_web','elsa',...) failed: Too many connections QUERY:

* ERROR [2015/06/12 20:16:19] /opt/elsa/web/cron.pl (96) main:: 949 [undef]

Error: Internal error at /opt/elsa/web/lib/Utils.pm line 147

* TRACE [2015/06/12 20:16:19] /opt/elsa/web/cron.pl (99) main:: 949 [undef]
cron.pl finished.

[Doug Burks]

It looks like the only thing that has changed in the elsa_web database
schema is the pid column in the query table.

Please try the following:

# verify there is no pid column in the query_log table:
mysql -uroot -Delsa_web -e 'describe query_log;'

# add the pid column:
mysql -uroot -Delsa_web -e 'alter table query_log add column pid
smallint unsigned'

# verify the pid column got added:
mysql -uroot -Delsa_web -e 'describe query_log;'

# reboot
sudo reboot

# re-enable cron job and ELSA alerts while keeping an eye on system
activity and logs

> You received this message because you are subscribed to the Google Groups "security-onion" group.

> To unsubscribe from this group and stop receiving emails from it, send an email to security-onio...@googlegroups.com.

> To post to this group, send email to securit...@googlegroups.com.
> Visit this group at http://groups.google.com/group/security-onion.
> For more options, visit https://groups.google.com/d/optout.

[Doug Burks]

I've created the following issue for this:

ELSA 1205 package didn't add the pid column to the query_log table for
upgrades #748
https://github.com/Security-Onion-Solutions/security-onion/issues/748

[Damon Rouse]

Thanks Doug

I'll try as soon as I'm out of this meeting

[namobud...@gmail.com]

I just implemented this, and rebooted. I just un-commented out the line in /etc/cron.d/elsa and rebooted. Was there anything else I needed to do besides the DB schema update?

10 minutes in all is well.

[Doug Burks]

That should be it. Please let us know how it goes. Thanks!

[namobud...@gmail.com]

Also I can't remember whether there was a space at the beginning of /etc/cron.d/elsa or not?

* * * * * root perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

or if it matters.

[Doug Burks]

No space at the beginning of the line. Should look like this:

# /etc/cron.d/elsa
#
# crontab entry for ELSA

SHELL=/bin/sh
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin

* * * * * root perl /opt/elsa/web/cron.pl -c /etc/elsa_web.conf > /dev/null 2>&1

[namobud...@gmail.com]

Thanks, I just looked at the same file on a sensor and removed the space before the "* char and rebooted, so far, so good.

[Damon Rouse]

I was able to do this about 30 mins ago and everything seems nice and stable since.

Damon

On Friday, June 12, 2015 at 1:25:45 PM UTC-7, Doug Burks wrote:

[Doug Burks]

Glad to hear it, thanks!

An updated package has been submitted for testing:
https://groups.google.com/d/topic/security-onion-testing/CnDvHgysVwE/discussion

[James Taylor]

Doug, running with the added pid column seems to be working for the last hour or so. Thanks for the assistance.

I will try to test that package if time allows.

[Doug Burks]

Thanks, James!

[Damon Rouse]

One small item that I've found since adding the pid column, enabling the cron and my alerts and rebooting is that my alerts aren't being sent via email.  I've tested three and none of them fire off emails like they used to.

With the changes we made, do you think it could have caused an issue with how ELSA alerts are processed?  Should I just delete and recreate to test?

Thanks

Damon

Thanks, James!

You received this message because you are subscribed to a topic in the Google Groups "security-onion" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/security-onion/xF9v3RfNnaM/unsubscribe.
To unsubscribe from this group and all its topics, send an email to security-onio...@googlegroups.com.

[Damon Rouse]

Just a quick update--I'm still not receiving email alerts from ELSA. I double checked all the changes I made, rebooted one more time and still nada. I even went in and deleted a few alerts, recreated them and tested, still no email alerts.

Is there a log I can check for ELSA's processing of email?

Thanks

[Doug Burks]

Please start a new thread to troubleshoot emails. 

--
You received this message because you are subscribed to the Google Groups "security-onion" group.
To unsubscribe from this group and stop receiving emails from it, send an email to security-onio...@googlegroups.com.
To post to this group, send email to securit...@googlegroups.com.
Visit this group at http://groups.google.com/group/security-onion.
For more options, visit https://groups.google.com/d/optout.

[Jeff Nucciarone]

I wasn't able to post earlier (other network issues) but this corrected it for my installation as well.

Thanks much Doug!

[Doug Burks]

This fix happens automatically in the latest ELSA packages which are
now available in the stable PPA:
http://blog.securityonion.net/2015/06/new-elsa-packages-resolve-three-issues.html