# Help with Custom Postfix Scenario/Parsing

**URL:** <https://discourse.crowdsec.net/t/help-with-custom-postfix-scenario-parsing/1908>\
**Category:** crowdsec\
**Created:** [July 5, 2024, 8:15pm UTC](https://discourse.crowdsec.net/t/help-with-custom-postfix-scenario-parsing/1908 "2024-07-05T20:15:27Z")\
**Posts on this page:** 5\
**Page:** 1

<div class="post-metadata">

**Author:** ![tunloop](https://dub1.discourse-cdn.com/flex013/user_avatar/discourse.crowdsec.net/tunloop/32/902_2.png) [@tunloop](https://discourse.crowdsec.net/u/tunloop)\
**Post date:** [July 5, 2024, 8:15pm UTC](https://discourse.crowdsec.net/t/help-with-custom-postfix-scenario-parsing/1908/1 "2024-07-05T20:15:27Z")

</div>

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:

```auto
 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

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

```

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

```auto
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.

```auto
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?

```auto
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:

```auto
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!

---

<div class="post-metadata">

**Author:** ![tunloop](https://dub1.discourse-cdn.com/flex013/user_avatar/discourse.crowdsec.net/tunloop/32/902_2.png) [@tunloop](https://discourse.crowdsec.net/u/tunloop)\
**Post date:** [July 7, 2024, 3:34am UTC](https://discourse.crowdsec.net/t/help-with-custom-postfix-scenario-parsing/1908/2 "2024-07-07T03:34:11Z")

</div>

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:

```auto
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:

```auto
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:

```auto
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

```auto
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?

---

<div class="post-metadata">

**Author:** ![tunloop](https://dub1.discourse-cdn.com/flex013/user_avatar/discourse.crowdsec.net/tunloop/32/902_2.png) [@tunloop](https://discourse.crowdsec.net/u/tunloop)\
**Post date:** [July 7, 2024, 5:31am UTC](https://discourse.crowdsec.net/t/help-with-custom-postfix-scenario-parsing/1908/3 "2024-07-07T05:31:19Z")

</div>

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

Its processing now.

---

<div class="post-metadata">

**Author:** ![addisonbell](https://dub1.discourse-cdn.com/flex013/user_avatar/discourse.crowdsec.net/addisonbell/32/935_2.png) [@addisonbell](https://discourse.crowdsec.net/u/addisonbell)\
**Post date:** [July 13, 2024, 8:31am UTC](https://discourse.crowdsec.net/t/help-with-custom-postfix-scenario-parsing/1908/4 "2024-07-13T08:31:57Z")

</div>

Hello,  
Can you please explain this more.

---

<div class="post-metadata">

**Author:** ![tunloop](https://dub1.discourse-cdn.com/flex013/user_avatar/discourse.crowdsec.net/tunloop/32/902_2.png) [@tunloop](https://discourse.crowdsec.net/u/tunloop)\
**Post date:** [July 13, 2024, 4:06pm UTC](https://discourse.crowdsec.net/t/help-with-custom-postfix-scenario-parsing/1908/5 "2024-07-13T16:06:20Z")

</div>

What do you want to know specifically?