Bug #13839
closed
Suricata version updates take a long time
100%
Description
Recently I've noticed that updating Suricata versions takes a very long time, every time. After an update to the latest pfSense dev build, I saw these in the system logs - notice it took 10 minutes on a single step (logs reversed):
Jan 5 14:43:13 pkg-static 43609 pfSense-pkg-suricata upgraded: 6.0.8_4 -> 6.0.8_5 Jan 5 14:40:16 kernel done. Jan 5 14:40:16 php 70799 //etc/rc.packages: Successfully installed package: suricata. Jan 5 14:40:16 kernel done. Jan 5 14:40:16 php 70799 //etc/rc.packages: Configuration Change: (system): Overwrote previous installation of suricata. Jan 5 14:40:16 php 70799 [Suricata] Package post-installation tasks completed. Jan 5 14:40:16 php 70799 //etc/rc.packages: Configuration Change: (system): Suricata pkg v6.0.8_5: post-install configuration saved. Jan 5 14:40:16 php 70799 [Suricata] Finished rebuilding installation from saved settings. Jan 5 14:40:15 php 70799 //etc/rc.packages: Configuration Change: (system): Installed cron job for /usr/bin/nice -n20 /usr/local/bin/php-cgi -f /usr/local/pkg/suricata/suricata_check_for_rule_updates.php Jan 5 14:40:15 php 70799 //etc/rc.packages: Configuration Change: (system): Installed cron job for /usr/bin/nice -n20 /sbin/pfctl -q -t snort2c -T expire 3600 Jan 5 14:40:15 kernel done. Jan 5 14:40:15 php 70799 //etc/rc.packages: Configuration Change: (system): Installed cron job for /usr/bin/nice -n20 /usr/local/bin/php-cgi -f /usr/local/pkg/suricata/suricata_check_cron_misc.inc Jan 5 14:40:15 php 70799 [Suricata] Building new sid-msg.map file for ISP1... Jan 5 14:40:13 php 70799 [Suricata] Updating rules configuration for: ISP1 ... Jan 5 14:40:13 php 70799 [Suricata] The Rules update has finished. Jan 5 14:40:13 php 70799 [Suricata] Removed 0 obsoleted rules category files. Jan 5 14:40:13 kernel done. Jan 5 14:40:13 php 70799 [Suricata] Hide Deprecated Rules is enabled. Removing obsoleted rules categories. Jan 5 14:40:13 php 70799 [Suricata] Extra ETNetera rules were updated... Jan 5 14:40:13 kernel done. Jan 5 14:40:13 php 70799 [Suricata] Extra ETNetera rules file update downloaded successfully. Jan 5 14:40:03 kernel Extra MalSilo rules were updated. Jan 5 14:40:03 php 70799 [Suricata] Extra MalSilo rules were updated... Jan 5 14:40:03 kernel done. Jan 5 14:40:03 php 70799 [Suricata] Extra MalSilo rules file update downloaded successfully. Jan 5 14:40:03 kernel done. Jan 5 14:29:51 php 70799 [Suricata] ABUSE.ch SSL Blacklist rules were updated... Jan 5 14:29:51 kernel done. Jan 5 14:29:51 php 70799 [Suricata] ABUSE.ch SSL Blacklist rules file update downloaded successfully. Jan 5 14:19:40 kernel Feodo Tracker Botnet C2 IP rules were updated. Jan 5 14:19:40 php 70799 [Suricata] Feodo Tracker Botnet C2 IP rules were updated... Jan 5 14:19:40 kernel done. Jan 5 14:19:40 php 70799 [Suricata] Feodo Tracker Botnet C2 IP rules file update downloaded successfully. Jan 5 14:19:38 kernel done. Jan 5 14:19:38 php 70799 [Suricata] Snort GPLv2 Community Rules file update downloaded successfully. Jan 5 14:19:36 kernel done. Jan 5 14:19:36 php 70799 [Suricata] There is a new set of Snort GPLv2 Community Rules posted. Downloading community-rules.tar.gz... Jan 5 14:19:35 kernel done. Jan 5 14:19:35 php 70799 [Suricata] Emerging Threats Open rules file update downloaded successfully. Jan 5 14:19:34 kernel done. Jan 5 14:19:34 php 70799 [Suricata] There is a new set of Emerging Threats Open rules posted. Downloading emerging.rules.tar.gz... Jan 5 14:19:26 kernel done. Jan 5 14:19:26 php 70799 [Suricata] Downloading and updating configured rule types. Jan 5 14:19:26 php 70799 [Suricata] Configuration version is current. Jan 5 14:19:26 php 70799 [Suricata] Checking configuration settings version... Jan 5 14:19:26 kernel Saved settings detected... Jan 5 14:19:26 php 70799 [Suricata] Saved settings detected... rebuilding installation with saved settings. Jan 5 14:19:25 php 70799 //etc/rc.packages: Configuration Change: (system): Installed cron job for /usr/bin/nice -n20 /usr/local/bin/php-cgi -f /usr/local/pkg/suricata/suricata_geoipupdate.php Jan 5 14:19:25 php 70799 [Suricata] Cleaning up temp files after GeoLite2-Country database update. Jan 5 14:19:25 php 70799 [Suricata] GeoLite2-Country database update completed. Jan 5 14:19:25 php 70799 [Suricata] Moving new database to /usr/local/share/suricata/GeoLite2/GeoLite2-Country.mmdb... Jan 5 14:19:25 php 70799 [Suricata] Extracting new GeoLite2-Country database from the archive... Jan 5 14:19:25 php 70799 [Suricata] New GeoLite2-Country IP database gzip archive successfully downloaded. Jan 5 14:19:24 php 70799 [Suricata] Downloading new GeoLite2-Country IP database... Jan 5 14:19:24 php 70799 [Suricata] A new GeoLite2-Country IP database is available. Jan 5 14:19:23 php 70799 [Suricata] Checking for updated MaxMind GeoLite2 IP database file... Jan 5 14:19:23 php 70799 [Suricata] Installing free GeoLite2 country IP database file in /usr/local/share/suricata/GeoLite2/... Jan 5 14:19:23 php 70799 //etc/rc.packages: Configuration Change: (system): Intermediate config write during package install for suricata. Jan 5 14:19:23 php 70799 //etc/rc.packages: Beginning package installation for suricata . Jan 5 14:19:22 php 48950 [Suricata] Flushing all blocked hosts from <snort2c> table due to package removal... Jan 5 14:19:22 php 48950 /etc/rc.packages: Configuration Change: (system): Suricata pkg removed Dashboard Alerts widget. Jan 5 14:19:22 php 48950 /etc/rc.packages: Configuration Change: (system): Removed cron job for suricata_geoipupdate.php Jan 5 14:19:22 php 48950 /etc/rc.packages: Configuration Change: (system): Removed cron job for snort2c Jan 5 14:19:22 php 48950 /etc/rc.packages: Configuration Change: (system): Removed cron job for suricata_check_cron_misc.inc Jan 5 14:19:22 php 48950 /etc/rc.packages: Configuration Change: (system): Removed cron job for suricata_check_for_rule_updates.php Jan 5 14:19:20 php 48950 [Suricata] Suricata package uninstall in progress...
Downloading the files directly on a browser finished immediately so I don't think it's a bandwidth issue:
https://sslbl.abuse.ch/blacklist/sslblacklist_tls_cert.tar.gz
https://feodotracker.abuse.ch/downloads/feodotracker.tar.gz
Updated by Bill Meeks almost 2 years ago
I have also noticed some overall package installation issues with both Suricata and Snort over the last couple of months or so as I've tested my PHP 8.1 fixes. Originally I saw both packages hanging up during the post-install tasks when upgrading or reinstalling with an existing configuration in place. Attributed that to the issues with pkg and launching a daemon as part of the install. That issue did seem to resolve itself last week if I recall (or maybe early this week). But yesterday, when uninstalling/reinstalling Suricata I noticed the hang condition appeared to have returned. Wondered if it was a regression related to the latest fixes around upgrading older pfSense installs to the current snapshot version. But perhaps it is something else as you have documented here.
The time lapse in the log message timestamps is extremely puzzling. Did you do anything in between 14:20 and 14:29 that could have modified Suricata? And again, there is a long lapse of time and then another rule package downloads at 14:40. This is the entire sequence:
Jan 5 14:40:13 php 70799 [Suricata] Extra ETNetera rules were updated... Jan 5 14:40:13 kernel done. Jan 5 14:40:13 php 70799 [Suricata] Extra ETNetera rules file update downloaded successfully. Jan 5 14:40:03 kernel Extra MalSilo rules were updated. Jan 5 14:40:03 php 70799 [Suricata] Extra MalSilo rules were updated... Jan 5 14:40:03 kernel done. Jan 5 14:40:03 php 70799 [Suricata] Extra MalSilo rules file update downloaded successfully. Jan 5 14:40:03 kernel done. Jan 5 14:29:51 php 70799 [Suricata] ABUSE.ch SSL Blacklist rules were updated... Jan 5 14:29:51 kernel done. Jan 5 14:29:51 php 70799 [Suricata] ABUSE.ch SSL Blacklist rules file update downloaded successfully. Jan 5 14:19:40 kernel Feodo Tracker Botnet C2 IP rules were updated. Jan 5 14:19:40 php 70799 [Suricata] Feodo Tracker Botnet C2 IP rules were updated... Jan 5 14:19:40 kernel done. Jan 5 14:19:40 php 70799 [Suricata] Feodo Tracker Botnet C2 IP rules file update downloaded successfully. Jan 5 14:19:38 kernel done. Jan 5 14:19:38 php 70799 [Suricata] Snort GPLv2 Community Rules file update downloaded successfully. Jan 5 14:19:36 kernel done. Jan 5 14:19:36 php 70799 [Suricata] There is a new set of Snort GPLv2 Community Rules posted. Downloading community-rules.tar.gz... Jan 5 14:19:35 kernel done. Jan 5 14:19:35 php 70799 [Suricata] Emerging Threats Open rules file update downloaded successfully. Jan 5 14:19:34 kernel done. Jan 5 14:19:34 php 70799 [Suricata] There is a new set of Emerging Threats Open rules posted. Downloading emerging.rules.tar.gz... Jan 5 14:19:26 kernel done. Jan 5 14:19:26 php 70799 [Suricata] Downloading and updating configured rule types.
Those 10-minute pauses between 14:19, 14:29, and then 14:40 are very puzzling unless some manual change to enabled rules was being made. I will test and try to reproduce with the two built-in rules (Feodotracker and SSL BL), but I don't have the complete URL of those extra rules that appear to enabled.
Are you confident the box was stuck trying to download those files for the full 10 minutes between each of the log entries between the Feodo Tracker rules and the ABUSE.ch SSL rules?
Updated by Marcos M almost 2 years ago
I certainly did not take any action during it that would have affected it. I did ommit some unrelated lines like me logging in via SSH to figure out what was happening. These particular logs are after a pfSense snapshot update, but it's happened even just updating the rules from the suricata rules update page.
The URL for it is:
https://malsilo.gitlab.io/feeds/dumps/malsilo.rules.tar.gz
Perhaps a clue, I currently have MD5 checked on it. Maybe the issue lies somewhere there?
Updated by Bill Meeks almost 2 years ago
Marcos M wrote in #note-3:
I certainly did not take any action during it that would have affected it. I did ommit some unrelated lines like me logging in via SSH to figure out what was happening. These particular logs are after a pfSense snapshot update, but it's happened even just updating the rules from the suricata rules update page.
The URL for it is:
https://malsilo.gitlab.io/feeds/dumps/malsilo.rules.tar.gzPerhaps a clue, I currently have MD5 checked on it. Maybe the issue lies somewhere there?
I believe it is related to the MD5 option being checked. And I do see a new line of PHP code added to suricata_check_for_rule_updates.php file 6 years ago. That extra line implements a 10-minute timeout for broken connections, and it is used to prevent curl() from waiting forever for a download. Something about the md5 download process seems to trigger that wait. I am continuing to investigate.
This also seems to only have the 10-minute pause during the rules update DURING a package install when an existing configuration is present. Running a check for updated rules via the option on the UPDATES tab is very fast. And the really puzzling part is that option runs the exact same code as the package install does -- namely both operations call and execute the code within /usr/local/pkg/suricata/suricata_check_for_rule_updates.php. The only difference in the two is the former will execute under pkg while it is installing the package. Wonder if that is a clue ???
Updated by Bill Meeks almost 2 years ago
After some digging around, I am pretty sure I found the problem here. It is related to HTTP/2 support in cURL. I can only assume something changed in an underlying library with the new FreeBSD version (or PHP 8.1 itself). Adding two additional CURL_SETOPT values related to HTTP/2 support in the cURL function for downloading files fixed the stall issue. A pull request will be posted after more testing to verify the condition is truly fixed.
Updated by Jim Pingle almost 2 years ago
To fix some issues in Dynamic DNS where it didn't want to close connections (it hung pretty much indefinitely) we ended up having to set CURLOPT_FORBID_REUSE on all the cURL calls: https://github.com/pfsense/pfsense/commit/02d6ca03965777ab95da05c7ae526aa75d2ddc2a -- might need to do something similar here.
curl_close() does nothing on PHP 8, so you may as well remove all references to that as well.
Updated by Bill Meeks almost 2 years ago
The pull request to correct this issue has been submitted against the snapshots DEVEL branch here: https://github.com/pfsense/FreeBSD-ports/pull/1224.
Once the PR is merged, this issue can be marked resolved.
Updated by Bill Meeks almost 2 years ago
Jim Pingle wrote in #note-6:
To fix some issues in Dynamic DNS where it didn't want to close connections (it hung pretty much indefinitely) we ended up having to set CURLOPT_FORBID_REUSE on all the cURL calls: https://github.com/pfsense/pfsense/commit/02d6ca03965777ab95da05c7ae526aa75d2ddc2a -- might need to do something similar here.
curl_close()does nothing on PHP 8, so you may as well remove all references to that as well.
Thanks for the tip. I appended that change to the pull request and also applied the same changes for cURL and PHP 8.1 to the GeoIP2 database update function.