Help with Custom Postfix Scenario/Parsing

crowdsec
1

My ultimate goal is to ban IPs that abuse my Postfix service (by abuse, I mean sending non-SMTP data to it). I am using the nftables bouncer.

I have the postfix collection installed as well as these parsers:

 crowdsecurity/dateparse-enrich  ✔  enabled  0.2      /etc/crowdsec/parsers/s02-enrich/dateparse-enrich.yaml 
 crowdsecurity/geoip-enrich      ✔  enabled  0.4      /etc/crowdsec/parsers/s02-enrich/geoip-enrich.yaml     
 crowdsecurity/postfix-logs      ✔  enabled  0.6      /etc/crowdsec/parsers/s01-parse/postfix-logs.yaml      
 crowdsecurity/postscreen-logs   ✔  enabled  0.3      /etc/crowdsec/parsers/s01-parse/postscreen-logs.yaml   
 crowdsecurity/syslog-logs       ✔  enabled  0.8      /etc/crowdsec/parsers/s00-raw/syslog-logs.yaml

And the log acquis

filenames:
  - /var/log/postfix.log
labels:
  type: syslog
---

The particular logs I am looking to parse the remote IP for look like this:

Jul 05 11:13:52 mail postfix/smtpd[19976]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\003\001\246\001\000\001\242\003\003\024d\211\020@\336\376\260K\035\330\243K\220w\374r\252\357\026\233\341\206\t$\037\225c\005\313\023\016 X\321\003\374\213\361\375nL\247\374\221\002M$\2>
Jul 05 11:13:52 mail postfix/smtpd[19976]: lost connection after CONNECT from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19976]: disconnect from unknown[207.90.244.2] commands=0/0
Jul 05 11:13:52 mail postfix/smtpd[19976]: connect from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19976]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\003\001\246\001\000\001\242\003\003T%U\277e\201\254\341\354\036\006\000l\365\356\206\002^\313L\326=\375#\236\271\223j2\365\313S \223\372\031\232\003\002\003\3263\232\353\301C1\266\311\3>
Jul 05 11:13:52 mail postfix/smtpd[19976]: lost connection after CONNECT from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19976]: disconnect from unknown[207.90.244.2] commands=0/0
Jul 05 11:13:52 mail postfix/smtpd[19976]: connect from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19972]: lost connection after STARTTLS from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19972]: disconnect from unknown[207.90.244.2] ehlo=1 starttls=1 commands=2
Jul 05 11:13:52 mail postfix/smtpd[19976]: lost connection after CONNECT from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19976]: disconnect from unknown[207.90.244.2] commands=0/0
Jul 05 11:13:52 mail postfix/smtpd[19972]: connect from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19972]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\003\001I\001\000\001E\003\003C\245CWw\226\267\030\021\244\326B\347\370\265*}\036\336(\265x\251$\025|\270\037[|\033\276 \a\307?\256@bq`\325b\351Sv\335\232\306\311\322\361\342\364\330\205>
Jul 05 11:13:52 mail postfix/smtpd[19972]: lost connection after CONNECT from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19972]: disconnect from unknown[207.90.244.2] commands=0/0
Jul 05 11:13:52 mail postfix/smtpd[19976]: connect from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19976]: lost connection after CONNECT from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19976]: disconnect from unknown[207.90.244.2] commands=0/0
Jul 05 11:13:52 mail postfix/smtpd[19972]: connect from unknown[207.90.244.2]
Jul 05 11:13:52 mail postfix/smtpd[19972]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\002\001\233\001\000\001\227\003\002\036n\024\217\274`x\371\357\373\307\302\265=P\0347\336\247~\024\216P\255 \251pY\017u0\307 \a\021\206\2134\223\272\227\2620\227\022\357s\376\3414\335\2>
Jul 05 11:13:53 mail postfix/smtpd[19972]: lost connection after CONNECT from unknown[207.90.244.2]
Jul 05 11:13:53 mail postfix/smtpd[19972]: disconnect from unknown[207.90.244.2] commands=0/0
Jul 05 11:13:53 mail postfix/smtpd[19976]: connect from unknown[207.90.244.2]
Jul 05 11:13:53 mail postfix/smtpd[19976]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\001\001\250\001\000\001\244\003\003\020n\333\177\035rE\024\201\214\276E\224\voDDLK\nA\344\347?\354\t\031@\264\326#\203 \323\016\346\367\372\201\367\027U\246\273\2260\335\240\357\032\333>
Jul 05 11:13:53 mail postfix/smtpd[19976]: lost connection after CONNECT from unknown[207.90.244.2]
Jul 05 11:13:53 mail postfix/smtpd[19976]: disconnect from unknown[207.90.244.2] commands=0/0
Jul 05 11:13:53 mail postfix/smtpd[19972]: connect from unknown[207.90.244.2]
Jul 05 11:13:53 mail postfix/smtpd[19972]: lost connection after CONNECT from unknown[207.90.244.2]
Jul 05 11:13:53 mail postfix/smtpd[19972]: disconnect from unknown[207.90.244.2] commands=0/0
Jul 05 11:13:53 mail postfix/smtpd[19976]: connect from unknown[207.90.244.2]
Jul 05 11:13:53 mail postfix/smtpd[19976]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\001\001\236\001\000\001\232\003\003rA\314{\355rBu\377\223.\344\204"\377\321\273\211\313\252H\255\016}K\340em\211&\350\216 \t\017\247\216]\340\340\370\335\253\253\214\363\202I\314\373w\2>
Jul 05 11:13:53 mail postfix/smtpd[19976]: lost connection after CONNECT from unknown[207.90.244.2]
Jul 05 11:13:53 mail postfix/smtpd[19976]: disconnect from unknown[207.90.244.2] commands=0/0
Jul 05 11:13:53 mail postfix/smtpd[19972]: connect from unknown[207.90.244.2]
Jul 05 11:13:53 mail postfix/smtpd[19972]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\001\001\265\001\000\001\261\003\003\274F\354\363\262\343\3215&\220)LW)\022g\366\217\232\221\232g\004\323\332(V\376\f\250_H i\336\300\a\323/\3364\023\240\240$\243G\344\nB\343\005-\244\02>
Jul 05 11:13:53 mail postfix/smtpd[19972]: lost connection after CONNECT from unknown[207.90.244.2]

I think attempting to filter down to smtpd and the string improper command pipelining is a good starting place to add these abusing IPs to the firewall. I could probaby figure out how to write the scenario, except using cscli explain is failing and I am not quite sure why.

cscli explain --log=/var/log/postfix.log --type smtp
WARN Line 0/1 is missing evt.StrTime. It is most likely a mistake as it will prevent your logs to be processed in time-machine/forensic mode. 
line: /var/log/postfix.log
        ├ s00-raw
        |       ├ 🔴 crowdsecurity/syslog-logs
        |       └ 🟢 crowdsecurity/non-syslog (+5 ~8)
        ├ s01-parse
        |       ├ 🔴 crowdsecurity/postfix-logs
        |       └ 🔴 crowdsecurity/postscreen-logs
        └-------- parser failure 🔴

I know that the s01-parse postfix-logs yaml does filter down to smtpd already, but it looks like maybe this parser is not set up to ingest the improper command pipelining error from smtpd?
Should I attempt to add my own grok node to parsers/s01-parse/postfix-logs.yaml or create my own parser entirely? I just want to make sure theres not an easier way to handle these smtpd logs before jumping into some grok fun.

And as for the scenario, once the parser is correct, maybe something like this, depending on the parser output?

type: trigger
name: postfix-scan-ban
description: "Ban IP addresses that attempt non-SMTP scanning against SMTPd"
filter: "evt.Meta.service == '????' && evt.Meta.log_message == 'improper command pipelining'
labels:
  service: postfix
  remediation: true

Remediation profile:

name: default_ip_remediation
filters:
 - Alert.Remediation == true && Alert.GetScenario() contains "postfix"
decisions:
 - type: ban
   duration: 4h
on_success: break

I am still getting used to and understanding the crowdsec pipeline, any help, advice, assistance is appreciated. Thanks!

2

So I got everything working when giving the explain command the log line itself.
But it appears that I have broken crowdsec reading the actual log file.

Here is my s01 parser:

filter: "evt.Parsed.program == 'smtp'"
name: postfix-smtpd
description: "Parse postfix smtpd logs"
nodes:
  - grok:
      apply_on: message
      pattern: '%{MONTH:date_month}\s+%{MONTHDAY:date_day}\s+%{TIME:date_time}\s+%{HOSTNAME:hostname}\s+postfix/smtpd\[[0-9]+\]:\s+%{DATA:smtpd_msg}\[%{IP:remote_addr}\]'
      statics:
        - meta: action
          expression: "evt.Parsed.action"
statics:
    - meta: service
      value: postfix
    - meta: source_ip
      expression: "evt.Parsed.remote_addr"
    - meta: smtpd_msg
      expression: "evt.Parsed.smtpd_msg"
    - meta: log_type
      value: postfix

Here is my scenario:

type: trigger
name: postfix-scan-ban
description: "Ban IP addresses that attempt non-SMTP scanning against SMTPd"
filter: "evt.Meta.service == 'postfix' && evt.Parsed.smtpd_msg startsWith 'improper command pipelining'"
labels:
  service: postfix
  remediation: true

And if I feed the log file directly into explain, it gets all the way to the scenario no problem:

cscli explain -vv --log "Jul 05 11:13:52 mail postfix/smtpd[19976]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\003\001\246\001\000\001\242\003\003T%U\277e\201\254\341\354\036\006\000l\365\356\206\002^\313L\326=\375#\236\271\223j2\365\313S \223\372\031\232\003\002\003\3263\232\353\301C1\266\311\3>" --type smtp
WARN Line 0/1 is missing evt.StrTime. It is most likely a mistake as it will prevent your logs to be processed in time-machine/forensic mode. 
line: Jul 05 11:13:52 mail postfix/smtpd[19976]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\003\001\246\001\000\001\242\003\003T%U\277e\201\254\341\354\036\006\000l\365\356\206\002^\313L\326=\375#\236\271\223j2\365\313S \223\372\031\232\003\002\003\3263\232\353\301C1\266\311\3>
        ├ s00-raw
        |       ├ 🔴 crowdsecurity/syslog-logs
        |       └ 🟢 crowdsecurity/non-syslog (+5 ~8)
        |               └ update evt.ExpectMode : %!s(int=0) -> 1
        |               └ update evt.Stage :  -> s01-parse
        |               └ update evt.Line.Raw :  -> Jul 05 11:13:52 mail postfix/smtpd[19976]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\003\001\246\001\000\001\242\003\003T%U\277e\201\254\341\354\036\006\000l\365\356\206\002^\313L\326=\375#\236\271\223j2\365\313S \223\372\031\232\003\002\003\3263\232\353\301C1\266\311\3>
        |               └ update evt.Line.Src :  -> /tmp/cscli_explain1253933983/cscli_test_tmp.log
        |               └ update evt.Line.Time : 0001-01-01 00:00:00 +0000 UTC -> 2024-07-07 03:26:52.534032445 +0000 UTC
        |               └ create evt.Line.Labels.type : smtp
        |               └ update evt.Line.Process : %!s(bool=false) -> true
        |               └ update evt.Line.Module :  -> file
        |               └ create evt.Parsed.message : Jul 05 11:13:52 mail postfix/smtpd[19976]: improper command pipelining after CONNECT from unknown[207.90.244.2]: \026\003\003\001\246\001\000\001\242\003\003T%U\277e\201\254\341\354\036\006\000l\365\356\206\002^\313L\326=\375#\236\271\223j2\365\313S \223\372\031\232\003\002\003\3263\232\353\301C1\266\311\3>
        |               └ create evt.Parsed.program : smtp
        |               └ update evt.Time : 0001-01-01 00:00:00 +0000 UTC -> 2024-07-07 03:26:52.534059456 +0000 UTC
        |               └ create evt.Meta.datasource_path : /tmp/cscli_explain1253933983/cscli_test_tmp.log
        |               └ create evt.Meta.datasource_type : file
        ├ s01-parse
        |       ├ 🔴 crowdsecurity/postfix-logs
        |       └ 🟢 postfix-smtpd (+10 ~1)
        |               └ update evt.Stage : s01-parse -> s02-enrich
        |               └ create evt.Parsed.date_time : 11:13:52
        |               └ create evt.Parsed.hostname : mail
        |               └ create evt.Parsed.remote_addr : 207.90.244.2
        |               └ create evt.Parsed.smtpd_msg : improper command pipelining after CONNECT from unknown
        |               └ create evt.Parsed.date_day : 05
        |               └ create evt.Parsed.date_month : Jul
        |               └ create evt.Meta.log_type : postfix
        |               └ create evt.Meta.service : postfix
        |               └ create evt.Meta.smtpd_msg : improper command pipelining after CONNECT from unknown
        |               └ create evt.Meta.source_ip : 207.90.244.2
        ├ s02-enrich
        |       ├ 🔴 crowdsecurity/dateparse-enrich
        |       └ 🟢 crowdsecurity/geoip-enrich (+13)
        |               └ create evt.Enriched.ASNNumber : 174
        |               └ create evt.Enriched.ASNOrg : COGENT-174
        |               └ create evt.Enriched.ASNumber : 174
        |               └ create evt.Enriched.IsInEU : false
        |               └ create evt.Enriched.IsoCode : US
        |               └ create evt.Enriched.Latitude : 37.751000
        |               └ create evt.Enriched.Longitude : -97.822000
        |               └ create evt.Enriched.SourceRange : 207.90.244.0/24
        |               └ create evt.Meta.ASNNumber : 174
        |               └ create evt.Meta.SourceRange : 207.90.244.0/24
        |               └ create evt.Meta.ASNOrg : COGENT-174
        |               └ create evt.Meta.IsInEU : false
        |               └ create evt.Meta.IsoCode : US
        ├-------- parser success 🟢        ├ Scenarios
                └ 🟢 postfix-scan-ban

But giving the explain the log file that contains that exact log line, it fails to go to even s01-parse

cscli explain -vvv --log=/var/log/postfix.log --type smtp
WARN Line 0/1 is missing evt.StrTime. It is most likely a mistake as it will prevent your logs to be processed in time-machine/forensic mode. 
line: /var/log/postfix.log
        ├ s00-raw
        |       ├ 🔴 crowdsecurity/syslog-logs
        |       └ 🟢 crowdsecurity/non-syslog (+5 ~8)
        |               └ update evt.ExpectMode : %!s(int=0) -> 1
        |               └ update evt.Stage :  -> s01-parse
        |               └ update evt.Line.Raw :  -> /var/log/postfix.log
        |               └ update evt.Line.Src :  -> /tmp/cscli_explain3882528558/cscli_test_tmp.log
        |               └ update evt.Line.Time : 0001-01-01 00:00:00 +0000 UTC -> 2024-07-07 03:27:19.513044736 +0000 UTC
        |               └ create evt.Line.Labels.type : smtp
        |               └ update evt.Line.Process : %!s(bool=false) -> true
        |               └ update evt.Line.Module :  -> file
        |               └ create evt.Parsed.message : /var/log/postfix.log
        |               └ create evt.Parsed.program : smtp
        |               └ update evt.Time : 0001-01-01 00:00:00 +0000 UTC -> 2024-07-07 03:27:19.513068021 +0000 UTC
        |               └ create evt.Meta.datasource_path : /tmp/cscli_explain3882528558/cscli_test_tmp.log
        |               └ create evt.Meta.datasource_type : file
        ├ s01-parse
        |       ├ 🔴 crowdsecurity/postfix-logs
        |       ├ 🔴 postfix-smtpd
        |       └ 🔴 crowdsecurity/postscreen-logs
        └-------- parser failure 🔴

My parser filter is set to evt.Parsed.program equal to smtp, which as explain shows, is clearly true.

Why, when using the log file, isn’t s01-parsers getting used?
Is there something about the non-syslog path that breaks this?

3

Oops, explain is supposed to use --file for the log.

Its processing now.

4

Hello,
Can you please explain this more.

5

What do you want to know specifically?