enhance: parse more data out of postfix log lines (#1104)

* enhance: parse more data out of postfix rejection commands to allow more scenarios

* enhance: fix so parser supports just basic Service unavailable

* enhance: rename key to codes instead of code since there could be 2

* enhance: Add new scenarios based on helo and relay rejections to create a more specific filter, add tests and update parser to set a meta attribute for reason

* enhance: Add to collections and update index manually cause of fork

.tests/postfix-helo/config.yaml

@@ -0,0 +1,11 @@
+parsers:
+- crowdsecurity/postfix-logs
+- crowdsecurity/syslog-logs
+- crowdsecurity/dateparse-enrich
+scenarios:
+- ./scenarios/crowdsecurity/postfix-helo-rejected.yaml
+postoverflows:
+- ""
+log_file: postfix-spam.log
+log_type: syslog
+ignore_parsers: true

.tests/postfix-helo/postfix-spam.log

@@ -0,0 +1,2 @@
+2024-08-29T01:08:59.764590+00:00 machine postfix/smtpd[1938053]: NOQUEUE: reject: RCPT from unknown[192.168.1.1]: 504 5.5.2 <WIN-9QL4SDRB93L>: Helo command rejected: need fully-qualifiedhostname; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<WIN-9QL4SDRB93L>
+2024-08-29T01:09:08.989498+00:00 machine postfix/smtpd[1938053]: NOQUEUE: reject: RCPT from unknown[192.168.1.1]: 504 5.5.2 <WIN-9QL4SDRB93L>: Helo command rejected: need fully-qualifiedhostname; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<WIN-9QL4SDRB93L>

.tests/postfix-helo/scenario.assert

@@ -0,0 +1,29 @@
+len(results) == 1
+"192.168.1.1" in results[0].Overflow.GetSources()
+results[0].Overflow.Sources["192.168.1.1"].IP == "192.168.1.1"
+results[0].Overflow.Sources["192.168.1.1"].Range == ""
+results[0].Overflow.Sources["192.168.1.1"].GetScope() == "Ip"
+results[0].Overflow.Sources["192.168.1.1"].GetValue() == "192.168.1.1"
+results[0].Overflow.Alert.Events[0].GetMeta("action") == "reject"
+results[0].Overflow.Alert.Events[0].GetMeta("datasource_path") == "postfix-spam.log"
+results[0].Overflow.Alert.Events[0].GetMeta("datasource_type") == "file"
+results[0].Overflow.Alert.Events[0].GetMeta("log_type") == "postfix"
+results[0].Overflow.Alert.Events[0].GetMeta("machine") == "machine"
+results[0].Overflow.Alert.Events[0].GetMeta("reason") == "Helo command rejected: need fully-qualifiedhostname"
+results[0].Overflow.Alert.Events[0].GetMeta("service") == "postfix"
+results[0].Overflow.Alert.Events[0].GetMeta("source_hostname") == "unknown"
+results[0].Overflow.Alert.Events[0].GetMeta("source_ip") == "192.168.1.1"
+results[0].Overflow.Alert.Events[0].GetMeta("timestamp") == "2024-08-29T01:08:59.76459Z"
+results[0].Overflow.Alert.Events[1].GetMeta("action") == "reject"
+results[0].Overflow.Alert.Events[1].GetMeta("datasource_path") == "postfix-spam.log"
+results[0].Overflow.Alert.Events[1].GetMeta("datasource_type") == "file"
+results[0].Overflow.Alert.Events[1].GetMeta("log_type") == "postfix"
+results[0].Overflow.Alert.Events[1].GetMeta("machine") == "machine"
+results[0].Overflow.Alert.Events[1].GetMeta("reason") == "Helo command rejected: need fully-qualifiedhostname"
+results[0].Overflow.Alert.Events[1].GetMeta("service") == "postfix"
+results[0].Overflow.Alert.Events[1].GetMeta("source_hostname") == "unknown"
+results[0].Overflow.Alert.Events[1].GetMeta("source_ip") == "192.168.1.1"
+results[0].Overflow.Alert.Events[1].GetMeta("timestamp") == "2024-08-29T01:09:08.989498Z"
+results[0].Overflow.Alert.GetScenario() == "crowdsecurity/postfix-helo-rejected"
+results[0].Overflow.Alert.Remediation == true
+results[0].Overflow.Alert.GetEventsCount() == 2

.tests/postfix-logs/postfix-logs.log

@@ -1,3 +1,5 @@
-May 11 04:02:36 host1 postfix/smtpd[26897]: warning: unknown[1.2.3.4]: SASL LOGIN authentication failed: authentication failure
-May 11 04:02:37 host1 postfix/smtpd[26897]: NOQUEUE: reject: RCPT from unknown[1.2.3.4]: 554 5.7.1 Service unavailable
-
+May 11 04:02:36 host1 postfix/smtpd[26897]: warning: unknown[192.168.1.1]: SASL LOGIN authentication failed: authentication failure
+May 11 04:02:37 host1 postfix/smtpd[26897]: NOQUEUE: reject: RCPT from unknown[192.168.1.1]: 554 5.7.1 Service unavailable
+2024-08-26T01:33:38.572449+00:00 machine postfix/smtpd[60203]: NOQUEUE: reject: RCPT from unknown[192.168.1.1]: 504 5.5.2 <WIN-9QL4SDRB93L>: Helo command rejected: need fully-qualified hostname; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<WIN-9QL4SDRB93L>
+2024-08-25T12:31:56.154748+00:00 machine postfix/smtpd[3887453]: NOQUEUE: reject: RCPT from unknown[192.168.1.1]: 454 4.7.1 <[email protected]>: Relay access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<WIN-CLJ1B0GQ6JP>
+Jun 04 22:24:28 machine postfix/smtpd[3967801]: NOQUEUE: reject: RCPT from static.1.1.168.192.client.domain.xyz[192.168.1.1]: 454 4.7.1 <[email protected]>: Relay access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<WIN-CLJ1B0GQ6JP>

.tests/postfix-relay/config.yaml

@@ -0,0 +1,11 @@
+parsers:
+- crowdsecurity/postfix-logs
+- crowdsecurity/syslog-logs
+- crowdsecurity/dateparse-enrich
+scenarios:
+- ./scenarios/crowdsecurity/postfix-relay-denied.yaml
+postoverflows:
+- ""
+log_file: postfix-spam.log
+log_type: syslog
+ignore_parsers: true

.tests/postfix-relay/postfix-spam.log

@@ -0,0 +1,2 @@
+2024-08-25T10:04:35.051238+00:00 machine postfix/smtpd[3814725]: NOQUEUE: reject: RCPT from unknown[192.168.1.1]: 454 4.7.1 <[email protected]>: Relay access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<WIN-9QL4SDRB93L>
+2024-08-25T10:04:52.547326+00:00 machine postfix/smtpd[3814725]: NOQUEUE: reject: RCPT from unknown[192.168.1.1]: 454 4.7.1 <[email protected]>: Relay access denied; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<WIN-9QL4SDRB93L>

.tests/postfix-relay/scenario.assert

@@ -0,0 +1,29 @@
+len(results) == 1
+"192.168.1.1" in results[0].Overflow.GetSources()
+results[0].Overflow.Sources["192.168.1.1"].IP == "192.168.1.1"
+results[0].Overflow.Sources["192.168.1.1"].Range == ""
+results[0].Overflow.Sources["192.168.1.1"].GetScope() == "Ip"
+results[0].Overflow.Sources["192.168.1.1"].GetValue() == "192.168.1.1"
+results[0].Overflow.Alert.Events[0].GetMeta("action") == "reject"
+results[0].Overflow.Alert.Events[0].GetMeta("datasource_path") == "postfix-spam.log"
+results[0].Overflow.Alert.Events[0].GetMeta("datasource_type") == "file"
+results[0].Overflow.Alert.Events[0].GetMeta("log_type") == "postfix"
+results[0].Overflow.Alert.Events[0].GetMeta("machine") == "machine"
+results[0].Overflow.Alert.Events[0].GetMeta("reason") == "Relay access denied"
+results[0].Overflow.Alert.Events[0].GetMeta("service") == "postfix"
+results[0].Overflow.Alert.Events[0].GetMeta("source_hostname") == "unknown"
+results[0].Overflow.Alert.Events[0].GetMeta("source_ip") == "192.168.1.1"
+results[0].Overflow.Alert.Events[0].GetMeta("timestamp") == "2024-08-25T10:04:35.051238Z"
+results[0].Overflow.Alert.Events[1].GetMeta("action") == "reject"
+results[0].Overflow.Alert.Events[1].GetMeta("datasource_path") == "postfix-spam.log"
+results[0].Overflow.Alert.Events[1].GetMeta("datasource_type") == "file"
+results[0].Overflow.Alert.Events[1].GetMeta("log_type") == "postfix"
+results[0].Overflow.Alert.Events[1].GetMeta("machine") == "machine"
+results[0].Overflow.Alert.Events[1].GetMeta("reason") == "Relay access denied"
+results[0].Overflow.Alert.Events[1].GetMeta("service") == "postfix"
+results[0].Overflow.Alert.Events[1].GetMeta("source_hostname") == "unknown"
+results[0].Overflow.Alert.Events[1].GetMeta("source_ip") == "192.168.1.1"
+results[0].Overflow.Alert.Events[1].GetMeta("timestamp") == "2024-08-25T10:04:52.547326Z"
+results[0].Overflow.Alert.GetScenario() == "crowdsecurity/postfix-relay-denied"
+results[0].Overflow.Alert.Remediation == true
+results[0].Overflow.Alert.GetEventsCount() == 2

collections/crowdsecurity/postfix.yaml

@@ -3,6 +3,8 @@ parsers:
   - crowdsecurity/postscreen-logs
 scenarios:
   - crowdsecurity/postfix-spam
+  - crowdsecurity/postfix-relay-denied
+  - crowdsecurity/postfix-helo-rejected
 description: "postfix support : parser and spammer detection"
 author: crowdsecurity
 tags:

parsers/s01-parse/crowdsecurity/postfix-logs.yaml

@@ -29,6 +29,9 @@ pattern_syntax:
   POSTFIX_COMMAND: '(AUTH|STARTTLS|CONNECT|EHLO|HELO|RCPT)'
   POSTFIX_ACTION: 'discard|dunno|filter|hold|ignore|info|prepend|redirect|replace|reject|warn'
   RELAY: '(?:%{HOSTNAME:remote_host}(?:\[%{IP:remote_addr}\](?::[0-9]+(.[0-9]+)?)?)?)'
+  SMTP_BASIC_STATUS_CODE: '[0-9]{3}' #250
+  SMTP_ENHANCED_STATUS_CODE: '[0-9.]+' #2.0.0
+  SMTP_RETURN_CODES: '%{SMTP_BASIC_STATUS_CODE:smtp_basic_status_code}( %{SMTP_ENHANCED_STATUS_CODE:smtp_enhanced_status_code})?' #250 2.0.0
 description: "Parse postfix logs"
 nodes:
   - grok:
@@ -45,10 +48,21 @@ nodes:
           value: spam-attempt
   - grok:
       apply_on: message
-      pattern: 'NOQUEUE: %{POSTFIX_ACTION:action}: %{DATA:command} from %{RELAY}: %{GREEDYDATA:reason}'
+      pattern: 'NOQUEUE: %{POSTFIX_ACTION:action}: %{DATA:command} from %{RELAY}: %{SMTP_RETURN_CODES:smtp_return_codes} %{GREEDYDATA:reason}'
       statics:
         - meta: action
-          expression: "evt.Parsed.action"        
+          expression: "evt.Parsed.action"
+    nodes:
+      ## We check if the reason is not a service unavailable if so we parser more information
+      - filter: "evt.Parsed.reason != 'Service unavailable'"
+        grok:
+          apply_on: reason
+          pattern: "<%{DATA:helo}>: %{GREEDYDATA:reason}; %{GREEDYDATA:kvItems}"
+        statics:
+          - parsed: unused
+            expression: ParseKV(evt.Parsed.kvItems, evt.Unmarshaled, "postfix")
+          - meta: reason
+            expression: "evt.Parsed.reason"
 statics:
     - meta: service
       value: postfix

scenarios/crowdsecurity/postfix-helo-rejected.md

@@ -0,0 +1,5 @@
+### Postfix helo rejected
+
+Postfix helo rejected is a log message generated when a client sends a HELO or EHLO command that is rejected by the server. This can happen for a variety of reasons, such as the client using an invalid hostname or the server being configured to reject certain types of HELO commands.
+
+You can see the configuration for the restrictions placed on HELO commands within https://www.postfix.org/postconf.5.html#smtpd_helo_restrictions

scenarios/crowdsecurity/postfix-helo-rejected.yaml

@@ -0,0 +1,22 @@
+# postfix helo rejected because it did not match postfix restrictions
+type: leaky
+name: crowdsecurity/postfix-helo-rejected
+description: "Detect HELO rejections"
+filter: "evt.Meta.log_type == 'postfix' && evt.Meta.action == 'reject' && evt.Meta.reason startsWith 'Helo command rejected'"
+references:
+  - https://www.postfix.org/postconf.5.html#smtpd_helo_restrictions
+groupby: evt.Meta.source_ip
+capacity: 1
+leakspeed: 600s
+blackhole: 1m
+reprocess: false
+labels:
+  service: postfix
+  remediation: true
+  confidence: 2
+  spoofable: 0
+  classification:
+  - attack.T1595
+  - attack.T1592
+  behavior: "smtp:spam"
+  label: "Postfix Helo Rejected"

scenarios/crowdsecurity/postfix-relay-denied.md

@@ -0,0 +1,5 @@
+### Postfix relay denied access
+
+Postfix relay denied access is a log message generated when a client tries to relay an email through the server without being authorized to do so. This can happen for a variety of reasons, such as the client not being authenticated or the server not being configured to allow relaying from the client's IP address.
+
+Many bots and spammers try to exploit open relays to send spam emails, so it's important to monitor for these types of events and take action to prevent unauthorized relaying.

scenarios/crowdsecurity/postfix-relay-denied.yaml

@@ -0,0 +1,22 @@
+# postfix relay access denied
+type: leaky
+name: crowdsecurity/postfix-relay-denied
+description: "Detect multiple open relay attempts"
+filter: "evt.Meta.log_type == 'postfix' && evt.Meta.action == 'reject' && evt.Meta.reason == 'Relay access denied'"
+references:
+  - https://en.wikipedia.org/wiki/Open_mail_relay
+groupby: evt.Meta.source_ip
+capacity: 1
+leakspeed: 600s
+blackhole: 1m
+reprocess: false
+labels:
+  service: postfix
+  remediation: true
+  confidence: 3
+  spoofable: 0
+  classification:
+  - attack.T1595
+  - attack.T1190
+  behavior: "smtp:spam"
+  label: "Postfix Relay Denied"