Suricata log rotation bug

wrightsonm

I am running PfSense 2.5.2-RELEASE with Suricata package 6.0.0_11

I have noticed that my suricata logs are not correctly rotating and slowly filling the disk.
Any ideas on how to fix this would be appreciated

Jul 11 11:15 I delete all of the logs.

This is the state of the folder prior to restarting suricata.
alerts.log.2021_0712_0635 is still being appended to by suricata.
It is as if the file has by moved and suricata is still writing to it.

[2.5.2-RELEASE][root@firewall]/var/log/suricata/suricata_igb063733: ls -lah
total 10096264
drwxr-xr-x  2 root  wheel   512B Jul 18 19:00 .
drwx------  3 root  wheel   512B Jul 11 11:15 ..
-rw-r--r--  1 root  wheel     0B Jul 21 20:45 alerts.log
-rw-r--r--  1 root  wheel   9.6G Jul 21 20:48 alerts.log.2021_0712_0635
-rw-r--r--  1 root  wheel     0B Jul 21 20:45 http.log
-rw-r--r--  1 root  wheel    32M Jul 21 20:48 http.log.2021_0712_0330
-rw-r--r--  1 root  wheel    30K Jul 21 20:49 suricata.log

Jul 21 20:48 I restart suricata
The archived log file is nolonger being written to & the alerts.log file is now being filled

[2.5.2-RELEASE][root@firewall]/var/log/suricata/suricata_igb063733: ls -lah
total 10096276
drwxr-xr-x  2 root  wheel   512B Jul 18 19:00 .
drwx------  3 root  wheel   512B Jul 11 11:15 ..
-rw-r--r--  1 root  wheel   614B Jul 21 21:15 alerts.log
-rw-r--r--  1 root  wheel   9.6G Jul 21 20:48 alerts.log.2021_0712_0635
-rw-r--r--  1 root  wheel   4.1K Jul 21 21:17 http.log
-rw-r--r--  1 root  wheel    32M Jul 21 20:48 http.log.2021_0712_0330
-rw-r--r--  1 root  wheel    30K Jul 21 20:50 suricata.log
[2.5.2-RELEASE][root@firewall]/var/log/suricata/suricata_igb063733: stat *
125 6580999 -rw-r--r-- 1 root wheel 13154629 614 "Jul 12 06:35:01 2021" "Jul 21 21:15:54 2021" "Jul 21 21:15:54 2021" "Jul 12 06:35:01 2021" 32768 8 0 alerts.log
125 6580995 -rw-r--r-- 1 root wheel 13154512 10302656397 "Jul 11 11:15:09 2021" "Jul 21 20:48:18 2021" "Jul 21 20:48:18 2021" "Jul 11 11:15:09 2021" 32768 20127424 0 alerts.log.2021_0712_0635
125 6580998 -rw-r--r-- 1 root wheel 13154592 4162 "Jul 12 03:30:00 2021" "Jul 21 21:17:00 2021" "Jul 21 21:17:00 2021" "Jul 12 03:30:00 2021" 32768 16 0 http.log
125 6580997 -rw-r--r-- 1 root wheel 13154824 33253244 "Jul 11 19:00:00 2021" "Jul 21 20:48:58 2021" "Jul 21 20:48:58 2021" "Jul 11 19:00:00 2021" 32768 65024 0 http.log.2021_0712_0330
125 6580994 -rw-r--r-- 1 root wheel 13154424 31049 "Jul 11 11:15:09 2021" "Jul 21 20:50:14 2021" "Jul 21 20:50:14 2021" "Jul 11 11:15:09 2021" 32768 64 0 suricata.log

The log folder size is much larger than the max size specified in config.

[2.5.2-RELEASE][root@firewall]/var/log: du -hs ./suricata/
9.6G    ./suricata/

The log management config is mostly set to default values:
The directory size limit has been set to 4096MB

22/7/21 - Suricata crashes at 00:14 after updating rules. I restarted suricata and left it for another day.

[2.5.2-RELEASE][root@firewall]/var/log/suricata/suricata_igb063733: ls -lah
total 10096272
drwxr-xr-x  2 root  wheel   512B Jul 18 19:00 .
drwx------  3 root  wheel   512B Jul 11 11:15 ..
-rw-r--r--  1 root  wheel   414B Jul 22 13:40 alerts.log
-rw-r--r--  1 root  wheel   9.6G Jul 21 20:48 alerts.log.2021_0712_0635
-rw-r--r--  1 root  wheel   2.2K Jul 22 13:40 http.log
-rw-r--r--  1 root  wheel    32M Jul 21 20:48 http.log.2021_0712_0330
-rw-r--r--  1 root  wheel    31K Jul 22 00:15 suricata.log

This is the status today 23/7/21 at 14:44

[2.5.2-RELEASE][root@firewall]/var/log/suricata/suricata_igb063733: ls -lah
total 90696
drwxr-xr-x  2 root  wheel   512B Jul 22 21:40 .
drwx------  3 root  wheel   512B Jul 11 11:15 ..
-rw-r--r--  1 root  wheel     0B Jul 22 19:20 alerts.log
-rw-r--r--  1 root  wheel    51M Jul 23 14:44 alerts.log.2021_0722_1920
-rw-r--r--  1 root  wheel     0B Jul 22 21:40 http.log
-rw-r--r--  1 root  wheel    32M Jul 21 20:48 http.log.2021_0712_0330
-rw-r--r--  1 root  wheel   5.2M Jul 23 14:44 http.log.2021_0722_2140
-rw-r--r--  1 root  wheel    31K Jul 22 19:17 suricata.log

it definitely looks like it rotated the log files, but is still writing to the original file…!

bmeeks

@wrightsonm
The log rotation capability in the Suricata binary is very limited. You could say it is almost non-existent. There is an option to rotate EVE log files based on time, but not size. Snort offers much better internal log size management in my opinion via features in the Snort binary.

The Suricata developer team philosophically prefers to leave log file management to an outside tool (for example, logrotate in Linux). So in the Suricata GUI package an attempt is made to emulate what logrotate does by way of a cron task that wakes up and runs every 5 minutes. That task scans the logs directory and tries to rotate the files and control growth per the settings on the LOGS MGMT tab.

One difficulty can arise if the cron task is unable to properly signal the running Suricata daemon (or daemons, in the case of multiple interfaces) to restart logging. The daemon needs to be notified to stop writing to the old file handle, and instead open a new one. That sometimes doesn't happen smoothly, especially if for some other reason multiple instances of Suricata have gotten started on the same physical interface. That may be what is happening in your case. Especially if you are running the 6.0.0_11 version of the package. That version had a bug in the rules update code that caused the INTERFACES tab to "falsely" indicate Suricata was not running when it actually was. So if you restarted Suricata from there, you likely wound up with two running instances on the same interface. To test that, run this command from a shell prompt on the firewall:

ps -ax | grep suricata

You should see only a single instance of Suricata per configured interface. If you see any duplicates, you will need to kill them. The easiest way to do that is shutdown all Suricata instances using the GUI controls on the INTERFACES tab, then return to the shell prompt and issue the command again. If running Suricata processes remain, note their Process ID (pid) and then run this command on each pid:

kill -9 <pid>

Exit the shell prompt and return to the INTERFACES tab in the GUI. Restart the interfaces.

After you get this cleaned up, upgrade to the latest 6.0.0_12 version that is available now. It fixes the problem with showing falsely showing Suricata "down" when it is actually "up" following a rules update.

wrightsonm

@bmeeks thanks for the fast detailed reply.

Indeed the gui thinks the interface is down:

and two instances are running:

[2.5.2-RELEASE][root@firewall]/root: ps -ax | grep suricata
46578  -  SNs     28:46.54 /usr/local/bin/suricata -i igb0 -D -c /usr/local/etc
58897  -  Ss      17:40.77 /usr/local/bin/suricata -i igb0 -D -c /usr/local/etc
50376  0  S+       0:00.00 grep suricata

In the current version of suricata that i'm using. starting the interface adds a new suricata process, and stopping it from the GUI does NOT stop an instance of suricata, so the number of instances grows.

I have just upgraded to v12 and the same problem occurs if you click start/stop suricata on the interface list:

[2.5.2-RELEASE][root@firewall]/root: ps -ax | grep suricata
99499  -  Rs       0:22.14 /usr/local/bin/suricata -i igb0 -D -c /usr/local/etc/suricata/suricata_63733_igb0/suricata.yaml --pidfi
67811  0  R+       0:00.00 grep suricata
#stop and start suricata on the gui interface list
[2.5.2-RELEASE][root@firewall]/root: ps -ax | grep suricata
93487  -  Rs       0:03.27 /usr/local/bin/suricata -i igb0 -D -c /usr/local/etc/suricata/suricata_63733_igb0/suricata.yaml --pidfi
99499  -  Rs       0:34.61 /usr/local/bin/suricata -i igb0 -D -c /usr/local/etc/suricata/suricata_63733_igb0/suricata.yaml --pidfi
41251  0  S+       0:00.00 grep suricata

SteveITS

@wrightsonm said in Suricata log rotation bug:

gui thinks the interface is down

That was just found and solved this week.

wrightsonm

@steveits on the latest version (v12) there is a UI bug that can cause suricata to run 2 instances of the application. Its taken me a while to spot the trend.

Steps to reproduce.

Stop suricata on the interfaces
confirm no instances are running - ps -ax | grep suricata
click the start button in the GUI
Press F5 and refresh the page
This will start another instance of suricata

bmeeks

@wrightsonm said in Suricata log rotation bug:

@steveits on the latest version (v12) there is a UI bug that can cause suricata to run 2 instances of the application. Its taken me a while to spot the trend.

Steps to reproduce.

Stop suricata on the interfaces

confirm no instances are running - ps -ax | grep suricata

click the start button in the GUI

Press F5 and refresh the page

This will start another instance of suricata

Pressing F5 and refreshing the page will submit the same form variables again to the code. That can easily result in dual-starting Suricata if the first instance has not fully finished starting up (and created its PID file).

The short version of this is -- DON'T DO THAT! The GUI page is dynamic, and will refresh itself automatically to indicate when Suricata starts. Do not "refresh" that page if the last action you did was start and interface.

wrightsonm

@bmeeks I would say that your suggestion isn't particularly good design practice.
There is already ajax being used on this page - see check_status() function.
The start / stop buttons should really get submitted as an ajax request that then updates the icons on the page onc completion rather than submitting the entire page and causing the described problem.

Secondly, the issue that the php page is at risk of a type of replay attack that is triggered when refreshing the page, that then causes multiple services to be started is less than ideal. The main php script should really take advantage of the logic contained within $_POST['check'] and use that to determine whether or not to start a new process to prevent the possibility of multiple services being started - i.e. add validation.

bmeeks

@wrightsonm said in Suricata log rotation bug:

@bmeeks I would say that your suggestion isn't particularly good design practice.
There is already ajax being used on this page - see check_status() function.
The start / stop buttons should really get submitted as an ajax request that then updates the icons on the page onc completion rather than submitting the entire page and causing the described problem.

Secondly, the issue that the php page is at risk of a type of replay attack that is triggered when refreshing the page, that then causes multiple services to be started is less than ideal. The main php script should really take advantage of the logic contained within $_POST['check'] and use that to determine whether or not to start a new process to prevent the possibility of multiple services being started - i.e. add validation.

The code tries, as best it can within the limitations of PHP, to see if another instance is running before starting an instance. The problem is that the only way the code really has to determine if another process is running for the interface is to look for the PID file created in /var/run. Each interface has a randomly generated UUID associated with it at interface creation. That UUID is used to name the PID file, so the code can tell which interfaces have Suricata running, and be able to control them individually. However, it takes some amount of time for Suricata to start and create that PID file. If the user quickly refreshes back-to-back, there is no PID file yet from the first process, and so not seeing an existing PID, it assumes there is no existing process and thus starts a new process. Then you have two.

The Ajax section was added a few years ago to improve GUI responsiveness. It works by actually creating a new background PHP process to start the Suricata daemon. The Ajax loop then checks for the existence of the aforementioned PID file to determine whether Suricata is running or not. Prior to that, the GUI just sat there and "spun" with the web page totally unresponsive until the PHP function calls returned. That was not ideal, either.

If you have a better solution, please feel free to submit a Pull Request here: https://github.com/pfsense/FreeBSD-ports/tree/devel/security/pfSense-pkg-suricata. User contributions are welcomed.