Lots of Curator processes not stopping

[greatapoc]

2.3.2 Standalone install

CPU is pegging at 99%. ps -aux shows a lot of this:

root 63100 0.0 0.0 113280 1196 ? Ss 02:55 0:00 /bin/sh -c /usr/sbin/so-curator-closed-delete > /opt/so/log/curator/cron-closed-delete.log 2>&1
root 63103 0.0 0.0 113280 1348 ? S 02:55 0:00 /bin/bash /usr/sbin/so-curator-closed-delete
root 63141 0.0 0.0 113284 1056 ? S 02:55 0:00 /bin/bash /usr/sbin/so-curator-closed-delete
root 64551 0.0 0.0 182472 2532 ? S 03:17 0:00 /usr/sbin/CROND -n
root 64561 0.0 0.0 113280 1196 ? Ss 03:17 0:00 /bin/sh -c /usr/sbin/so-curator-close > /opt/so/log/curator/cron-close.log 2>&1
root 64568 0.0 0.0 113280 1184 ? S 03:17 0:00 /bin/bash /usr/sbin/so-curator-close
root 64575 0.0 0.0 113280 1348 ? S 03:17 0:00 /bin/bash /usr/sbin/so-curator-closed-delete
root 64599 0.0 0.0 113284 1048 ? S 03:17 0:00 /bin/bash /usr/sbin/so-curator-closed-delete
root 65015 0.0 0.0 182472 2532 ? S 04:04 0:00 /usr/sbin/CROND -n
root 65016 0.0 0.0 182472 2532 ? S 04:04 0:00 /usr/sbin/CROND -n
root 65024 0.0 0.0 113280 1192 ? Ss 04:04 0:00 /bin/sh -c /usr/sbin/so-curator-closed-delete > /opt/so/log/curator/cron-closed-delete.log 2>&1
root 65026 0.0 0.0 113280 1196 ? Ss 04:04 0:00 /bin/sh -c /usr/sbin/so-curator-close > /opt/so/log/curator/cron-close.log 2>&1
root 65030 0.0 0.0 113280 1344 ? S 04:04 0:00 /bin/bash /usr/sbin/so-curator-closed-delete
root 65031 0.0 0.0 113280 1344 ? S 04:04 0:00 /bin/bash /usr/sbin/so-curator-close
root 65063 0.0 0.0 113284 1040 ? S 04:04 0:00 /bin/bash /usr/sbin/so-curator-closed-delete

Log file shows a lot of this:
[root@securityonion onion]# cat /opt/so/log/curator/cron-closed-delete.log
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 253 100 253 0 0 128k 0 --:--:-- --:--:-- --:--:-- 247k
{"error":{"root_cause":[{"type":"action_request_validation_exception","reason":"Validation Failed: 1: index / indices is missing;"}],"type":"action_request_validation_exception","reason":"Validation Failed: 1: index / indices is missing;"},"status":400} % Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 253 100 253 0 0 11810 0 --:--:-- --:--:-- --:--:-- 12047
{"error":{"root_cause":[{"type":"action_request_validation_exception","reason":"Validation Failed: 1: index / indices is missing;"}],"type":"action_request_validation_exception","reason":"Validation Failed: 1: index / indices is missing;"},"status":400} % Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 253 100 253 0 0 72059 0 --:--:-- --:--:-- --:--:-- 84333
{"error":{"root_cause":[{"type":"action_request_validation_exception","reason":"Validation Failed: 1: index / indices is missing;"}],"type":"action_request_validation_exception","reason":"Validation Failed: 1: index / indices is missing;"},"status":400} % Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 253 100 253 0 0 95077 0 --:--:-- --:--:-- --:--:-- 123k

I've had some other problems which I've posted about recently which seem to be to do with running out of diskspace.

[root@securityonion onion]# df -h
Filesystem Size Used Avail Use% Mounted on
devtmpfs 32G 0 32G 0% /dev
tmpfs 32G 300K 32G 1% /dev/shm
tmpfs 32G 14M 32G 1% /run
tmpfs 32G 0 32G 0% /sys/fs/cgroup
/dev/mapper/system-root 293G 41G 253G 14% /
/dev/sda2 492M 189M 303M 39% /boot
/dev/mapper/system-nsm 814G 725G 90G 89% /nsm
/dev/mapper/system-tmp 2.0G 50M 1.9G 3% /tmp
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/9f3fe2f7cb5cdcd449e4c621042d4a8ca9f4fcd1e84c73cb31a0f10043488c5d/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/017f0cadc85019febb50b95f343b1e74048708b59799d60a3828750109d86222/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/586f4a6c6488c47e8af89984c0ddce2dc8abd11e9ad04af4a6b0a5ec65120a3e/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/db18aa69214e51efabc9d40ccde3a843c7297a8bde5e3d149aa41590a60c6510/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/9fd6b808c12bd140aff3e0885b63e1bd0bce36a8471853ee6b6458f6d4671ec4/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/500b926d1dd12f924c482879c0001890d690fb40a94588a21ba5743e8cc88288/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/f20006123fd48146e31bb84534754e03471bc67779042656a589903ec9f714e3/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/5f8b842bb09939ffbd60187965d6dd20952ffe29a6276598d1f4cf8a4d2e9e6f/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/470198e07a0c18466262b2c2fd2e9fd3cf84291e18374391059d38111ffa576c/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/d6e611058da686e09294a4bfe36434ab4c03b57e2310046a4b59976eaeda969b/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/ffa5294c0d4596d06d5a119925a8c65b261327f32779ca5b6b28f00ecbc88cef/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/5319582930cd91cc28a95acc1f55763549fc7355689ebb193567cd23fbd9156d/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/0e63c9908e00d1984e00aa9361a084e69e207899998dc2f695ece881079a3325/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/f86a2d063d63201c4c74fe7f90c30698ff72a2d073725a8230429f3e812de705/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/164bfabd05416a115f2f03f3db36b35e8ad0214da65df459d1c9fdab26384951/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/ffad90725b376410bb5312277e58fe79e517892539228720942b090d26ab6728/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/770975bee6007bb4f644a09e84811eaee47b2f51e6b30c403f73df493d42afd3/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/d60b407a67c76d9d3d2de8d8bd1b6e2d3acf654fa9bcc764497292f9964724c1/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/fd82e00e0867e36eb397786d07a30f6ca5c7e581ff43f4587928f3e98819f731/merged
tmpfs 6.3G 0 6.3G 0% /run/user/0
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/7455577b729b887e6b9d2187988cca6bca49a9189491465b9e96cb7c182368bf/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/3faa3042f9d39b1012defdc319ec3fc4840c35d4ac3745f17f30e82c49182863/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/c343b3658502108844659b607e91431882a221e108944b045ac872a5a5f9da32/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/11cd2c472671dc92f59e8e043e71388dda8a9bd87b9e2e4a4880f5f311a19b4c/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/7f84a0e7bed867c1f539e5ca6a2008b2015cb295ec492c9f39e6a95380e7e152/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/55ae2dd51fbb5fc1b5f4744a238e544eceb6e4c2e58c31003338dae354657d35/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/69e0781b8e6ff8f376c3c9768fc459aaff6aff2ba5ab5eb7c06f1c301e9d50d8/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/526573d7eb9c764fa4fe38350c89e56ba07368ff8c3938a2d4261eec2c22db64/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/212de6692edcc5cc2222e6453a3ee5e0f2cc068adfdc83ba1b4a80e0b618eb1b/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/d6305f154718964b240b01c64540c764c37daa9c46489b4edb3bf57ca4cce855/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/9374d9cef457cb815ce4da754b476d9472d5e81caa620fd2bebe1564c299651e/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/4a31658df3e9292d8dd1b24b05d983238dd0fdd9ac2e0e885e579fdc6d802fa8/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/640d612f98c3eb1aaa3091035c1c9d92d58bdbc825a8b021440110f35fd8f194/merged
overlay 293G 41G 253G 14% /var/lib/docker/overlay2/6d5b1fe3665d5859c03b95394e34387030e8882484d084f47d5d91fb58bc2bf7/merged
tmpfs 6.3G 0 6.3G 0% /run/user/1000

Elasticsearch using all the CPU. Host is a 6 core (12 HT) 2.3GHz Xeon.

[root@securityonion onion]# top
top - 04:15:25 up 1:41, 1 user, load average: 39.47, 42.65, 43.84
Tasks: 991 total, 8 running, 980 sleeping, 0 stopped, 3 zombie
%Cpu(s): 87.0 us, 9.2 sy, 0.5 ni, 0.2 id, 0.0 wa, 0.0 hi, 3.0 si, 0.0 st
KiB Mem : 65764484 total, 1118620 free, 42290556 used, 22355308 buff/cache
KiB Swap: 8388604 total, 8388604 free, 0 used. 22926924 avail Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
13317 elastic+ 20 0 482.2g 19.5g 1.9g S 692.8 31.1 551:29.91 java
21827 root 20 0 1819924 125476 25140 S 104.3 0.2 93:58.73 filebeat
15742 suricata 20 0 2960344 1.7g 22304 S 62.3 2.6 80:47.57 Suricata-Main
20310 zeek 20 0 6805528 6.2g 145548 R 61.3 9.9 36:15.86 zeek
20321 zeek 20 0 1206396 510032 145524 R 50.5 0.8 26:40.78 zeek
20301 zeek 20 0 821320 468564 145540 R 46.6 0.7 25:39.72 zeek
14805 logstash 20 0 9338560 1.7g 22920 S 42.0 2.8 42:54.00 java

[weslambert]

Hmm, I'll have to check on this, as we added a fix for something similar, here: c611996#diff-9f90044f32ca0152c18146ecf3c7edb45b803f48cae9738a231946b704cce794 , which should be in 2.3.2, iirc.

[weslambert]

No worries! Definitely want to get it sorted out in case this is a larger issue.

[greatapoc]

So when I left off I disabled my monitor interfaces to allow everything to hopefully catch up. I've come in this morning and cpu is at 20%, /nsm is 78% full and there are no Curator processes increasing. I enabled my monitor interfaces and CPU shot back up to 99% on approximately 200mbps of monitor traffic, bulk of CPU going to ES. It seems as though things are running reasonably normal now as far as space recovery. It's possible my machine is just underspecced but perhaps some sort of protection needs to be put on the scripts so it can't keep blowing out?

Thanks again for all your help.

[greatapoc]

I've left it running since my previous comment and it has filled up and processes increasing again.

[weslambert]

What do the Curator and ES logs say?

[greatapoc]

Which log files in particular would you like to see? The Curator log files seem to have blown out significantly. curator.log is 525MB and so-curator-closed-delete-delete.log is 433MB.

cron-closed-delete.log
elasticsearch.log

[dougburks]

WARNING! THIS NEW SCRIPT HASN'T HAD MUCH TESTING YET! PROCEED WITH CAUTION!

On the manager, replace /opt/so/saltstack/default/salt/curator/files/bin/so-curator-closed-delete-delete with:
https://raw.githubusercontent.com/Security-Onion-Solutions/securityonion/patch_2.3.3/salt/curator/files/bin/so-curator-closed-delete-delete

Then on the search node(s), do:

sudo killall curl
sudo salt-call state.apply curator

[dougburks]

I did warn that the new script hasn't had much testing yet! 😄

Just uploaded a new version that fixes a few variables. 😄

[greatapoc]

Good stuff, just updated it :)

I might still have an issue with CPU but I'm not sure if it's just my machine being underspec. CPU is still at 99%

https://snapshot.raintank.io/dashboard/snapshot/jNYvINuhgzfed9J1Ts7jVbHqpHlADO1p

Output of curl -X GET "localhost:9200/_nodes/hot_threads?pretty"
https://pastebin.com/jeKKbMPv

[dougburks]

If you're no longer seeing the issue of Lots of Curator processes not stopping, then please start a separate discussion with appropriate title for additional troubleshooting. Thanks! 😄

[greatapoc]

Good call, thanks again for your help :)

[greatapoc]

@dougburks Probably holding off on a new discussion for now, I think I fixed it. CPU is still high (70-80%) but definitely better than it was at 99%.

I increased the ES heap size from 16GB to 30GB and that seems to have settled things down. This machine has 64GB RAM. I also had a whole bunch of .yaml files in /opt/so/rules/elastalert/playbook that hadn't been cleared out despite having turned off the plays. I deleted all those.

It remains to be seen if the script change improves the disk space scavenging as I did a so-elastic-clear and it hasn't gotten back up to what it was.

Thank you once again for your help.