Bug 12812 - Something is off with Suricata
Summary: Something is off with Suricata
Status: CLOSED FIXED
Alias: None
Product: IPFire
Classification: Unclassified
Component: --- (show other bugs)
Version: 2
Hardware: unspecified Unspecified
: - Unknown - Security
Assignee: Stefan Schantl
QA Contact: Peter Müller
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2022-03-21 12:05 UTC by Peter Müller
Modified: 2022-06-13 14:27 UTC (History)
3 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Peter Müller 2022-03-21 12:05:05 UTC
As already mentioned in https://lists.ipfire.org/pipermail/development/2022-March/012758.html, something seems to be wrong with the IPS in Core Update 165 (testing).

A few minutes ago, I experienced the same behaviour described in the mail linked above again: SSH connections to IPFire itself mostly timed out, and the web proxy was opening new connections tardily, if any.

Suricata is up and running on that machine, but since the reboot (which took place at approximately 3:15 AM), it has only logged one hit:

03/21/2022-03:15:31.561692  [Drop] [**] [1:2009582:3] ET SCAN NMAP -sS window 1024 [**] [Classification: Attempted Information Leak] [Priority: 2] {TCP} 45.x.x.x:46974 -> 85.x.x.x:4217
03/21/2022-09:27:03.016337  [Drop] [**] [1:2002995:10] ET SCAN Rapid IMAPS Connections - Possible Brute Force Attack [**] [Classification: Misc activity] [Priority: 3] {TCP} 10.x.x.x:56726 -> 10.x.x.x:993

This is too good to be true. While I did not yet found out what is happening here, something is definitely off with Suricata, apparently causing at least traffic on RED not to be scanned at all (otherwise, I'd have IPS hits several times per minute), plus presumably causing trouble with connections involving IPFire itself.

More information will be added as soon as I have them. At the moment, I am a bit lost and do not know where to look first.
Comment 1 Michael Tremer 2022-03-21 15:50:18 UTC
(In reply to Peter Müller from comment #0)
> This is too good to be true. While I did not yet found out what is happening
> here, something is definitely off with Suricata, apparently causing at least
> traffic on RED not to be scanned at all (otherwise, I'd have IPS hits
> several times per minute), plus presumably causing trouble with connections
> involving IPFire itself.
> 
> More information will be added as soon as I have them. At the moment, I am a
> bit lost and do not know where to look first.

How do you know this is happening?

Does a restart of suricata bring it back to life? Can you see a worker crashing?
Comment 2 Peter Müller 2022-03-21 15:57:22 UTC
> Does a restart of suricata bring it back to life?

Yes. Stopping and restarting the IPS via the GUI solves the problem
until the next reboot.

> Can you see a worker crashing?

No. In /var/log/messages, these lines appear:

Mar 21 03:17:37 maverick suricata: This is Suricata version 5.0.8 RELEASE running in SYSTEM mode
Mar 21 03:17:37 maverick suricata: CPUs/cores online: 4
Mar 21 03:17:37 maverick suricata: HTTP memcap: 268435456
Mar 21 03:17:37 maverick suricata: Enabling fail-open on queue
Mar 21 03:17:37 maverick suricata: NFQ running in REPEAT mode with mark 2147483648/2147483648
Mar 21 03:17:38 maverick suricata: dropped the caps for main thread
Mar 21 03:17:38 maverick suricata: fast output device (regular) initialized: fast.log
Mar 21 03:17:38 maverick suricata: Packets will start being processed before signatures are active.
Mar 21 03:17:38 maverick suricata: binding this thread 0 to queue '0'
Mar 21 03:17:38 maverick suricata: setting queue length to 4096
Mar 21 03:17:38 maverick suricata: setting nfnl bufsize to 6144000
Mar 21 03:17:38 maverick suricata: NFQ running in 'workers' runmode, will not use mutex.
Mar 21 03:17:38 maverick suricata: fail-open mode should be set on queue
Mar 21 03:17:38 maverick suricata: binding this thread 1 to queue '1'
Mar 21 03:17:38 maverick suricata: setting queue length to 4096
Mar 21 03:17:38 maverick suricata: setting nfnl bufsize to 6144000
Mar 21 03:17:38 maverick suricata: NFQ running in 'workers' runmode, will not use mutex.
Mar 21 03:17:38 maverick suricata: fail-open mode should be set on queue
Mar 21 03:17:38 maverick suricata: binding this thread 2 to queue '2'
Mar 21 03:17:38 maverick suricata: setting queue length to 4096
Mar 21 03:17:38 maverick suricata: setting nfnl bufsize to 6144000
Mar 21 03:17:38 maverick suricata: NFQ running in 'workers' runmode, will not use mutex.
Mar 21 03:17:38 maverick suricata: fail-open mode should be set on queue
Mar 21 03:17:38 maverick suricata: all 3 packet processing threads, 2 management threads initialized, engine started.
Mar 21 03:17:38 maverick suricata: rule reload starting
Mar 21 03:17:38 maverick suricata: Including configuration file /var/ipfire/suricata/suricata-homenet.yaml.
Mar 21 03:17:38 maverick suricata: Including configuration file /var/ipfire/suricata/suricata-dns-servers.yaml.
Mar 21 03:17:38 maverick suricata: Including configuration file /var/ipfire/suricata/suricata-http-ports.yaml.
Mar 21 03:17:38 maverick suricata: Including configuration file /var/ipfire/suricata/suricata-used-providers.yaml.
Mar 21 03:17:38 maverick suricata: Including configuration file /var/ipfire/suricata/suricata-emerging-used-rulefiles.yaml.
Mar 21 03:17:38 maverick suricata: Including configuration file /var/ipfire/suricata/suricata-default-rules.yaml.
Mar 21 03:18:01 maverick suricata: [ERRCODE: SC_WARN_JA3_DISABLED(309)] - ja3 support is not enabled
Mar 21 03:18:01 maverick suricata: [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - error parsing signature "alert tls $HOME_NET any -> $EXTERNAL_NET any (msg:"ET JA3 Hash - Suspected Cobalt Strike Malleable C2 M1 (set)"; flow:established,to_server; ja3.hash; content:"eb88d0b3e1961a0562f006e5ce2a0b87"; ja3.string; content:"771,49192-49191-49172-49171"; flowbits:set,ET.cobaltstrike.ja3; flowbits:noalert; classtype:command-and-control; sid:2028831; rev:1; metadata:affected_product Windows_XP_Vista_7_8_10_Server_32_64_Bit, attack_target Client_Endpoint, created_at 2019_10_15, deployment Perimeter, former_category JA3, malware_family Cobalt_Strike, signature_severity Major, updated_at 2019_10_15, mitre_tactic_id TA0011, mitre_tactic_name Command_And_Control, mitre_technique_id T1001, mitre_technique_name Data_Obfuscation;)" from file /var/lib/suricata/emerging-ja3.rules at line 41
Mar 21 03:18:01 maverick suricata: [ERRCODE: SC_WARN_JA3_DISABLED(309)] - ja3(s) support is not enabled
Mar 21 03:18:01 maverick suricata: [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - error parsing signature "drop tls $EXTERNAL_NET any -> $HOME_NET any (msg:"ET JA3 HASH - Possible RustyBuer Server Response"; flowbits:isset,ET.rustybuer; ja3s.hash; content:"f6dfdd25d1522e4e1c7cd09bd37ce619"; reference:md5,ea98a9d6ca6f5b2a0820303a1d327593; classtype:bad-unknown; sid:2032960; rev:1; metadata:attack_target Client_Endpoint, created_at 2021_05_13, deployment Perimeter, former_category JA3, malware_family RustyBuer, performance_impact Low, signature_severity Major, updated_at 2021_05_13;)" from file /var/lib/suricata/emerging-ja3.rules at line 289
Mar 21 03:18:03 maverick suricata: 34 rule files processed. 21167 rules successfully loaded, 129 rules failed
Mar 21 03:18:03 maverick suricata: Threshold config parsed: 0 rule(s) found
Mar 21 03:18:04 maverick suricata: 21167 signatures processed. 189 are IP-only rules, 3312 are inspecting packet payload, 17629 inspect application layer, 0 are decoder event only
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'et.JavaArchiveOrClass' is checked but not set. Checked in 2017768 and 11 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.http.javaclient' is checked but not set. Checked in 2017181 and 15 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.pdf.in.http' is checked but not set. Checked in 2017150 and 4 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'et.IE7.NoRef.NoCookie' is checked but not set. Checked in 2023671 and 9 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.gocd.auth' is checked but not set. Checked in 2034333 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'dcerpc.rpcnetlogon' is checked but not set. Checked in 2030870 and 6 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'is_proto_irc' is checked but not set. Checked in 2002029 and 4 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.http.javaclient.vulnerable' is checked but not set. Checked in 2013036 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.ELFDownload' is checked but not set. Checked in 2019896 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.MSSQL' is checked but not set. Checked in 2020569 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.wininet.UA' is checked but not set. Checked in 2021312 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'et.MS.XMLHTTP.ip.request' is checked but not set. Checked in 2022050 and 1 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'et.MS.XMLHTTP.no.exe.request' is checked but not set. Checked in 2022053 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'et.MCOFF' is checked but not set. Checked in 2019837 and 1 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'et.MS.WinHttpRequest.no.exe.request' is checked but not set. Checked in 2022653 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.armwget' is checked but not set. Checked in 2024241 and 1 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.smb.binary' is checked but not set. Checked in 2027402 and 4 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.Socks5.OnionReq' is checked but not set. Checked in 2027704 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.autoit.ua' is checked but not set. Checked in 2019165 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'min.gethttp' is checked but not set. Checked in 2023711 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'et.http.PK' is checked but not set. Checked in 2019835 and 3 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'HTTP.UncompressedFlash' is checked but not set. Checked in 2016396 and 3 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'http.dottedquadhost' is checked but not set. Checked in 2021076 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.bit.do.shortener' is checked but not set. Checked in 2029550 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.PS.Download' is checked but not set. Checked in 2032169 and 3 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'ET.JS.Obfus.Func' is checked but not set. Checked in 2017247 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'et.WinHttpRequest' is checked but not set. Checked in 2019823 and 0 other sigs
Mar 21 03:18:04 maverick suricata: [ERRCODE: SC_WARN_FLOWBIT(306)] - flowbit 'exe.no.referer' is checked but not set. Checked in 2020500 and 0 other sigs
Mar 21 03:20:33 maverick suricata: cleaning up signature grouping structure... complete
Mar 21 03:20:33 maverick suricata: rule reload complete
Mar 21 03:20:33 maverick suricata: Signature(s) loaded, Detect thread(s) activated.

They look pretty much normal, and nothing else is logged afterwards.
Comment 3 Michael Tremer 2022-03-21 15:59:18 UTC
Yes, this looks absolutely not suspicious to me either.
Comment 4 Stefan Schantl 2022-03-21 16:52:50 UTC
Hello Peter,

thanks for reporting this issue.

When looking on your provided log output, I can see, that you have enabled one ore more JA3 rules - Sadly currently we have no support for JA3 rules see (#12536).

The other warnings looks like "normal" to me. They appears because of some flowbits which are set by various rules and also are displayed and logged on my system since a long time.

So they are uggly, but should not have such a deep impact, as internet and various services had worked fine in the past.

So I'm afraid, I can't reproduce you issue - please feel free to post additional informations to keep track and help to fix this issue.

Thanks in advance,

-Stefan
Comment 5 Michael Tremer 2022-03-21 18:53:01 UTC
(In reply to Stefan Schantl from comment #4)
> Hello Peter,
> 
> thanks for reporting this issue.
> 
> When looking on your provided log output, I can see, that you have enabled
> one ore more JA3 rules - Sadly currently we have no support for JA3 rules
> see (#12536).

They are enabled in most rulesets by default and I do not think it is worth to manually disable them.
Comment 6 Peter Müller 2022-03-22 07:37:40 UTC
Hello Stefan, hello Michael,

indeed, the warnings and JA3 errors are not new here, either, and do not seem to be related to the problem.

Today, this behaviour did not occur again for whatever reason. I will continue to investigate and get back later.

Thanks, and best regards,
Peter Müller
Comment 7 Charles Brown 2022-03-22 14:32:26 UTC
I too have seen a disturbingly long period with no events triggered for several hours.  I believe it started after I had made a series of changes – enabling / disabling individual sids.  Looking at the logs it appeared that oinkmaster finished okay and suricata successfully reloaded the rules.  I rebooted and things started working normally.
I’m running a bit of a hack – c164 with Stefan’s patches for Talos Subscribed/Registered rulesets manually applied.  So I would guess this issue is not something new with c165.
Comment 8 Charles Brown 2022-03-22 14:42:10 UTC
(In reply to Charles Brown from comment #7)
> I too have seen a disturbingly long period with no events triggered for
> several hours.  I believe it started after I had made a series of changes –
> enabling / disabling individual sids.  Looking at the logs it appeared that
> oinkmaster finished okay and suricata successfully reloaded the rules.  I
> rebooted and things started working normally.
> I’m running a bit of a hack – c164 with Stefan’s patches for Talos
> Subscribed/Registered rulesets manually applied.  So I would guess this
> issue is not something new with c165.

Over the past few days I have made several tweaks enabling/disabling sids, and have not had the issue reoccur.  It seems that occasionally/rarely suricata seems to not be working properly after it appears to successfully reload the rules.
Comment 9 Peter Müller 2022-03-23 09:28:41 UTC
Ever since I changed two firewall rules that made problems with Core Update 165 (see: https://bugzilla.ipfire.org/show_bug.cgi?id=12809#c1), Suricata appears to work normal here - i. e. logging several hits per minute on RED, and manually triggered scans are also detected properly.
Comment 10 Peter Müller 2022-03-23 10:55:17 UTC
Stefan just confirmed to me that the root cause of this bug on my testing machine is #12809 indeed, and he will submit a patch for fixing that later.

Therefore, if nobody is against it, I would like to close this as being a duplicate.
Comment 11 Michael Tremer 2022-03-23 10:57:01 UTC
(In reply to Peter Müller from comment #10)
> Stefan just confirmed to me that the root cause of this bug on my testing
> machine is #12809 indeed, and he will submit a patch for fixing that later.

I don't see how those two things are connected. Could you please explain?
Comment 12 Charles Brown 2022-03-27 14:54:37 UTC
I just had another recurrence of the issue where after making a change -- simply disabling one sid, suricata stopped detecting events.  I have rules that regularly fire within minutes.
I tried stopping IPS by un-clicking "Enable Intrusion Prevention System" and saving. Then re-enabled and saved.  Suricata restarted, but that did not fix the issue. 
Then tried by killing suricata with /etc/init.d/suricata  stop; Then restarted it by un-clicking "Enable Intrusion Prevention System" and saving. Then re-enabled via the WUI.  Suricata restarted, but also did not fix the issue.
Then I rebooted ipfire, that also failed to get suricata detecting the events.
Finally I tried disabling one of my two ruleset providers (using both ET Community and Talos Subscipted).  I disabled / un-checked the Talos rules as a provider, waited for suricata to reload and then the ET rules started firing.  I then re-enabled the Talos rules and things continued working normally.
Comment 13 Charles Brown 2022-03-27 14:58:20 UTC
(In reply to Charles Brown from comment #12)
> I just had another recurrence of the issue where after making a change --
> simply disabling one sid, suricata stopped detecting events.  I have rules
> that regularly fire within minutes.
> I tried stopping IPS by un-clicking "Enable Intrusion Prevention System" and
> saving. Then re-enabled and saved.  Suricata restarted, but that did not fix
> the issue. 
> Then tried by killing suricata with /etc/init.d/suricata  stop; Then
> restarted it by un-clicking "Enable Intrusion Prevention System" and saving.
> Then re-enabled via the WUI.  Suricata restarted, but also did not fix the
> issue.
> Then I rebooted ipfire, that also failed to get suricata detecting the
> events.
> Finally I tried disabling one of my two ruleset providers (using both ET
> Community and Talos Subscipted).  I disabled / un-checked the Talos rules as
> a provider, waited for suricata to reload and then the ET rules started
> firing.  I then re-enabled the Talos rules and things continued working
> normally.

Well, almost normally -- prior to c164 there was a Talos rule that had been firing a few times daily. I have verified by looking at the sid in the corresponding  /var/lib/suricata rule file that this rule is set to drop, but I have not seen it fire since upgrading to c164.
Comment 14 Charles Brown 2022-03-27 15:16:23 UTC
Since this randomly / infrequently occurs in Core Update 164, I would not call this blocking for release of Core Update 165.
Besides, when you detect the situation, you can fix it by doing enough magical incantations, religious rituals, ,swinging a dead chicken in a graveyard at midnight,or perhaps random banging on the keyboard :-)

-Charles
Comment 15 Peter Müller 2022-05-01 08:17:40 UTC
Today, I observed exactly the same behaviour again (running Core Update 167): Network connections would establish slow if not running into time-outs, while Suricata logging no alerts on RED since IPFire booted.

Let's hope the Suricata update in Core 168 will come with a cure...
Comment 16 Peter Müller 2022-06-13 14:27:56 UTC
As I was unable to reproduce this problem(s) ever since Core Update 168 (which came with a Suricata update), I consider this fixed by now. Please reopen, if necessary.

https://blog.ipfire.org/post/ipfire-2-27-core-update-168-released