diff --git a/Makefile b/Makefile index 6db4c02..f539fba 100644 --- a/Makefile +++ b/Makefile @@ -1,5 +1,5 @@ .DEFAULT_GOAL := help -Owner := youyo +Owner := yo000 Name := postfix-log-parser Repository := "github.com/$(Owner)/$(Name)" GithubToken := ${GITHUB_TOKEN} @@ -28,7 +28,7 @@ vendoring: ## Build build: go get - goxz -os=darwin,linux -arch=amd64 -d=pkg ./$(Name) + goxz -os=freebsd,darwin,linux -arch=amd64 -d=pkg ./$(Name) ## Release release: diff --git a/README.md b/README.md index dcd9b12..0f77f73 100644 --- a/README.md +++ b/README.md @@ -5,14 +5,14 @@ Parse postfix log, and output json format ## Install Place a `postfix-log-parser` command to your PATH and set an executable flag. -Download the latest release from github. https://github.com/youyo/postfix-log-parser/releases/latest +Download the latest release from github. https://github.com/yo000/postfix-log-parser/releases/latest ## Usage Input postfix logs as os stdin. ``` console -# cat /var/log/maillog | ./postfix-log-parser +# cat /var/log/maillog | ./postfix-log-parser | jq { "time": "0000-10-10T15:59:29+09:00", "hostname": "mail", @@ -20,8 +20,12 @@ Input postfix logs as os stdin. "queue_id": "3D74ADB7400B", "client_hostname": "example.com", "client_ip": "127.0.0.1", + "sasl_method": "PLAIN", + "sasl_username": "test2@smtp.example.info", "message_id": "f93388828093534f92d85ffe21b2a719@example.info", "from": "test2@example.info", + "size": "1988", + "nrcpt": "1", "messages": [ { "time": "0000-10-10T15:59:30+09:00", @@ -42,6 +46,70 @@ Input postfix logs as os stdin. . ``` +Use -f flag to flatten json structure: + +``` console +# cat /var/log/maillog | ./postfix-log-parser -f | jq +{ + "time": "0000-10-10T15:59:29+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1827]", + "queue_id": "3D74ADB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "PLAIN", + "sasl_username": "test2@smtp.example.info", + "message_id": "f93388828093534f92d85ffe21b2a719@example.info", + "from": "test2@example.info", + "size": "1988", + "nrcpt": "1", + "time_sent": "0000-10-10T15:59:30+09:00", + "to": "test@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)" +} +{ + "time": "0000-10-10T15:59:29+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1827]", + "queue_id": "3D74ADB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "PLAIN", + "sasl_username": "test2@smtp.example.info", + "message_id": "f93388828093534f92d85ffe21b2a719@example.info", + "from": "test2@example.info", + "size": "1988", + "nrcpt": "1", + "time_sent": "0000-10-10T15:59:30+09:00", + "to": "test2@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)" +} +. +. +. +``` + +Use "-o filename.json" to write output to file. + +## Piping rsyslog to postfix-log-parser + +You can feed syslog to postfix-log-parser by using "omprog" rsyslog module, with template "RSYSLOG_FileFormat" : +``` console +module(load="omprog") +[...] +mail.info /var/log/maillog +& action( + type="omprog" + binary="/usr/local/bin/postfix-log-parser -f -o /var/log/maillog.json" + template="RSYSLOG_FileFormat") + +& stop + +``` + + ## Library usage ``` @@ -75,8 +143,12 @@ postfixlog.LogFormat{ Messages: "to=, relay=mail.example-to.com[192.168.0.10]:25, delay=5.3, delays=0.26/0/0.31/4.7, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C598F1B0002D)", ClientHostname: "", ClinetIp: "", + SaslMethod: "", + SaslUsername: "", MessageId: "", From: "", + Size: "", + NRcpt: "", To: "test@example-to.com", Status: "sent", } diff --git a/go.mod b/go.mod index 6e5eadf..759cb73 100644 --- a/go.mod +++ b/go.mod @@ -1,8 +1,25 @@ -module github.com/youyo/postfix-log-parser +module github.com/yo000/postfix-log-parser + +go 1.21 + +toolchain go1.23.2 require ( - github.com/spf13/cobra v0.0.3 - github.com/spf13/pflag v1.0.3 // indirect + github.com/prometheus/client_golang v1.21.0 + github.com/spf13/cobra v1.9.1 + github.com/tabalt/pidfile v1.1.0 ) -go 1.13 +require ( + github.com/beorn7/perks v1.0.1 // indirect + github.com/cespare/xxhash/v2 v2.3.0 // indirect + github.com/inconshreveable/mousetrap v1.1.0 // indirect + github.com/klauspost/compress v1.17.11 // indirect + github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect + github.com/prometheus/client_model v0.6.1 // indirect + github.com/prometheus/common v0.62.0 // indirect + github.com/prometheus/procfs v0.15.1 // indirect + github.com/spf13/pflag v1.0.6 // indirect + golang.org/x/sys v0.28.0 // indirect + google.golang.org/protobuf v1.36.1 // indirect +) diff --git a/go.sum b/go.sum index 385007d..d8766ff 100644 --- a/go.sum +++ b/go.sum @@ -1,4 +1,43 @@ -github.com/spf13/cobra v0.0.3 h1:ZlrZ4XsMRm04Fr5pSFxBgfND2EBVa1nLpiy1stUsX/8= -github.com/spf13/cobra v0.0.3/go.mod h1:1l0Ry5zgKvJasoi3XT1TypsSe7PqH0Sj9dhYf7v3XqQ= -github.com/spf13/pflag v1.0.3 h1:zPAT6CGy6wXeQ7NtTnaTerfKOsV6V6F8agHXFiazDkg= -github.com/spf13/pflag v1.0.3/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4= +github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= +github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= +github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= +github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= +github.com/cpuguy83/go-md2man/v2 v2.0.6/go.mod h1:oOW0eioCTA6cOiMLiUPZOpcVxMig6NIQQ7OS05n1F4g= +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI= +github.com/google/go-cmp v0.6.0/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= +github.com/inconshreveable/mousetrap v1.1.0 h1:wN+x4NVGpMsO7ErUn/mUI3vEoE6Jt13X2s0bqwp9tc8= +github.com/inconshreveable/mousetrap v1.1.0/go.mod h1:vpF70FUmC8bwa3OWnCshd2FqLfsEA9PFc4w1p2J65bw= +github.com/klauspost/compress v1.17.11 h1:In6xLpyWOi1+C7tXUUWv2ot1QvBjxevKAaI6IXrJmUc= +github.com/klauspost/compress v1.17.11/go.mod h1:pMDklpSncoRMuLFrf1W9Ss9KT+0rH90U12bZKk7uwG0= +github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc= +github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= +github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= +github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= +github.com/prometheus/client_golang v1.21.0 h1:DIsaGmiaBkSangBgMtWdNfxbMNdku5IK6iNhrEqWvdA= +github.com/prometheus/client_golang v1.21.0/go.mod h1:U9NM32ykUErtVBxdvD3zfi+EuFkkaBvMb09mIfe0Zgg= +github.com/prometheus/client_model v0.6.1 h1:ZKSh/rekM+n3CeS952MLRAdFwIKqeY8b62p8ais2e9E= +github.com/prometheus/client_model v0.6.1/go.mod h1:OrxVMOVHjw3lKMa8+x6HeMGkHMQyHDk9E3jmP2AmGiY= +github.com/prometheus/common v0.62.0 h1:xasJaQlnWAeyHdUBeGjXmutelfJHWMRr+Fg4QszZ2Io= +github.com/prometheus/common v0.62.0/go.mod h1:vyBcEuLSvWos9B1+CyL7JZ2up+uFzXhkqml0W5zIY1I= +github.com/prometheus/procfs v0.15.1 h1:YagwOFzUgYfKKHX6Dr+sHT7km/hxC76UB0learggepc= +github.com/prometheus/procfs v0.15.1/go.mod h1:fB45yRUv8NstnjriLhBQLuOUt+WW4BsoGhij/e3PBqk= +github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM= +github.com/spf13/cobra v1.9.1 h1:CXSaggrXdbHK9CF+8ywj8Amf7PBRmPCOJugH954Nnlo= +github.com/spf13/cobra v1.9.1/go.mod h1:nDyEzZ8ogv936Cinf6g1RU9MRY64Ir93oCnqb9wxYW0= +github.com/spf13/pflag v1.0.6 h1:jFzHGLGAlb3ruxLB8MhbI6A8+AQX/2eW4qeyNZXNp2o= +github.com/spf13/pflag v1.0.6/go.mod h1:McXfInJRrz4CZXVZOBLb0bTZqETkiAhM9Iw0y3An2Bg= +github.com/stretchr/testify v1.10.0 h1:Xv5erBjTwe/5IxqUQTdXv5kgmIvbHo3QQyRwhJsOfJA= +github.com/stretchr/testify v1.10.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY= +github.com/tabalt/pidfile v1.1.0 h1:Q7qQGZ4MoAXE+rvM5tB4/eAIrawewYewByhMiPoDE50= +github.com/tabalt/pidfile v1.1.0/go.mod h1:7F1QwNrjfAApsuX4Nyah3RsbHVAdY/D9qZWp0nnJ/Uw= +golang.org/x/sys v0.28.0 h1:Fksou7UEQUWlKvIdsqzJmUmCX3cZuD2+P3XyyzwMhlA= +golang.org/x/sys v0.28.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= +google.golang.org/protobuf v1.36.1 h1:yBPeRvTftaleIgM3PZ/WBIZ7XM/eEYAaEyCwvyjq/gk= +google.golang.org/protobuf v1.36.1/go.mod h1:9fA7Ob0pmnwhb644+1+CVWFRbNajQ6iRojtC/QF5bRE= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= +gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= diff --git a/postfix-log-parser.go b/postfix-log-parser.go index 739c2ec..efb0363 100644 --- a/postfix-log-parser.go +++ b/postfix-log-parser.go @@ -1,19 +1,46 @@ package postfixlog import ( + "errors" "regexp" "time" ) const ( + SyslogPri = `(?:<\d{1,3}>)?` TimeFormat = "Jan 2 15:04:05" TimeFormatISO8601 = "2006-01-02T15:04:05.999999-07:00" - TimeRegexpFormat = `([A-Za-z]{3}\s*[0-9]{1,2} [0-9]{2}:[0-9]{2}:[0-9]{2}|^\d{4}-[01]\d-[0-3]\dT[0-2]\d:[0-5]\d:[0-5]\d\.\d+(?:[+-][0-2]\d:[0-5]\d|Z))` - HostRegexpFormat = `([0-9A-Za-z\.]*)` - ProcessRegexpFormat = `(postfix/[a-z]*\[[0-9]{1,5}\])?` + // Capture group 1 + TimeRegexpFormat = `([A-Za-z]{3}\s*[0-9]{1,2} [0-9]{2}:[0-9]{2}:[0-9]{2}|^\d{4}-[01]\d-[0-3]\dT[0-2]\d:[0-5]\d:[0-5]\d(?:\.\d+)?(?:[+-][0-2]\d:[0-5]\d|Z))` + // Capture group 2 + HostRegexpFormat = `([0-9A-Za-z\-\.]*)` + // Capture group 3 + ProcessRegexpFormat = `(postfix.*(?:\/[a-z]*)+\[[0-9]{1,7}\])?` + // Capture group 4 QueueIdRegexpFormat = `([0-9A-Z]*)` - MessageDetailsRegexpFormat = `((?:client=(.+)\[(.+)\])?(?:message-id=<(.+)>)?(?:from=<(.+@.+)>)?(?:to=<(.+@.+)>.*status=([a-z]+))?.*)` - RegexpFormat = TimeRegexpFormat + ` ` + HostRegexpFormat + ` ` + ProcessRegexpFormat + `: ` + QueueIdRegexpFormat + `(?:\: )?` + MessageDetailsRegexpFormat + // These are the main messages : Capture group 5 get all the following + // Capture groups 6, 7, 8, 9 + ClientRegexpFormat = `(?:client=(.+)\[(.+)\](?:, sasl_method=(.+), sasl_username=(.+))?)?` + // CG 10 + MessageIdRegexpFormat = `(?:message-id=<(.+)>)?` + // CG 11, 12, 13 + FromRegexpFormat = `(?:from=<(.+@.+)>(?:, size=(\d+), nrcpt=(\d+))?)?` + // CG 14, 15 + ToRegexpFormat = `(?:to=<(.+@.+)>.*status=([a-z]+))?` + // CG 16 + SenderNDNRegexpFormat = `(?:sender non-delivery notification: ([0-9A-Z]*))?` + // CG 17, 18, 19, 20, 21 + MilterRegexpFormat = `(?:(milter-.*): .* from (.+)\[(.+)\]: .*from=<(.+@.+)?> to=<(.+@.+)> .*)?` + // CG 22, 23, 24, 25 + AuthentFailedRegexpFormat = `(?:warning: (.+)\[(.+)\]: SASL (.*) authentication failed: (.*))?` + // CG 26, 27, 28, 29. from regex is voluntarily lazy, b/c some senders really do not put '@' in from + PostfixRejectRegexpFormat = `(?:reject: RCPT from (.+)\[(.+)\]: [0-9]{3} [0-9\.]{5} [^;]*; from=<(.+)?> to=<(.+@[^>]+)>.*$)?` + // CG 30, 31, 32 + PostfixRLimitExceedFormat = `(?:warning: Message delivery request rate limit exceeded: ([0-9]+) from (.+)\[(.+)\] for service [a-zA-Z]+)?` + // CG 33, 34, 35, 36, 37, 38 + FilterRcptRegexpFormat = `(?:filter: RCPT from (.+)\[(.+)\]: <(.+@.+)?>: ([^;]+); from=<(.+@.+)?> to=<(.+@[^>]+)> proto=[^ ]+ helo=<.+>)?` + MessageDetailsRegexpFormat = `(` + ClientRegexpFormat + MessageIdRegexpFormat + FromRegexpFormat + ToRegexpFormat + SenderNDNRegexpFormat + MilterRegexpFormat + AuthentFailedRegexpFormat + PostfixRejectRegexpFormat + PostfixRLimitExceedFormat + FilterRcptRegexpFormat + `.*)` + RegexpFormat = SyslogPri + TimeRegexpFormat + ` ` + HostRegexpFormat + ` ` + ProcessRegexpFormat + `:? ` + QueueIdRegexpFormat + `(?:\: )?` + MessageDetailsRegexpFormat ) type ( @@ -27,13 +54,18 @@ type ( Hostname string `json:"hostname"` Process string `json:"process"` QueueId string `json:"queue_id"` - Messages string `json:"messages"` + Message string `json:"message"` ClientHostname string `json:"client_hostname"` ClinetIp string `json:"client_ip"` + SaslMethod string `json:"sasl_method"` + SaslUsername string `json:"sasl_username"` MessageId string `json:"message_id"` From string `json:"from"` + Size string `json:"size"` + NRcpt string `json:"nrcpt"` To string `json:"to"` Status string `json:"status"` + BounceId string `json:"bounce_id"` } ) @@ -46,6 +78,10 @@ func NewPostfixLog() *PostfixLog { func (p *PostfixLog) Parse(text []byte) (LogFormat, error) { re := p.Regexp.Copy() group := re.FindSubmatch(text) + if len(group) == 0 { + err := errors.New("Error: Line do not match regex") + return LogFormat{}, err + } var t time.Time t, err := time.ParseInLocation(TimeFormat, string(group[1]), time.Local) if err != nil { @@ -56,17 +92,58 @@ func (p *PostfixLog) Parse(text []byte) (LogFormat, error) { } logFormat := LogFormat{ - Time: &t, - Hostname: string(group[2]), - Process: string(group[3]), - QueueId: string(group[4]), - Messages: string(group[5]), - ClientHostname: string(group[6]), - ClinetIp: string(group[7]), - MessageId: string(group[8]), - From: string(group[9]), - To: string(group[10]), - Status: string(group[11]), + Time: &t, + Hostname: string(group[2]), + Process: string(group[3]), + QueueId: string(group[4]), + Message: string(group[5]), + SaslMethod: string(group[8]), + SaslUsername: string(group[9]), + MessageId: string(group[10]), + Size: string(group[12]), + NRcpt: string(group[13]), + BounceId: string(group[16]), + } + + // Milter reject|hold put values far in the group + if len(group[17]) > 0 { + logFormat.Status = string(group[17]) + logFormat.ClientHostname = string(group[18]) + logFormat.ClinetIp = string(group[19]) + logFormat.From = string(group[20]) + logFormat.To = string(group[21]) + // Authentication failure + } else if len(group[22]) > 0 { + logFormat.ClientHostname = string(group[22]) + logFormat.ClinetIp = string(group[23]) + logFormat.SaslMethod = string(group[24]) + logFormat.Status = "auth-failed" + // postfix-reject + } else if len(group[26]) > 0 { + logFormat.ClientHostname = string(group[26]) + logFormat.ClinetIp = string(group[27]) + logFormat.From = string(group[28]) + logFormat.To = string(group[29]) + logFormat.Status = "postfix-reject" + // postfix rate-limit + } else if len(group[30]) > 0 { + logFormat.ClientHostname = string(group[31]) + logFormat.ClinetIp = string(group[32]) + logFormat.Status = "postfix-ratelimit" + // postfix filter RCPT + } else if len(group[33]) > 0 { + logFormat.ClientHostname = string(group[33]) + logFormat.ClinetIp = string(group[34]) + logFormat.From = string(group[37]) + logFormat.To = string(group[38]) + logFormat.Status = "postfix-filter" + // bounced by remote + } else { + logFormat.Status = string(group[15]) + logFormat.ClientHostname = string(group[6]) + logFormat.ClinetIp = string(group[7]) + logFormat.From = string(group[11]) + logFormat.To = string(group[14]) } return logFormat, nil diff --git a/postfix-log-parser/cmd/execute.go b/postfix-log-parser/cmd/execute.go deleted file mode 100644 index 530f8a7..0000000 --- a/postfix-log-parser/cmd/execute.go +++ /dev/null @@ -1,15 +0,0 @@ -package cmd - -import "os" - -func initConfig() {} - -func Execute() { - cmd := NewCmdRoot() - cmd.SetOutput(os.Stdout) - if err := cmd.Execute(); err != nil { - cmd.SetOutput(os.Stderr) - cmd.Println(err) - os.Exit(1) - } -} diff --git a/postfix-log-parser/cmd/root.go b/postfix-log-parser/cmd/root.go index 22d5187..6aa84dc 100644 --- a/postfix-log-parser/cmd/root.go +++ b/postfix-log-parser/cmd/root.go @@ -1,15 +1,28 @@ package cmd import ( - "bufio" - "encoding/json" + "os" "fmt" "log" - "os" + "net" + "sync" "time" + "bufio" + "errors" + "net/http" + "runtime" + "strconv" + "strings" + "syscall" + "os/signal" + "encoding/json" "github.com/spf13/cobra" - postfixlog "github.com/youyo/postfix-log-parser" + "github.com/tabalt/pidfile" + postfixlog "github.com/yo000/postfix-log-parser" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promauto" + "github.com/prometheus/client_golang/prometheus/promhttp" ) func init() {} @@ -22,115 +35,843 @@ type ( QueueId string `json:"queue_id"` ClientHostname string `json:"client_hostname"` ClinetIp string `json:"client_ip"` + SaslMethod string `json:"sasl_method"` + SaslUsername string `json:"sasl_username"` MessageId string `json:"message_id"` From string `json:"from"` - Messages []Message `json:"messages"` + Size string `json:"size"` + NRcpt string `json:"nrcpt"` + Nrcpti int `json:"-"` + Messages Messages `json:"messages"` } + Messages []Message + Message struct { - Time *time.Time `json:"time"` - To string `json:"to"` - Status string `json:"status"` - Message string `json:"message"` + Time *time.Time `json:"time"` + To string `json:"to"` + Status string `json:"status"` + Message string `json:"message"` + BounceId string `json:"bounce_id"` + } + + PostfixLogParserFlat struct { + Time *time.Time `json:"time"` + Hostname string `json:"hostname"` + Process string `json:"process"` + QueueId string `json:"queue_id"` + ClientHostname string `json:"client_hostname"` + ClinetIp string `json:"client_ip"` + SaslMethod string `json:"sasl_method"` + SaslUsername string `json:"sasl_username"` + MessageId string `json:"message_id"` + From string `json:"from"` + Size string `json:"size"` + NRcpt string `json:"nrcpt"` + TimeSent *time.Time `json:"time_sent"` + To string `json:"to"` + Status string `json:"status"` + Message string `json:"message"` + BounceId string `json:"bounce_id"` } ) -func NewCmdRoot() *cobra.Command { - cmd := &cobra.Command{ +var ( + File os.File + Writer *bufio.Writer + + Version = "1.4.7" + + BuildInfo = promauto.NewGaugeVec(prometheus.GaugeOpts{ + Name: "postfixlogparser_build_info", + Help: "Constant 1 value labeled by version and goversion from which postfix-log-parser was built", + }, []string{"version", "goversion"}) + StartTime = promauto.NewGauge(prometheus.GaugeOpts{ + Name: "postfixlogparser_time_start_seconds", + Help: "Process start time in UNIX timestamp (seconds)", + }) + LineReadCnt = promauto.NewCounter(prometheus.CounterOpts{ + Name: "postfixlogparser_line_read_count", + Help: "Number of lines read", + }) + LineIncorrectCnt = promauto.NewCounter(prometheus.CounterOpts{ + Name: "postfixlogparser_line_incorrect_count", + Help: "Number of lines with incorrect format", + }) + LineOutCnt = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "postfixlogparser_line_out_count", + Help: "Number of lines written to ouput", + }, []string{"host"}) + MsgInCnt = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "postfixlogparser_msg_in_count", + Help: "Number of mails accepted by smtpd", + }, []string{"host"}) + MsgSentCnt = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "postfixlogparser_msg_sent_count", + Help: "Number of mails sent", + }, []string{"host"}) + MsgDeferredCnt = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "postfixlogparser_msg_deferred_count", + Help: "Number of mails deferred", + }, []string{"host"}) + MsgBouncedCnt = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "postfixlogparser_msg_bounced_count", + Help: "Number of mails bounced", + }, []string{"host"}) + MsgRejectedCnt = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "postfixlogparser_msg_rejected_count", + Help: "Number of mails rejected", + }, []string{"host"}) + MsgHoldCnt = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "postfixlogparser_msg_hold_count", + Help: "Number of mails hold", + }, []string{"host"}) + MsgAuthFailed = promauto.NewCounterVec(prometheus.CounterOpts{ + Name: "postfixlogparser_auth_failed_count", + Help: "Number of failed authentications", + }, []string{"host"}) + ConnectedClientCnt = promauto.NewGauge(prometheus.GaugeOpts{ + Name: "postfixlogparser_client_count", + Help: "Number of connected clients", + }) + + rootCmd = &cobra.Command{ Use: "postfix-log-parser", - Short: "Parse postfix log, and output json format", + Short: "Postfix Log Parser v" + Version + ". Parse postfix log, and output json format", //Long: ``, Run: func(cmd *cobra.Command, args []string) { + processLogs(cmd, args) + }, + } + + gShowRegex bool + gFlatten bool + gOutputFile string + gPidFilePath string + gSyslogListenAddress string + gPromListenAddress string + gPromMetricPath string +) + + +func (p *PostfixLogParser) Copy() PostfixLogParser { + var nm []Message + + for _, m := range p.Messages { + nm = append(nm, m) + } + + return PostfixLogParser{ + Time: p.Time, + Hostname: p.Hostname, + Process: p.Process, + QueueId: p.QueueId, + ClientHostname: p.ClientHostname, + ClinetIp: p.ClinetIp, + SaslMethod: p.SaslMethod, + SaslUsername: p.SaslUsername, + MessageId: p.MessageId, + From: p.From, + Size: p.Size, + NRcpt: p.NRcpt, + Nrcpti: p.Nrcpti, + Messages: nm, + } +} + +func (m *Messages) GetByRecipient(recipient string) (*Message, int, error) { + for i, msg := range *m { + if strings.EqualFold(msg.To, recipient) { + return &msg, i, nil + } + } + return &Message{}, -1, fmt.Errorf("Not found") +} + - // create queue - m := make(map[string]*PostfixLogParser) +func Execute() { + if err := rootCmd.Execute(); err != nil { + rootCmd.SetOutput(os.Stderr) + rootCmd.Println(err) + os.Exit(1) + } +} - // initialize - p := postfixlog.NewPostfixLog() +func PlpToFlat(plp *PostfixLogParser) []PostfixLogParserFlat { + var plpf = make([]PostfixLogParserFlat, len(plp.Messages)) - // writer - wtr := bufio.NewWriter(os.Stdout) + for i := range plp.Messages { + plpf[i] = PostfixLogParserFlat{ + Time: plp.Time, + Hostname: plp.Hostname, + Process: plp.Process, + QueueId: plp.QueueId, + ClientHostname: plp.ClientHostname, + ClinetIp: plp.ClinetIp, + SaslMethod: plp.SaslMethod, + SaslUsername: plp.SaslUsername, + MessageId: plp.MessageId, + From: plp.From, + Size: plp.Size, + // PlpToFlat make 1 json object per message, so we need to override NRcpt + //NRcpt: plp.NRcpt, + NRcpt: "1", + TimeSent: plp.Messages[i].Time, + To: plp.Messages[i].To, + Status: plp.Messages[i].Status, + Message: plp.Messages[i].Message, + BounceId: plp.Messages[i].BounceId, + } + } - // input stdin - scanner := bufio.NewScanner(os.Stdin) - for scanner.Scan() { + return plpf +} - // parse log - logFormat, err := p.Parse(scanner.Bytes()) +func NewWriter(file string) (*bufio.Writer, *os.File, error) { + if len(file) > 0 { + var f *os.File + var err error + if _, err = os.Stat(file); err == nil { + f, err = os.OpenFile(file, os.O_APPEND|os.O_WRONLY, 0640) + } else if os.IsNotExist(err) { + f, err = os.OpenFile(file, os.O_CREATE|os.O_WRONLY, 0640) + } + if err != nil { + return nil, nil, err + } + Writer = bufio.NewWriter(f) + return Writer, f, nil + } else { + Writer = bufio.NewWriter(os.Stdout) + return Writer, nil, nil + } +} + +func writeOut(msg string) error { + _, err := fmt.Fprintln(Writer, msg) + Writer.Flush() + if err != nil { + return err + } + + var tmpPlp PostfixLogParser + json.Unmarshal([]byte(msg), &tmpPlp) + LineOutCnt.WithLabelValues(tmpPlp.Hostname).Inc() + + return nil +} + + +// Remove sent, milter-rejected and deferred that entered queue more than "duration" ago +func cleanMQueue(mqueue map[string]*PostfixLogParser, mqMtx *sync.Mutex, age time.Duration) { + var ok int + + log.Printf("Start cleaning queue task: %d items in queue", len(mqueue)) + + // We need read lock: fatal error: concurrent map iteration and map write + mqMtx.Lock() + for qid, inmail := range mqueue { + ok = 0 + // Check all mails were sent (multiple destinations mails) + for _, outmail := range inmail.Messages { + // Sent and Rejected mails won't have any other event, we can rm + if outmail.Status == "sent" || outmail.Status == "milter-reject" || outmail.Status == "postfix-reject" { + ok += 1 + } else if outmail.Status == "deferred" { + if inmail.Time.Add(age).Before(time.Now()) { + ok += 1 + } + } + } + + if ok == len(inmail.Messages) { + // We already in rw lock + delete(mqueue, qid) + } + } + mqMtx.Unlock() + log.Printf("Finished cleaning queue task: %d items in queue", len(mqueue)) +} + + +// Every 24H, remove sent, milter-rejected and deferred that entered queue more than 5 days ago +func periodicallyCleanMQueue(mqueue map[string]*PostfixLogParser, mqMtx *sync.Mutex) { + for range time.Tick(time.Hour * 24) { + cleanMQueue(mqueue, mqMtx, 5 * 24 * time.Hour) + } +} + + +func initConfig() {} + +func init() { + rootCmd.Version = Version + + rootCmd.Flags().BoolVarP(&gShowRegex, "regex", "r", false, "Show parsing regex then exit") + rootCmd.Flags().BoolVarP(&gFlatten, "gFlatten", "f", false, "Flatten output for using with syslog") + rootCmd.Flags().StringVarP(&gOutputFile, "out", "o", "", "Output to file, append if exists") + rootCmd.Flags().StringVarP(&gPidFilePath, "pidfile", "p", "", "pid file path") + rootCmd.Flags().StringVarP(&gSyslogListenAddress, "syslog.listen-address", "s", "do-not-listen", "Address to listen on for syslog incoming messages. Default is to parse stdin") + rootCmd.Flags().StringVarP(&gPromListenAddress, "prom.listen-address", "l", "do-not-listen", "Address to listen on for prometheus metrics") + rootCmd.Flags().StringVarP(&gPromMetricPath, "prom.telemetry-path", "m", "/metrics", "Path under which to expose metrics.") + + cobra.OnInitialize(initConfig) +} + +/* + * This is the function doing the work. + * Each input is stored in a map, + * then written to output when we recognize it as the last line + */ +func parseStoreAndWrite(input []byte, mq map[string]*PostfixLogParser, mqMtx *sync.Mutex, outfMtx *sync.Mutex, p *postfixlog.PostfixLog) error { + + logFormat, err := p.Parse(input) + if err != nil { + // Incorrect line, just skip it + if err.Error() == "Error: Line do not match regex" { + LineIncorrectCnt.Inc() + return err + } + return err + } + + /************************************************* + * + * First process one line messages, as we dont + * need to store them + * + ************************************************/ + /* + * 2025-02-13T12:44:28.836533+01:00 srv-smtp postfix/smtpd[65735] warning: Message delivery request rate limit exceeded: 19 from unknown[41.42.43.44] for service smtp + */ + // A postfix-ratelimit message is not queued, we just write and forget + if strings.EqualFold(logFormat.Status, "postfix-ratelimit") { + MsgRejectedCnt.WithLabelValues(logFormat.Hostname).Inc() + message := Message{ + Time: logFormat.Time, + Status: logFormat.Status, + Message: logFormat.Message, + } + + tmpplp := PostfixLogParser{ + Time: logFormat.Time, + Hostname: logFormat.Hostname, + Process: logFormat.Process, + ClientHostname: logFormat.ClientHostname, + ClinetIp: logFormat.ClinetIp, + } + tmpplp.Messages = append(tmpplp.Messages, message) + + var jsonBytes []byte + if gFlatten { + jsonBytes, err = json.Marshal(PlpToFlat(&tmpplp)[0]) + } else { + jsonBytes, err = json.Marshal(tmpplp) + } + if err != nil { + log.Fatal(err) + } + outfMtx.Lock() + err = writeOut(string(jsonBytes)) + outfMtx.Unlock() + if err != nil { + log.Fatal(err) + } + + return nil + } + + /* + * 2022-06-29T10:55:18.498553+02:00 srv-smtp-01.domain.com postfix/smtpd[75994] warning: unknown[10.11.12.13]: SASL LOGIN authentication failed: authentication failure + */ + // An auth failed message is not queued, we just write and forget + if strings.EqualFold(logFormat.Status, "auth-failed") { + MsgAuthFailed.WithLabelValues(logFormat.Hostname).Inc() + message := Message{ + Time: logFormat.Time, + Status: logFormat.Status, + Message: logFormat.Message, + } + + tmpplp := PostfixLogParser{ + Time: logFormat.Time, + Hostname: logFormat.Hostname, + Process: logFormat.Process, + ClientHostname: logFormat.ClientHostname, + ClinetIp: logFormat.ClinetIp, + SaslMethod: logFormat.SaslMethod, + } + tmpplp.Messages = append(tmpplp.Messages, message) + + var jsonBytes []byte + if gFlatten { + jsonBytes, err = json.Marshal(PlpToFlat(&tmpplp)[0]) + } else { + jsonBytes, err = json.Marshal(tmpplp) + } + if err != nil { + log.Fatal(err) + } + outfMtx.Lock() + err = writeOut(string(jsonBytes)) + outfMtx.Unlock() + if err != nil { + log.Fatal(err) + } + + return nil + } + + // postfix-filter : We don't store message, only increment nrcpt and add recipient. + // postfix-filter is a transitional state : mail will either be sent, or milter-rejected + // check if queue_id already exist. Check if queue_id already exist. If so, +1 to Nrcpt and add recipient to list + if strings.EqualFold(logFormat.Status, "postfix-filter") { + mqMtx.Lock() + message := Message{ + Time: logFormat.Time, + To: logFormat.To, + Status: logFormat.Status, + Message: logFormat.Message, + BounceId: "", + } + if plp, ok := mq[logFormat.QueueId]; ok { + nplp := plp.Copy() + if len(nplp.From) == 0 { + nplp.From = logFormat.From + } + if len(nplp.ClientHostname) == 0 { + nplp.ClientHostname = logFormat.ClientHostname + } + if len(nplp.ClinetIp) == 0 { + nplp.ClinetIp = logFormat.ClinetIp + } + nplp.Messages = append(nplp.Messages, message) + nplp.Nrcpti++ + nplp.NRcpt = strconv.Itoa(nplp.Nrcpti) + mq[logFormat.QueueId] = &nplp + } else { + nplp := &PostfixLogParser{ + Time: logFormat.Time, + Hostname: logFormat.Hostname, + Process: logFormat.Process, + QueueId: logFormat.QueueId, + ClientHostname: logFormat.ClientHostname, + ClinetIp: logFormat.ClinetIp, + SaslMethod: logFormat.SaslMethod, + SaslUsername: logFormat.SaslUsername, + From: logFormat.From, + Nrcpti: 1, + NRcpt: "1", + } + nplp.Messages = append(nplp.Messages, message) + mq[logFormat.QueueId] = nplp + } + mqMtx.Unlock() + + return nil + } + + /* + Oct 10 04:02:02 mail.example.com postfix/smtpd[22941]: DFBEFDBF00C5: client=example.net[127.0.0.1], sasl_method=PLAIN, sasl_username=user@example.com + */ + if logFormat.ClientHostname != "" && !strings.HasPrefix(logFormat.Message, "milter-reject:") { + mqMtx.Lock() + mq[logFormat.QueueId] = &PostfixLogParser{ + Time: logFormat.Time, + Hostname: logFormat.Hostname, + Process: logFormat.Process, + QueueId: logFormat.QueueId, + ClientHostname: logFormat.ClientHostname, + ClinetIp: logFormat.ClinetIp, + SaslMethod: logFormat.SaslMethod, + SaslUsername: logFormat.SaslUsername, + } + mqMtx.Unlock() + } + + /* + Oct 10 04:02:02 mail.example.com postfix/cleanup[22923]: DFBEFDBF00C5: message-id=<20181009190202.81363306015D@example.com> + */ + if logFormat.MessageId != "" { + mqMtx.Lock() + if plp, ok := mq[logFormat.QueueId]; ok { + plp.MessageId = logFormat.MessageId + } + mqMtx.Unlock() + } + + /* + Oct 10 04:02:03 mail.example.com postfix/qmgr[18719]: DFBEFDBF00C5: from=, size=3578, nrcpt=1 (queue active) + or + 2021-02-06T10:57:58+01:00 mail.server.com postfix/cleanup[59586]: D6DDA23B0F: milter-reject: END-OF-MESSAGE from unknown[99.88.77.66]: 4.7.1 Greylisting in action, try again later; from= to= proto=ESMTP helo= + */ + if logFormat.From != "" { + mqMtx.Lock() + if plp, ok := mq[logFormat.QueueId]; ok { + plp.From = logFormat.From + if logFormat.Size != "" { + plp.Size = logFormat.Size + } + // Do not handle NRcpt here, it will be done next block + } + mqMtx.Unlock() + nrcpt, _ := strconv.ParseFloat(logFormat.NRcpt, 64) + MsgInCnt.WithLabelValues(logFormat.Hostname).Add(nrcpt) + } + + /* + Oct 10 04:02:08 mail.example.com postfix/smtp[22928]: DFBEFDBF00C5: to=, relay=mail.example-to.com[192.168.0.10]:25, delay=5.3, delays=0.26/0/0.31/4.7, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C598F1B0002D) + or + 2025-03-15T11:10:11.206043+01:00 mail.example.com postfix/cleanup[58145] 53AEC4F144: milter-reject: END-OF-MESSAGE from unknown[1.2.3.4]: 4.7.1 Ratelimit "to_ip_from" exceeded; from= to= proto=ESMTP helo= + */ + //if logFormat.To != "" { + if logFormat.To != "" { + mqMtx.Lock() + if plp, ok := mq[logFormat.QueueId]; ok { + message := Message{ + Time: logFormat.Time, + To: logFormat.To, + Status: logFormat.Status, + Message: logFormat.Message, + BounceId: "", + } + /* When a message is deferred, it won't be written out until it is either sent, expired, or generates a non delivery notification. + We want to know instantly when a message is deferred, so we handle this case by emiting output for this message, and not appending this occurence + to the list of Messages + */ + if logFormat.Status == "deferred" { + MsgDeferredCnt.WithLabelValues(plp.Hostname).Inc() + tmpplp := PostfixLogParser{ + Time: plp.Time, + Hostname: plp.Hostname, + Process: plp.Process, + QueueId: plp.QueueId, + ClientHostname: plp.ClientHostname, + ClinetIp: plp.ClinetIp, + SaslMethod: plp.SaslMethod, + SaslUsername: plp.SaslUsername, + MessageId: plp.MessageId, + From: plp.From, + Size: plp.Size, + // Could it be > 1 ? + NRcpt: "1", + } + tmpplp.Messages = append(tmpplp.Messages, message) + + var jsonBytes []byte + if gFlatten { + jsonBytes, err = json.Marshal(PlpToFlat(&tmpplp)[0]) + } else { + jsonBytes, err = json.Marshal(tmpplp) + } if err != nil { - cmd.SetOutput(os.Stderr) - cmd.Println(err) - os.Exit(1) + log.Fatal(err) + } + outfMtx.Lock() + err = writeOut(string(jsonBytes)) + outfMtx.Unlock() + if err != nil { + log.Fatal(err) + } + tmpplp.Messages = nil + // cannot use nil as type PostfixLogParser in assignment + //tmpplp = nil + } else { + _, i, err := plp.Messages.GetByRecipient(logFormat.To) + if err != nil && strings.EqualFold(err.Error(), "Not found") { + plp.Messages = append(plp.Messages, message) + plp.Nrcpti++ + plp.NRcpt = strconv.Itoa(plp.Nrcpti) + } else { + plp.Messages[i] = message } + } + } + mqMtx.Unlock() + } - /* - Oct 10 04:02:02 mail.example.com postfix/smtpd[22941]: DFBEFDBF00C5: client=example.net[127.0.0.1] - */ - if logFormat.ClientHostname != "" { - m[logFormat.QueueId] = &PostfixLogParser{ - Time: logFormat.Time, - Hostname: logFormat.Hostname, - Process: logFormat.Process, - QueueId: logFormat.QueueId, - ClientHostname: logFormat.ClientHostname, - ClinetIp: logFormat.ClinetIp, + /* + 2021-02-05T17:25:03+01:00 mail.example.com postfix/bounce[39258]: 006B056E6: sender non-delivery notification: 642E456E9 + */ + if logFormat.BounceId != "" { + mqMtx.Lock() + if plp, ok := mq[logFormat.QueueId]; ok { + // Get the matching Message by Status=bounced + for i, msg := range plp.Messages { + // Need to manage more than one bounce for the same queue_id. This is flawy as we just rely on order to match + if msg.Status == "bounced" && len(msg.BounceId) == 0 { + message := Message{ + Time: msg.Time, + To: msg.To, + Status: msg.Status, + Message: msg.Message, + BounceId: logFormat.BounceId, } + // Delete old message, put new at the end + copy(plp.Messages[i:], plp.Messages[i+1:]) + plp.Messages[len(plp.Messages)-1] = message + break } + } + } + mqMtx.Unlock() + } - /* - Oct 10 04:02:02 mail.example.com postfix/cleanup[22923]: DFBEFDBF00C5: message-id=<20181009190202.81363306015D@example.com> - */ - if logFormat.MessageId != "" { - if plp, ok := m[logFormat.QueueId]; ok { - plp.MessageId = logFormat.MessageId - } + // milter-reject reject message for all recipient, so we need to update status for every message + if logFormat.Status == "milter-reject" { + mqMtx.Lock() + if plp, ok := mq[logFormat.QueueId]; ok { + for i, _ := range plp.Messages { + plp.Messages[i].Time = logFormat.Time + plp.Messages[i].Status = logFormat.Status + // FIXME: We override message, but the originating mesage from postfix log could be wrong as it have the last recipient in "to=<>" + // and we don't want to insert manipulated log line + // Would it be better to clear message? or leave previous one which could be unrelated to the postfix decision? eg: + // "filter: RCPT from unknown[192.168.0.22]: : Recipient address triggers FILTER relay:[pod-02.smtpout.exploit.intra]; from= to= proto=ESMTP helo=" + plp.Messages[i].Message = logFormat.Message + } + } else { + // TODO : error case : milter reject for unknown message ?! + } + mqMtx.Unlock() + } + + /* + Oct 10 04:02:08 mail.example.com postfix/qmgr[18719]: DFBEFDBF00C5: removed + or + 2021-02-05T14:17:51+01:00 smtp.server.com postfix/cleanup[38982]: D8C136A3A: milter-reject: END-OF-MESSAGE from unknown[1.2.3.4]: 4.7.1 Greylisting in action, try again later; from= to= proto=ESMTP helo= + or + 2023-12-22T09:11:42.627010+01:00 smtp-02.example.org postfix/smtpd[2717] 6CB5F45B78: reject: RCPT from unknown[11.12.13.14]: 450 4.1.2 : Recipient address rejected: Domain not found; from= to= proto=ESMTP helo= + */ + // "removed" message is end of logs. then flush. + if logFormat.Message == "removed" || strings.HasPrefix(logFormat.Status, "milter-") || strings.EqualFold(logFormat.Status, "postfix-reject") { + mqMtx.Lock() + if plp, ok := mq[logFormat.QueueId]; ok { + for _, plpf := range PlpToFlat(plp) { + switch plpf.Status { + case "sent": + MsgSentCnt.WithLabelValues(plpf.Hostname).Inc() + case "milter-reject", "postfix-reject": + MsgRejectedCnt.WithLabelValues(plpf.Hostname).Inc() + case "milter-hold": + MsgHoldCnt.WithLabelValues(plpf.Hostname).Inc() + case "bounced": + MsgBouncedCnt.WithLabelValues(plpf.Hostname).Inc() } - /* - Oct 10 04:02:03 mail.example.com postfix/qmgr[18719]: DFBEFDBF00C5: from=, size=3578, nrcpt=1 (queue active) - */ - if logFormat.From != "" { - if plp, ok := m[logFormat.QueueId]; ok { - plp.From = logFormat.From + if gFlatten { + jsonBytes, err := json.Marshal(plpf) + if err != nil { + log.Fatal(err) + } + outfMtx.Lock() + err = writeOut(string(jsonBytes)) + outfMtx.Unlock() + if err != nil { + log.Fatal(err) } } + } - /* - Oct 10 04:02:08 mail.example.com postfix/smtp[22928]: DFBEFDBF00C5: to=, relay=mail.example-to.com[192.168.0.10]:25, delay=5.3, delays=0.26/0/0.31/4.7, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C598F1B0002D) - */ - if logFormat.To != "" { - if plp, ok := m[logFormat.QueueId]; ok { - message := Message{ - Time: logFormat.Time, - To: logFormat.To, - Status: logFormat.Status, - Message: logFormat.Messages, - } - - plp.Messages = append(plp.Messages, message) - } + if !gFlatten { + jsonBytes, err := json.Marshal(plp) + if err != nil { + log.Fatal(err) + } + outfMtx.Lock() + err = writeOut(string(jsonBytes)) + outfMtx.Unlock() + if err != nil { + log.Fatal(err) } + } + } + mqMtx.Unlock() + } - /* - Oct 10 04:02:08 mail.example.com postfix/qmgr[18719]: DFBEFDBF00C5: removed - */ - // "removed" message is end of logs. then flush. - if logFormat.Messages == "removed" { - if plp, ok := m[logFormat.QueueId]; ok { - jsonBytes, err := json.Marshal(plp) - if err != nil { - log.Fatal(err) - } - - fmt.Fprintln(wtr, string(jsonBytes)) - wtr.Flush() - } + return nil +} + +func scanAndProcess(scanner *bufio.Scanner, isStdin bool, conn net.Conn, mQueue map[string]*PostfixLogParser, + mqMtx *sync.Mutex, outfMtx *sync.Mutex, p *postfixlog.PostfixLog) error { + for { + // If input is made via TCP Conn, we need to read from a connected net.Conn + if scanner == nil || (isStdin == false && conn == nil) { + return errors.New("Invalid input") + } + + if false == scanner.Scan() { + // After Scan returns false, the Err method will return any error that occurred during scanning, except that if it was io.EOF, Err will return nil + if err := scanner.Err(); err != nil { + log.Printf("Error reading data: %v\n", err.Error()) + } + if isStdin == false { + log.Printf("No more data, closing connection.\n") + // Should we? + conn.Close() + } + // input is dead, abort mission! + return errors.New("Read error") + } + // Extend timeout after successful read (so we got an idle timeout) + if isStdin == false && conn != nil { + conn.SetReadDeadline(time.Now().Add(time.Duration(600) * time.Second)) + } + + LineReadCnt.Inc() + + read := scanner.Bytes() + err := parseStoreAndWrite(read, mQueue, mqMtx, outfMtx, p) + if err != nil { + if err.Error() != "Error: Line do not match regex" { + return err + } else { + log.Printf("input do not match regex: %s\n", string(read)) + } + } + } + return nil +} + +func processLogs(cmd *cobra.Command, args []string) { + //var scanner *bufio.Scanner + var listener net.Listener + // Output file mutex + var outfMtx sync.Mutex + // mQueue mutex + var mqMtx sync.Mutex + var useStdin bool + + if gShowRegex == true { + fmt.Printf("%s\n", postfixlog.RegexpFormat) + return + } + + // create map of messages + mQueue := make(map[string]*PostfixLogParser) + + BuildInfo.WithLabelValues(Version, runtime.Version()).Set(1) + StartTime.Set(float64(time.Now().Unix())) + + // Prometheus exporter + if gPromListenAddress != "do-not-listen" { + go func() { + http.Handle(gPromMetricPath, promhttp.Handler()) + http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) { + w.Write([]byte(` + + Postfix-log-parser Exporter + +

Postfix-log-parser Exporter

+

Metrics

+ + `)) + }) + log.Fatal(http.ListenAndServe(gPromListenAddress, nil)) + }() + } + + // Create PID file + if len(gPidFilePath) > 0 { + if pid, err := pidfile.Create(gPidFilePath); err != nil { + log.Fatal(err) + } else { + defer pid.Clear() + } + } + + // initialize + p := postfixlog.NewPostfixLog() + + // Get a writer, file or stdout + _, File, err := NewWriter(gOutputFile) + if err != nil { + cmd.SetOutput(os.Stderr) + cmd.Println(err) + os.Exit(1) + } + + // Manage output file rotation when receiving SIGUSR1 + if len(gOutputFile) > 0 { + sig := make(chan os.Signal) + signal.Notify(sig, syscall.SIGUSR1) + go func() { + for { + <-sig + outfMtx.Lock() + fmt.Println("SIGUSR1 received, recreating output file") + File.Close() + _, File, err = NewWriter(gOutputFile) + if err != nil { + outfMtx.Unlock() + cmd.SetOutput(os.Stderr) + cmd.Println(err) + os.Exit(1) } + outfMtx.Unlock() + } + }() + } + + // Cleaner thread + go periodicallyCleanMQueue(mQueue, &mqMtx) + + // On demand Mqueue cleaning... For debug, dont try this at home, kids! +/* sig2 := make(chan os.Signal) + signal.Notify(sig2, syscall.SIGUSR2) + go func() { + for { + <-sig2 + cleanMQueue(mQueue, &mqMtx, 1 * time.Hour) + } + }() +*/ + // On demand queue dump +/* sig2 := make(chan os.Signal) + signal.Notify(sig2, syscall.SIGUSR2) + go func() { + for { + <-sig2 + fmt.Printf("Dump current in-ram queue. Length: %d\n", len(mQueue)) + + fmt.Printf("%v\n", mQueue) + mqMtx.Lock() + for k, v := range mQueue { + fmt.Printf("%v: %v\n", k, v) } - }, + mqMtx.Unlock() + } + }() +*/ + // Initialize Stdin input... + if true == strings.EqualFold(gSyslogListenAddress, "do-not-listen") { + useStdin = true + scanner := bufio.NewScanner(os.Stdin) + scanAndProcess(scanner, useStdin, nil, mQueue, &mqMtx, &outfMtx, p) + // ...or manages incoming connections + } else { + listener, err = net.Listen("tcp", gSyslogListenAddress) + if err != nil { + log.Fatal(fmt.Sprintf("Error listening on %s: %v\n", gSyslogListenAddress, err)) + } + for { + connClt, err := listener.Accept() + if err != nil { + log.Printf("Error accepting: %v", err) + // Loop + continue + } + scanner := bufio.NewScanner(connClt) + ConnectedClientCnt.Inc() + go scanAndProcess(scanner, useStdin, connClt, mQueue, &mqMtx, &outfMtx, p) + ConnectedClientCnt.Dec() + } } - cobra.OnInitialize(initConfig) - return cmd + if File != nil { + outfMtx.Lock() + File.Close() + outfMtx.Unlock() + } } diff --git a/postfix-log-parser/main.go b/postfix-log-parser/main.go index b37ca2b..8cc0a71 100644 --- a/postfix-log-parser/main.go +++ b/postfix-log-parser/main.go @@ -20,7 +20,7 @@ package main -import "github.com/youyo/postfix-log-parser/postfix-log-parser/cmd" +import "github.com/yo000/postfix-log-parser/postfix-log-parser/cmd" func main() { cmd.Execute() diff --git a/test/test-iso8601.log b/test/test-iso8601.log index 433315f..a9912b5 100644 --- a/test/test-iso8601.log +++ b/test/test-iso8601.log @@ -20,3 +20,44 @@ 2020-01-30T06:26:08.404714+09:00 mail postfix/qmgr[18719]: 6526CDB7400B: removed 2020-01-30T06:26:09.404714+09:00 mail postfix/smtp[1874]: C6E0DDB74006: to=, relay=example.ddd[192.168.0.30]:25, delay=3.4, delays=0.11/0/0.38/2.9, dsn=2.0.0, status=sent (250 2.0.0 OK 1539154772 az9-v6si5976496plb.190 - gsmtp) 2020-01-30T06:26:09.404714+09:00 mail postfix/qmgr[18719]: C6E0DDB74006: removed +2021-02-06T10:57:57+01:00 mail.server.com postfix/smtpd[59633]: D6DDA23B0F: client=unknown[99.88.77.66] +2021-02-06T10:57:57+01:00 mail.server.com postfix/cleanup[59586]: D6DDA23B0F: message-id=<20210206095814.2B34E19A19F6@host.sender.domain> +2021-02-06T10:57:58+01:00 mail.server.com postfix/cleanup[59586]: D6DDA23B0F: milter-reject: END-OF-MESSAGE from unknown[99.88.77.66]: 4.7.1 Greylisting in action, try again later; from= to= proto=ESMTP helo= +2021-02-06T09:58:59.184925+01:00 mail.server.com postfix/submission/smtpd[99525] 2D19728491: client=unknown[10.11.12.13], sasl_method=PLAIN, sasl_username=user1@domain.example.com +2021-02-06T09:58:59.194384+01:00 mail.server.com postfix/cleanup[7821] 2D19728491: replace: header Received: from localhost (unknown [10.11.12.13])??(using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits)?? key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256)??(N from unknown[10.11.12.13]; from= to= proto=ESMTP helo=: Received: from localhost (unknown [10.11.12.13])??(using TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits)?? key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256)??(No client certificate requested)??(Authenticated sender: user1)??by mail.server.com (Postfix) with ESMTPSA id 2D19728491??for ; Sat, 6 Feb 2021 09:58:49 +0100 (CET) +2021-02-06T09:58:59.194419+01:00 mail.server.com postfix/cleanup[7821] 2D19728491: message-id=<1612601937133741374.16589280196177750880@user1.domain.example.com> +2021-02-06T09:58:59.401801+01:00 mail.server.com postfix/qmgr[9086] 2D19728491: from=, size=11991, nrcpt=1 (queue active) +2021-02-06T09:58:59.560624+01:00 mail.server.com postfix/smtp[8160] 2D19728491: to=, relay=mail2.domain.com[2b00:128:64::1]:25, delay=9.7, delays=9.5/0.01/0.03/0.12, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 702A02A5BF) +2021-02-06T09:58:59.560956+01:00 mail.server.com postfix/qmgr[9086] 2D19728491: removed +2021-02-06T11:19:18.130932+01:00 mail2.server.com postfix/smtpd[61691] 1FEE23DED3: client=unknown[2b00:128:64::42] +2021-02-06T11:19:18.131299+01:00 mail2.server.com postfix/cleanup[51214] 1FEE23DED3: message-id=<20210206101916.672CC1B4E5@sender.example.com> +2021-02-06T11:19:18.132307+01:00 mail2.server.com postfix/qmgr[10190] 1FEE23DED3: from=<>, size=22738, nrcpt=1 (queue active) +2021-02-06T11:19:18.189624+01:00 mail2.server.com postfix/smtp[63135] 1FEE23DED3: to=, relay=relay.domain.com[22.33.44.55]:25, delay=0.06, delays=0/0/0.05/0.01, dsn=5.7.1, status=bounced (host relay.domain.com[22.33.44.55] said: 554 5.7.1 : Relay access denied (in reply to RCPT TO command)) +2021-02-06T11:19:18.190959+01:00 mail2.server.com postfix/qmgr[10190] 1FEE23DED3: removed +2021-02-06T11:19:25+01:00 mail1.example.com postfix/smtpd[64346]: 42E683DD0B: client=mail.sender.com[85.42.66.4] +2021-02-06T11:19:25+01:00 mail1.example.com postfix/cleanup[64327]: 42E683DD0B: message-id=<0tgs2nv56aexq9wn-dz6hijmzyfbesxxz-bcd8-493db@some.com> +2021-02-06T11:19:25+01:00 mail1.example.com postfix/qmgr[31205]: 42E683DD0B: from=<18546-55426-655542-8520-recipient1=sender1@mail.some.com>, size=8703, nrcpt=1 (queue active) +2021-02-06T11:19:26+01:00 mail1.example.com postfix/smtp[63622]: 42E683DD0B: to=, relay=aspmx.l.google.com[2a00:1450:400c:c04::1b]:25, delay=0.59, delays=0.23/0/0.17/0.19, dsn=5.7.26, status=bounced (host aspmx.l.google.com[2a00:1450:400c:c04::1b] said: 550-5.7.26 This message does not have authentication information or fails to 550-5.7.26 pass authentication checks. To best protect our users from spam, the 550-5.7.26 message has been blocked. Please visit 550-5.7.26 https://support.google.com/mail/answer/81126#authentication for more 550 5.7.26 information. a42si85499772wrx.219 - gsmtp (in reply to end of DATA command)) +2021-02-06T11:19:26+01:00 mail1.example.com postfix/bounce[64352]: 42E683DD0B: sender non-delivery notification: 1F99E4BC9A +2021-02-06T11:19:26+01:00 mail1.example.com postfix/qmgr[31205]: 42E683DD0B: removed +2021-02-20T13:18:56+01:00 srv-smtp postfix/smtpd[63060]: 9ABCD1BCA9: client=mailout.domain.com[10.11.12.13] +2021-02-20T13:18:56+01:00 srv-smtp postfix/cleanup[62622]: 9ABCD1BCA9: message-id=<20210220121856.17088.40693@internal.domain.lan> +2021-02-20T13:18:56+01:00 srv-smtp postfix/qmgr[28825]: 9ABCD1BCA9: from=, size=5712, nrcpt=1 (queue active) +2021-02-20T13:18:56+01:00 srv-smtp postfix/smtp[62771]: 9ABCD1BCA9: host gmail-smtp-in.l.google.com[74.125.140.27] said: 450-4.2.1 The user you are trying to contact is receiving mail at a rate that 450-4.2.1 prevents additional messages from being delivered. Please resend your 450-4.2.1 message at a later time. If the user is able to receive mail at that 450-4.2.1 time, your message will be delivered. For more information, please 450-4.2.1 visit 450 4.2.1 https://support.google.com/mail/?p=ReceivingRate f22si54329842vxg.12 - gsmtp (in reply to RCPT TO command) +2021-02-20T13:18:57+01:00 srv-smtp postfix/smtp[62771]: 9ABCD1BCA9: to=, relay=gmail-smtp-in.l.google.com[2a00:1450:400c:c02::1b]:25, delay=0.41, delays=0.19/0/0.19/0.03, dsn=4.2.1, status=deferred (host gmail-smtp-in.l.google.com[2a00:1450:400c:c02::1b] said: 450-4.2.1 The user you are trying to contact is receiving mail at a rate that 450-4.2.1 prevents additional messages from being delivered. Please resend your 450-4.2.1 message at a later time. If the user is able to receive mail at that 450-4.2.1 time, your message will be delivered. For more information, please 450-4.2.1 visit 450 4.2.1 https://support.google.com/mail/?p=ReceivingRate f22si54329842vxg.042 - gsmtp (in reply to RCPT TO command)) +2025-02-13T12:44:28.836533+01:00 srv-smtp postfix/smtpd[65735] warning: Message delivery request rate limit exceeded: 19 from unknown[41.42.43.44] for service smtp +2025-03-15T13:30:29.169282+01:00 smtp.example.org postfix/smtpd[17507] warning: hostname smtp.internal.local does not resolve to address 192.168.0.22: Name does not resolve +2025-03-15T13:30:29.169332+01:00 smtp.example.org postfix/smtpd[17507] connect from unknown[192.168.0.22] +2025-03-15T13:30:29.221416+01:00 smtp.example.org postfix/smtpd[17507] Anonymous TLS connection established from unknown[192.168.0.22]: TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits) +2025-03-15T13:30:30.342887+01:00 smtp.example.org postfix/smtpd[17507] 53AEC4F144: client=unknown[192.168.0.22], sasl_method=LOGIN, sasl_username=smtpuser@smtp.example.org +2025-03-15T13:30:30.352537+01:00 smtp.example.org postfix/smtpd[17507] 53AEC4F144: filter: RCPT from unknown[192.168.0.22]: : Recipient address triggers FILTER relay:[pod-02.smtpout.exploit.intra]; from= to= proto=ESMTP helo= +2025-03-15T13:30:30.355033+01:00 smtp.example.org postfix/smtpd[17507] 53AEC4F144: filter: RCPT from unknown[192.168.0.22]: : Recipient address triggers FILTER relay:[pod-02.smtpout.exploit.intra]; from= to= proto=ESMTP helo= +2025-03-15T13:30:30.362445+01:00 smtp.example.org postfix/smtpd[17507] 53AEC4F144: filter: RCPT from unknown[192.168.0.22]: : Recipient address triggers FILTER relay:[pod-02.smtpout.exploit.intra]; from= to= proto=ESMTP helo= +2025-03-15T13:30:31.158051+01:00 smtp.example.org postfix/cleanup[58145] 53AEC4F144: replace: header Received: from smtp.internal.local (unknown [192.168.0.22])??(using TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits))??(No client certificate requested)??(Authenticated sender: smtpuser from unknown[192.168.0.22]; from= to= proto=ESMTP helo=: Received: from smtp.internal.local (unknown [192.168.0.22])??(using TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits))??(No client certificate requested)??(Authenticated sender: anonymized)??by smtp.example.org (Postfix) with ESMTPSA id 53AEC4F144;??Sat, 15 Mar 2025 13:30:29 +0100 (CET) +2025-03-15T13:30:31.158169+01:00 smtp.example.org postfix/cleanup[58145] 53AEC4F144: message-id=<94851c4c5f9b5ef98755296606bf32ab@example.org> +2025-03-15T13:30:31.206043+01:00 smtp.example.org postfix/cleanup[58145] 53AEC4F144: milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit "to_ip_from" exceeded; from= to= proto=ESMTP helo= +2025-03-15T13:30:31.238801+01:00 smtp.example.org postfix/smtpd[17507] disconnect from unknown[192.168.0.22] ehlo=2 starttls=1 auth=1 mail=1 rcpt=4/4 bdat=0/1 rset=1 quit=1 commands=8/10 +2025-03-09T16:41:59.516331+01:00 smtp.example.org postfix/smtpd[78309] connect from unknown[192.168.0.11] +2025-03-09T16:41:59.568868+01:00 smtp.example.org postfix/smtpd[78309] NOQUEUE: reject: RCPT from unknown[192.168.0.11]: 504 5.5.2 : Sender address rejected: need fully-qualified address; from= to= proto=ESMTP helo= +2025-03-09T16:41:59.568892+01:00 smtp.example.org postfix/smtpd[78309] using backwards-compatible default setting smtpd_relay_before_recipient_restrictions=no to reject recipient "recipient@another.domain.com" from client "unknown[192.168.0.11]" +2025-03-09T16:41:59.587032+01:00 smtp.example.org postfix/smtpd[78309] disconnect from unknown[192.168.0.11] ehlo=1 mail=1 rcpt=0/1 quit=1 commands=3/4 diff --git a/test/test-iso8601.log.142.json b/test/test-iso8601.log.142.json new file mode 100644 index 0000000..524c205 --- /dev/null +++ b/test/test-iso8601.log.142.json @@ -0,0 +1,191 @@ +{ + "time": "2020-01-30T06:26:06.404714+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1827]", + "queue_id": "3D74ADB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "f93388828093534f92d85ffe21b2a719@example.info", + "from": "test2@example.info", + "size": "2140", + "nrcpt": "1", + "messages": [ + { + "time": "2020-01-30T06:26:07.404714+09:00", + "to": "test@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + }, + { + "time": "2020-01-30T06:26:07.404714+09:00", + "to": "test2@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + } + ] +} +{ + "time": "2020-01-30T06:26:08.404714+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "6526CDB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "153915476795520900002087@example.aaa", + "from": "test@example.bbb", + "size": "4118", + "nrcpt": "1", + "messages": [ + { + "time": "2020-01-30T06:26:08.404714+09:00", + "to": "test@example.ccc", + "status": "sent", + "message": "to=, relay=example.ccc[192.168.0.10]:25, delay=0.1, delays=0.02/0/0.03/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 71111424269E)", + "bounce_id": "" + } + ] +} +{ + "time": "2020-01-30T06:26:05.404714+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "C6E0DDB74006", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "A40CF64D-7F2D-42E4-8A76-CBFFF64A6EB1@example.com", + "from": "test@example.com", + "size": "309891", + "nrcpt": "1", + "messages": [ + { + "time": "2020-01-30T06:26:09.404714+09:00", + "to": "test@example.ddd", + "status": "sent", + "message": "to=, relay=example.ddd[192.168.0.30]:25, delay=3.4, delays=0.11/0/0.38/2.9, dsn=2.0.0, status=sent (250 2.0.0 OK 1539154772 az9-v6si5976496plb.190 - gsmtp)", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T10:57:57+01:00", + "hostname": "mail.server.com", + "process": "postfix/smtpd[59633]", + "queue_id": "D6DDA23B0F", + "client_hostname": "unknown", + "client_ip": "99.88.77.66", + "sasl_method": "", + "sasl_username": "", + "message_id": "20210206095814.2B34E19A19F6@host.sender.domain", + "from": "user2@example.com", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2021-02-06T10:57:58+01:00", + "to": "some.dest@destdomain.com", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[99.88.77.66]: 4.7.1 Greylisting in action, try again later; from= to= proto=ESMTP helo=", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T09:58:59.184925+01:00", + "hostname": "mail.server.com", + "process": "postfix/submission/smtpd[99525]", + "queue_id": "2D19728491", + "client_hostname": "unknown", + "client_ip": "10.11.12.13", + "sasl_method": "PLAIN", + "sasl_username": "user1@domain.example.com", + "message_id": "1612601937133741374.16589280196177750880@user1.domain.example.com", + "from": "user1@example.com", + "size": "11991", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-06T09:58:59.560624+01:00", + "to": "destuser@destination.com", + "status": "sent", + "message": "to=, relay=mail2.domain.com[2b00:128:64::1]:25, delay=9.7, delays=9.5/0.01/0.03/0.12, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 702A02A5BF)", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T11:19:18.130932+01:00", + "hostname": "mail2.server.com", + "process": "postfix/smtpd[61691]", + "queue_id": "1FEE23DED3", + "client_hostname": "unknown", + "client_ip": "2b00:128:64::42", + "sasl_method": "", + "sasl_username": "", + "message_id": "20210206101916.672CC1B4E5@sender.example.com", + "from": "", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2021-02-06T11:19:18.189624+01:00", + "to": "dest@domain.com", + "status": "bounced", + "message": "to=, relay=relay.domain.com[22.33.44.55]:25, delay=0.06, delays=0/0/0.05/0.01, dsn=5.7.1, status=bounced (host relay.domain.com[22.33.44.55] said: 554 5.7.1 : Relay access denied (in reply to RCPT TO command))", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T11:19:25+01:00", + "hostname": "mail1.example.com", + "process": "postfix/smtpd[64346]", + "queue_id": "42E683DD0B", + "client_hostname": "mail.sender.com", + "client_ip": "85.42.66.4", + "sasl_method": "", + "sasl_username": "", + "message_id": "0tgs2nv56aexq9wn-dz6hijmzyfbesxxz-bcd8-493db@some.com", + "from": "18546-55426-655542-8520-recipient1=sender1@mail.some.com", + "size": "8703", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-06T11:19:26+01:00", + "to": "recipient1@destdom.com", + "status": "bounced", + "message": "to=, relay=aspmx.l.google.com[2a00:1450:400c:c04::1b]:25, delay=0.59, delays=0.23/0/0.17/0.19, dsn=5.7.26, status=bounced (host aspmx.l.google.com[2a00:1450:400c:c04::1b] said: 550-5.7.26 This message does not have authentication information or fails to 550-5.7.26 pass authentication checks. To best protect our users from spam, the 550-5.7.26 message has been blocked. Please visit 550-5.7.26 https://support.google.com/mail/answer/81126#authentication for more 550 5.7.26 information. a42si85499772wrx.219 - gsmtp (in reply to end of DATA command))", + "bounce_id": "1F99E4BC9A" + } + ] +} +{ + "time": "2021-02-20T13:18:56+01:00", + "hostname": "srv-smtp", + "process": "postfix/smtpd[63060]", + "queue_id": "9ABCD1BCA9", + "client_hostname": "mailout.domain.com", + "client_ip": "10.11.12.13", + "sasl_method": "", + "sasl_username": "", + "message_id": "20210220121856.17088.40693@internal.domain.lan", + "from": "user1@domain.com", + "size": "5712", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-20T13:18:57+01:00", + "to": "recipient@gmail.com", + "status": "deferred", + "message": "to=, relay=gmail-smtp-in.l.google.com[2a00:1450:400c:c02::1b]:25, delay=0.41, delays=0.19/0/0.19/0.03, dsn=4.2.1, status=deferred (host gmail-smtp-in.l.google.com[2a00:1450:400c:c02::1b] said: 450-4.2.1 The user you are trying to contact is receiving mail at a rate that 450-4.2.1 prevents additional messages from being delivered. Please resend your 450-4.2.1 message at a later time. If the user is able to receive mail at that 450-4.2.1 time, your message will be delivered. For more information, please 450-4.2.1 visit 450 4.2.1 https://support.google.com/mail/?p=ReceivingRate f22si54329842vxg.042 - gsmtp (in reply to RCPT TO command))", + "bounce_id": "" + } + ] +} diff --git a/test/test-iso8601.log.146.json b/test/test-iso8601.log.146.json new file mode 100644 index 0000000..5d33b31 --- /dev/null +++ b/test/test-iso8601.log.146.json @@ -0,0 +1,214 @@ +{ + "time": "2020-01-30T06:26:06.404714+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1827]", + "queue_id": "3D74ADB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "f93388828093534f92d85ffe21b2a719@example.info", + "from": "test2@example.info", + "size": "2140", + "nrcpt": "1", + "messages": [ + { + "time": "2020-01-30T06:26:07.404714+09:00", + "to": "test@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + }, + { + "time": "2020-01-30T06:26:07.404714+09:00", + "to": "test2@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + } + ] +} +{ + "time": "2020-01-30T06:26:08.404714+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "6526CDB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "153915476795520900002087@example.aaa", + "from": "test@example.bbb", + "size": "4118", + "nrcpt": "1", + "messages": [ + { + "time": "2020-01-30T06:26:08.404714+09:00", + "to": "test@example.ccc", + "status": "sent", + "message": "to=, relay=example.ccc[192.168.0.10]:25, delay=0.1, delays=0.02/0/0.03/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 71111424269E)", + "bounce_id": "" + } + ] +} +{ + "time": "2020-01-30T06:26:05.404714+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "C6E0DDB74006", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "A40CF64D-7F2D-42E4-8A76-CBFFF64A6EB1@example.com", + "from": "test@example.com", + "size": "309891", + "nrcpt": "1", + "messages": [ + { + "time": "2020-01-30T06:26:09.404714+09:00", + "to": "test@example.ddd", + "status": "sent", + "message": "to=, relay=example.ddd[192.168.0.30]:25, delay=3.4, delays=0.11/0/0.38/2.9, dsn=2.0.0, status=sent (250 2.0.0 OK 1539154772 az9-v6si5976496plb.190 - gsmtp)", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T10:57:57+01:00", + "hostname": "mail.server.com", + "process": "postfix/smtpd[59633]", + "queue_id": "D6DDA23B0F", + "client_hostname": "unknown", + "client_ip": "99.88.77.66", + "sasl_method": "", + "sasl_username": "", + "message_id": "20210206095814.2B34E19A19F6@host.sender.domain", + "from": "user2@example.com", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2021-02-06T10:57:58+01:00", + "to": "some.dest@destdomain.com", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[99.88.77.66]: 4.7.1 Greylisting in action, try again later; from= to= proto=ESMTP helo=", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T09:58:59.184925+01:00", + "hostname": "mail.server.com", + "process": "postfix/submission/smtpd[99525]", + "queue_id": "2D19728491", + "client_hostname": "unknown", + "client_ip": "10.11.12.13", + "sasl_method": "PLAIN", + "sasl_username": "user1@domain.example.com", + "message_id": "1612601937133741374.16589280196177750880@user1.domain.example.com", + "from": "user1@example.com", + "size": "11991", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-06T09:58:59.560624+01:00", + "to": "destuser@destination.com", + "status": "sent", + "message": "to=, relay=mail2.domain.com[2b00:128:64::1]:25, delay=9.7, delays=9.5/0.01/0.03/0.12, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 702A02A5BF)", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T11:19:18.130932+01:00", + "hostname": "mail2.server.com", + "process": "postfix/smtpd[61691]", + "queue_id": "1FEE23DED3", + "client_hostname": "unknown", + "client_ip": "2b00:128:64::42", + "sasl_method": "", + "sasl_username": "", + "message_id": "20210206101916.672CC1B4E5@sender.example.com", + "from": "", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2021-02-06T11:19:18.189624+01:00", + "to": "dest@domain.com", + "status": "bounced", + "message": "to=, relay=relay.domain.com[22.33.44.55]:25, delay=0.06, delays=0/0/0.05/0.01, dsn=5.7.1, status=bounced (host relay.domain.com[22.33.44.55] said: 554 5.7.1 : Relay access denied (in reply to RCPT TO command))", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T11:19:25+01:00", + "hostname": "mail1.example.com", + "process": "postfix/smtpd[64346]", + "queue_id": "42E683DD0B", + "client_hostname": "mail.sender.com", + "client_ip": "85.42.66.4", + "sasl_method": "", + "sasl_username": "", + "message_id": "0tgs2nv56aexq9wn-dz6hijmzyfbesxxz-bcd8-493db@some.com", + "from": "18546-55426-655542-8520-recipient1=sender1@mail.some.com", + "size": "8703", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-06T11:19:26+01:00", + "to": "recipient1@destdom.com", + "status": "bounced", + "message": "to=, relay=aspmx.l.google.com[2a00:1450:400c:c04::1b]:25, delay=0.59, delays=0.23/0/0.17/0.19, dsn=5.7.26, status=bounced (host aspmx.l.google.com[2a00:1450:400c:c04::1b] said: 550-5.7.26 This message does not have authentication information or fails to 550-5.7.26 pass authentication checks. To best protect our users from spam, the 550-5.7.26 message has been blocked. Please visit 550-5.7.26 https://support.google.com/mail/answer/81126#authentication for more 550 5.7.26 information. a42si85499772wrx.219 - gsmtp (in reply to end of DATA command))", + "bounce_id": "1F99E4BC9A" + } + ] +} +{ + "time": "2021-02-20T13:18:56+01:00", + "hostname": "srv-smtp", + "process": "postfix/smtpd[63060]", + "queue_id": "9ABCD1BCA9", + "client_hostname": "mailout.domain.com", + "client_ip": "10.11.12.13", + "sasl_method": "", + "sasl_username": "", + "message_id": "20210220121856.17088.40693@internal.domain.lan", + "from": "user1@domain.com", + "size": "5712", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-20T13:18:57+01:00", + "to": "recipient@gmail.com", + "status": "deferred", + "message": "to=, relay=gmail-smtp-in.l.google.com[2a00:1450:400c:c02::1b]:25, delay=0.41, delays=0.19/0/0.19/0.03, dsn=4.2.1, status=deferred (host gmail-smtp-in.l.google.com[2a00:1450:400c:c02::1b] said: 450-4.2.1 The user you are trying to contact is receiving mail at a rate that 450-4.2.1 prevents additional messages from being delivered. Please resend your 450-4.2.1 message at a later time. If the user is able to receive mail at that 450-4.2.1 time, your message will be delivered. For more information, please 450-4.2.1 visit 450 4.2.1 https://support.google.com/mail/?p=ReceivingRate f22si54329842vxg.042 - gsmtp (in reply to RCPT TO command))", + "bounce_id": "" + } + ] +} +{ + "time": "2025-02-13T12:44:28.836533+01:00", + "hostname": "srv-smtp", + "process": "postfix/smtpd[65735]", + "queue_id": "", + "client_hostname": "unknown", + "client_ip": "41.42.43.44", + "sasl_method": "", + "sasl_username": "", + "message_id": "", + "from": "", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2025-02-13T12:44:28.836533+01:00", + "to": "", + "status": "postfix-ratelimit", + "message": "warning: Message delivery request rate limit exceeded: 19 from unknown[41.42.43.44] for service smtp", + "bounce_id": "" + } + ] +} diff --git a/test/test-iso8601.log.147.json b/test/test-iso8601.log.147.json new file mode 100644 index 0000000..d961fb3 --- /dev/null +++ b/test/test-iso8601.log.147.json @@ -0,0 +1,281 @@ +{ + "time": "2020-01-30T06:26:06.404714+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1827]", + "queue_id": "3D74ADB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "f93388828093534f92d85ffe21b2a719@example.info", + "from": "test2@example.info", + "size": "2140", + "nrcpt": "2", + "messages": [ + { + "time": "2020-01-30T06:26:07.404714+09:00", + "to": "test@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + }, + { + "time": "2020-01-30T06:26:07.404714+09:00", + "to": "test2@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + } + ] +} +{ + "time": "2020-01-30T06:26:08.404714+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "6526CDB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "153915476795520900002087@example.aaa", + "from": "test@example.bbb", + "size": "4118", + "nrcpt": "1", + "messages": [ + { + "time": "2020-01-30T06:26:08.404714+09:00", + "to": "test@example.ccc", + "status": "sent", + "message": "to=, relay=example.ccc[192.168.0.10]:25, delay=0.1, delays=0.02/0/0.03/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 71111424269E)", + "bounce_id": "" + } + ] +} +{ + "time": "2020-01-30T06:26:05.404714+09:00", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "C6E0DDB74006", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "A40CF64D-7F2D-42E4-8A76-CBFFF64A6EB1@example.com", + "from": "test@example.com", + "size": "309891", + "nrcpt": "1", + "messages": [ + { + "time": "2020-01-30T06:26:09.404714+09:00", + "to": "test@example.ddd", + "status": "sent", + "message": "to=, relay=example.ddd[192.168.0.30]:25, delay=3.4, delays=0.11/0/0.38/2.9, dsn=2.0.0, status=sent (250 2.0.0 OK 1539154772 az9-v6si5976496plb.190 - gsmtp)", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T10:57:57+01:00", + "hostname": "mail.server.com", + "process": "postfix/smtpd[59633]", + "queue_id": "D6DDA23B0F", + "client_hostname": "unknown", + "client_ip": "99.88.77.66", + "sasl_method": "", + "sasl_username": "", + "message_id": "20210206095814.2B34E19A19F6@host.sender.domain", + "from": "user2@example.com", + "size": "", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-06T10:57:58+01:00", + "to": "some.dest@destdomain.com", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[99.88.77.66]: 4.7.1 Greylisting in action, try again later; from= to= proto=ESMTP helo=", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T09:58:59.184925+01:00", + "hostname": "mail.server.com", + "process": "postfix/submission/smtpd[99525]", + "queue_id": "2D19728491", + "client_hostname": "unknown", + "client_ip": "10.11.12.13", + "sasl_method": "PLAIN", + "sasl_username": "user1@domain.example.com", + "message_id": "1612601937133741374.16589280196177750880@user1.domain.example.com", + "from": "user1@example.com", + "size": "11991", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-06T09:58:59.560624+01:00", + "to": "destuser@destination.com", + "status": "sent", + "message": "to=, relay=mail2.domain.com[2b00:128:64::1]:25, delay=9.7, delays=9.5/0.01/0.03/0.12, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 702A02A5BF)", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T11:19:18.130932+01:00", + "hostname": "mail2.server.com", + "process": "postfix/smtpd[61691]", + "queue_id": "1FEE23DED3", + "client_hostname": "unknown", + "client_ip": "2b00:128:64::42", + "sasl_method": "", + "sasl_username": "", + "message_id": "20210206101916.672CC1B4E5@sender.example.com", + "from": "", + "size": "", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-06T11:19:18.189624+01:00", + "to": "dest@domain.com", + "status": "bounced", + "message": "to=, relay=relay.domain.com[22.33.44.55]:25, delay=0.06, delays=0/0/0.05/0.01, dsn=5.7.1, status=bounced (host relay.domain.com[22.33.44.55] said: 554 5.7.1 : Relay access denied (in reply to RCPT TO command))", + "bounce_id": "" + } + ] +} +{ + "time": "2021-02-06T11:19:25+01:00", + "hostname": "mail1.example.com", + "process": "postfix/smtpd[64346]", + "queue_id": "42E683DD0B", + "client_hostname": "mail.sender.com", + "client_ip": "85.42.66.4", + "sasl_method": "", + "sasl_username": "", + "message_id": "0tgs2nv56aexq9wn-dz6hijmzyfbesxxz-bcd8-493db@some.com", + "from": "18546-55426-655542-8520-recipient1=sender1@mail.some.com", + "size": "8703", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-06T11:19:26+01:00", + "to": "recipient1@destdom.com", + "status": "bounced", + "message": "to=, relay=aspmx.l.google.com[2a00:1450:400c:c04::1b]:25, delay=0.59, delays=0.23/0/0.17/0.19, dsn=5.7.26, status=bounced (host aspmx.l.google.com[2a00:1450:400c:c04::1b] said: 550-5.7.26 This message does not have authentication information or fails to 550-5.7.26 pass authentication checks. To best protect our users from spam, the 550-5.7.26 message has been blocked. Please visit 550-5.7.26 https://support.google.com/mail/answer/81126#authentication for more 550 5.7.26 information. a42si85499772wrx.219 - gsmtp (in reply to end of DATA command))", + "bounce_id": "1F99E4BC9A" + } + ] +} +{ + "time": "2021-02-20T13:18:56+01:00", + "hostname": "srv-smtp", + "process": "postfix/smtpd[63060]", + "queue_id": "9ABCD1BCA9", + "client_hostname": "mailout.domain.com", + "client_ip": "10.11.12.13", + "sasl_method": "", + "sasl_username": "", + "message_id": "20210220121856.17088.40693@internal.domain.lan", + "from": "user1@domain.com", + "size": "5712", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-20T13:18:57+01:00", + "to": "recipient@gmail.com", + "status": "deferred", + "message": "to=, relay=gmail-smtp-in.l.google.com[2a00:1450:400c:c02::1b]:25, delay=0.41, delays=0.19/0/0.19/0.03, dsn=4.2.1, status=deferred (host gmail-smtp-in.l.google.com[2a00:1450:400c:c02::1b] said: 450-4.2.1 The user you are trying to contact is receiving mail at a rate that 450-4.2.1 prevents additional messages from being delivered. Please resend your 450-4.2.1 message at a later time. If the user is able to receive mail at that 450-4.2.1 time, your message will be delivered. For more information, please 450-4.2.1 visit 450 4.2.1 https://support.google.com/mail/?p=ReceivingRate f22si54329842vxg.042 - gsmtp (in reply to RCPT TO command))", + "bounce_id": "" + } + ] +} +{ + "time": "2025-02-13T12:44:28.836533+01:00", + "hostname": "srv-smtp", + "process": "postfix/smtpd[65735]", + "queue_id": "", + "client_hostname": "unknown", + "client_ip": "41.42.43.44", + "sasl_method": "", + "sasl_username": "", + "message_id": "", + "from": "", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2025-02-13T12:44:28.836533+01:00", + "to": "", + "status": "postfix-ratelimit", + "message": "warning: Message delivery request rate limit exceeded: 19 from unknown[41.42.43.44] for service smtp", + "bounce_id": "" + } + ] +} +{ + "time": "2025-03-15T13:30:30.342887+01:00", + "hostname": "smtp.example.org", + "process": "postfix/smtpd[17507]", + "queue_id": "53AEC4F144", + "client_hostname": "unknown", + "client_ip": "192.168.0.22", + "sasl_method": "LOGIN", + "sasl_username": "smtpuser@smtp.example.org", + "message_id": "94851c4c5f9b5ef98755296606bf32ab@example.org", + "from": "sender@example.org", + "size": "", + "nrcpt": "4", + "messages": [ + { + "time": "2025-03-15T13:30:31.206043+01:00", + "to": "recipient1@domain1.net", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit \"to_ip_from\" exceeded; from= to= proto=ESMTP helo=", + "bounce_id": "" + }, + { + "time": "2025-03-15T13:30:31.206043+01:00", + "to": "recipient2@foreign.net", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit \"to_ip_from\" exceeded; from= to= proto=ESMTP helo=", + "bounce_id": "" + }, + { + "time": "2025-03-15T13:30:31.206043+01:00", + "to": "recipient3@somewhere.in", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit \"to_ip_from\" exceeded; from= to= proto=ESMTP helo=", + "bounce_id": "" + }, + { + "time": "2025-03-15T13:30:31.206043+01:00", + "to": "recipient4@anotherdomain.com", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit \"to_ip_from\" exceeded; from= to= proto=ESMTP helo=", + "bounce_id": "" + } + ] +} +{ + "time": "2025-03-09T16:41:59.568868+01:00", + "hostname": "smtp.example.org", + "process": "postfix/smtpd[78309]", + "queue_id": "NOQUEUE", + "client_hostname": "unknown", + "client_ip": "192.168.0.11", + "sasl_method": "", + "sasl_username": "", + "message_id": "", + "from": "not_an_email", + "size": "", + "nrcpt": "1", + "messages": [ + { + "time": "2025-03-09T16:41:59.568868+01:00", + "to": "recipient@another.domain.com", + "status": "postfix-reject", + "message": "reject: RCPT from unknown[192.168.0.11]: 504 5.5.2 : Sender address rejected: need fully-qualified address; from= to= proto=ESMTP helo=", + "bounce_id": "" + } + ] +} diff --git a/test/test-milter.142.json b/test/test-milter.142.json new file mode 100644 index 0000000..79ef6b8 --- /dev/null +++ b/test/test-milter.142.json @@ -0,0 +1,46 @@ +{ + "time": "2021-02-19T14:32:14.976132+01:00", + "hostname": "smtp01.example.org", + "process": "postfix/cleanup[52106]", + "queue_id": "E89FA2DEDA", + "client_hostname": "srv05.source.com", + "client_ip": "10.11.12.13", + "sasl_method": "", + "sasl_username": "", + "message_id": "", + "from": "", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2021-02-19T14:32:14.976132+01:00", + "to": "this_user@this.domain.com", + "status": "milter-hold", + "message": "milter-hold: END-OF-MESSAGE from srv05.source.com[10.11.12.13]: milter triggers HOLD action; from=<> to= proto=ESMTP helo=", + "bounce_id": "" + } + ] +} +{ + "time": "2021-12-03T06:27:33.887389+01:00", + "hostname": "smtp01.example.org", + "process": "postfix/smtpd[50419]", + "queue_id": "B42E77AB32", + "client_hostname": "42-64-53-170.subs.proxad.net", + "client_ip": "42.64.53.170", + "sasl_method": "PLAIN", + "sasl_username": "user42@smtp01.example.com", + "message_id": "164017759823.25920.10144256874843932242@12f2bb757669", + "from": "youssefh@senderdomain.com", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2021-12-03T06:27:34.105536+01:00", + "to": "archive@senderdomain.com", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from 42-64-53-170.subs.proxad.net[42.64.53.170]: 4.7.1 Ratelimit \"05\" exceeded; from= to= proto=ESMTP helo=<[172.18.0.2]>", + "bounce_id": "" + } + ] +} diff --git a/test/test-milter.146.json b/test/test-milter.146.json new file mode 100644 index 0000000..79ef6b8 --- /dev/null +++ b/test/test-milter.146.json @@ -0,0 +1,46 @@ +{ + "time": "2021-02-19T14:32:14.976132+01:00", + "hostname": "smtp01.example.org", + "process": "postfix/cleanup[52106]", + "queue_id": "E89FA2DEDA", + "client_hostname": "srv05.source.com", + "client_ip": "10.11.12.13", + "sasl_method": "", + "sasl_username": "", + "message_id": "", + "from": "", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2021-02-19T14:32:14.976132+01:00", + "to": "this_user@this.domain.com", + "status": "milter-hold", + "message": "milter-hold: END-OF-MESSAGE from srv05.source.com[10.11.12.13]: milter triggers HOLD action; from=<> to= proto=ESMTP helo=", + "bounce_id": "" + } + ] +} +{ + "time": "2021-12-03T06:27:33.887389+01:00", + "hostname": "smtp01.example.org", + "process": "postfix/smtpd[50419]", + "queue_id": "B42E77AB32", + "client_hostname": "42-64-53-170.subs.proxad.net", + "client_ip": "42.64.53.170", + "sasl_method": "PLAIN", + "sasl_username": "user42@smtp01.example.com", + "message_id": "164017759823.25920.10144256874843932242@12f2bb757669", + "from": "youssefh@senderdomain.com", + "size": "", + "nrcpt": "", + "messages": [ + { + "time": "2021-12-03T06:27:34.105536+01:00", + "to": "archive@senderdomain.com", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from 42-64-53-170.subs.proxad.net[42.64.53.170]: 4.7.1 Ratelimit \"05\" exceeded; from= to= proto=ESMTP helo=<[172.18.0.2]>", + "bounce_id": "" + } + ] +} diff --git a/test/test-milter.147.json b/test/test-milter.147.json new file mode 100644 index 0000000..f5dbea4 --- /dev/null +++ b/test/test-milter.147.json @@ -0,0 +1,46 @@ +{ + "time": "2021-02-19T14:32:14.976132+01:00", + "hostname": "smtp01.example.org", + "process": "postfix/cleanup[52106]", + "queue_id": "E89FA2DEDA", + "client_hostname": "srv05.source.com", + "client_ip": "10.11.12.13", + "sasl_method": "", + "sasl_username": "", + "message_id": "", + "from": "", + "size": "", + "nrcpt": "1", + "messages": [ + { + "time": "2021-02-19T14:32:14.976132+01:00", + "to": "this_user@this.domain.com", + "status": "milter-hold", + "message": "milter-hold: END-OF-MESSAGE from srv05.source.com[10.11.12.13]: milter triggers HOLD action; from=<> to= proto=ESMTP helo=", + "bounce_id": "" + } + ] +} +{ + "time": "2021-12-03T06:27:33.887389+01:00", + "hostname": "smtp01.example.org", + "process": "postfix/smtpd[50419]", + "queue_id": "B42E77AB32", + "client_hostname": "42-64-53-170.subs.proxad.net", + "client_ip": "42.64.53.170", + "sasl_method": "PLAIN", + "sasl_username": "user42@smtp01.example.com", + "message_id": "164017759823.25920.10144256874843932242@12f2bb757669", + "from": "youssefh@senderdomain.com", + "size": "", + "nrcpt": "1", + "messages": [ + { + "time": "2021-12-03T06:27:34.105536+01:00", + "to": "archive@senderdomain.com", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from 42-64-53-170.subs.proxad.net[42.64.53.170]: 4.7.1 Ratelimit \"05\" exceeded; from= to= proto=ESMTP helo=<[172.18.0.2]>", + "bounce_id": "" + } + ] +} diff --git a/test/test-milter.log b/test/test-milter.log new file mode 100644 index 0000000..f397ef9 --- /dev/null +++ b/test/test-milter.log @@ -0,0 +1,16 @@ +021-02-06T10:57:57+01:00 mail.server.com postfix/smtpd[59633]: D6DDA23B0F: client=unknown[99.88.77.66] +2021-02-06T10:57:57+01:00 mail.server.com postfix/cleanup[59586]: D6DDA23B0F: message-id=<20210206095814.2B34E19A19F6@host.sender.domain> +2021-02-06T10:57:58+01:00 mail.server.com postfix/cleanup[59586]: D6DDA23B0F: milter-reject: END-OF-MESSAGE from unknown[99.88.77.66]: 4.7.1 Greylisting in action, try again later; from= to= proto=ESMTP helo= +2021-02-19T14:32:14.936091+01:00 smtp01.example.org postfix/smtpd[58176] E89FA2DEDA: client=srv05.source.com[10.11.12.13] +2021-02-19T14:32:14.938357+01:00 smtp01.example.org postfix/cleanup[52106] E89FA2DEDA: message-id=<20210219133213.5D10C499CA@srv.domain.org> +2021-02-19T14:32:14.976132+01:00 smtp01.example.org postfix/cleanup[52106] E89FA2DEDA: milter-hold: END-OF-MESSAGE from srv05.source.com[10.11.12.13]: milter triggers HOLD action; from=<> to= proto=ESMTP helo= + + +2021-12-03T06:27:32.797930+01:00 smtp01.example.org postfix/smtpd[50419] connect from 42-64-53-170.subs.proxad.net[42.64.53.170] +2021-12-03T06:27:33.887389+01:00 smtp01.example.org postfix/smtpd[50419] B42E77AB32: client=42-64-53-170.subs.proxad.net[42.64.53.170], sasl_method=PLAIN, sasl_username=user42@smtp01.example.com +2021-12-03T06:27:33.923496+01:00 smtp01.example.org postfix/smtpd[50419] B42E77AB32: filter: RCPT from 42-64-53-170.subs.proxad.net[42.64.53.170]: : Recipient address triggers FILTER relay:[smtp01.example.org]; from= to= proto=ESMTP helo=<[172.18.0.2]> +2021-12-03T06:27:33.965888+01:00 smtp01.example.org postfix/cleanup[19657] B42E77AB32: replace: header Received: from [172.18.0.2] (42-64-53-170.subs.proxad.net [42.64.53.170])??(Authenticated sender: user42@smtp01.example.com)??by smtp01.example.org (Postfix) with ESMTPA id D89B from 42-64-53-170.subs.proxad.net[42.64.53.170]; from= to= proto=ESMTP helo=<[172.18.0.2]>: Received: from [172.18.0.2] (42-64-53-170.subs.proxad.net [42.64.53.170])??(Authenticated sender: youssef)??by smtp01.example.org (Postfix) with ESMTPA id B42E77AB32;??Wed, 22 Dec 2021 13:59:32 +0100 (CET) +2021-12-03T06:27:33.965947+01:00 smtp01.example.org postfix/cleanup[19657] B42E77AB32: message-id=<164017759823.25920.10144256874843932242@12f2bb757669> +2021-12-03T06:27:34.105536+01:00 smtp01.example.org postfix/cleanup[19657] B42E77AB32: milter-reject: END-OF-MESSAGE from 42-64-53-170.subs.proxad.net[42.64.53.170]: 4.7.1 Ratelimit "05" exceeded; from= to= proto=ESMTP helo=<[172.18.0.2]> +2021-12-03T06:27:34.135099+01:00 smtp01.example.org postfix/smtpd[50419] disconnect from 42-64-53-170.subs.proxad.net[42.64.53.170] ehlo=1 auth=1 mail=1 rcpt=2 data=0/1 rset=1 quit=1 commands=7/8 + diff --git a/test/test.142.json b/test/test.142.json new file mode 100644 index 0000000..8044519 --- /dev/null +++ b/test/test.142.json @@ -0,0 +1,76 @@ +{ + "time": "0000-10-10T15:59:29+00:09", + "hostname": "mail", + "process": "postfix/smtpd[1827]", + "queue_id": "3D74ADB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "f93388828093534f92d85ffe21b2a719@example.info", + "from": "test2@example.info", + "size": "2140", + "nrcpt": "1", + "messages": [ + { + "time": "0000-10-10T15:59:30+00:09", + "to": "test@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + }, + { + "time": "0000-10-10T15:59:30+00:09", + "to": "test2@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + } + ] +} +{ + "time": "0000-10-10T15:59:31+00:09", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "6526CDB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "153915476795520900002087@example.aaa", + "from": "test@example.bbb", + "size": "4118", + "nrcpt": "1", + "messages": [ + { + "time": "0000-10-10T15:59:31+00:09", + "to": "test@example.ccc", + "status": "sent", + "message": "to=, relay=example.ccc[192.168.0.10]:25, delay=0.1, delays=0.02/0/0.03/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 71111424269E)", + "bounce_id": "" + } + ] +} +{ + "time": "0000-10-10T15:59:28+00:09", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "C6E0DDB74006", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "A40CF64D-7F2D-42E4-8A76-CBFFF64A6EB1@example.com", + "from": "test@example.com", + "size": "309891", + "nrcpt": "1", + "messages": [ + { + "time": "0000-10-10T15:59:32+00:09", + "to": "test@example.ddd", + "status": "sent", + "message": "to=, relay=example.ddd[192.168.0.30]:25, delay=3.4, delays=0.11/0/0.38/2.9, dsn=2.0.0, status=sent (250 2.0.0 OK 1539154772 az9-v6si5976496plb.190 - gsmtp)", + "bounce_id": "" + } + ] +} diff --git a/test/test.146.json b/test/test.146.json new file mode 100644 index 0000000..8044519 --- /dev/null +++ b/test/test.146.json @@ -0,0 +1,76 @@ +{ + "time": "0000-10-10T15:59:29+00:09", + "hostname": "mail", + "process": "postfix/smtpd[1827]", + "queue_id": "3D74ADB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "f93388828093534f92d85ffe21b2a719@example.info", + "from": "test2@example.info", + "size": "2140", + "nrcpt": "1", + "messages": [ + { + "time": "0000-10-10T15:59:30+00:09", + "to": "test@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + }, + { + "time": "0000-10-10T15:59:30+00:09", + "to": "test2@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + } + ] +} +{ + "time": "0000-10-10T15:59:31+00:09", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "6526CDB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "153915476795520900002087@example.aaa", + "from": "test@example.bbb", + "size": "4118", + "nrcpt": "1", + "messages": [ + { + "time": "0000-10-10T15:59:31+00:09", + "to": "test@example.ccc", + "status": "sent", + "message": "to=, relay=example.ccc[192.168.0.10]:25, delay=0.1, delays=0.02/0/0.03/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 71111424269E)", + "bounce_id": "" + } + ] +} +{ + "time": "0000-10-10T15:59:28+00:09", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "C6E0DDB74006", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "A40CF64D-7F2D-42E4-8A76-CBFFF64A6EB1@example.com", + "from": "test@example.com", + "size": "309891", + "nrcpt": "1", + "messages": [ + { + "time": "0000-10-10T15:59:32+00:09", + "to": "test@example.ddd", + "status": "sent", + "message": "to=, relay=example.ddd[192.168.0.30]:25, delay=3.4, delays=0.11/0/0.38/2.9, dsn=2.0.0, status=sent (250 2.0.0 OK 1539154772 az9-v6si5976496plb.190 - gsmtp)", + "bounce_id": "" + } + ] +} diff --git a/test/test.147.json b/test/test.147.json new file mode 100644 index 0000000..e811faa --- /dev/null +++ b/test/test.147.json @@ -0,0 +1,76 @@ +{ + "time": "0000-10-10T15:59:29+00:09", + "hostname": "mail", + "process": "postfix/smtpd[1827]", + "queue_id": "3D74ADB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "f93388828093534f92d85ffe21b2a719@example.info", + "from": "test2@example.info", + "size": "2140", + "nrcpt": "2", + "messages": [ + { + "time": "0000-10-10T15:59:30+00:09", + "to": "test@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + }, + { + "time": "0000-10-10T15:59:30+00:09", + "to": "test2@example.to", + "status": "sent", + "message": "to=, relay=example.to[192.168.0.20]:25, delay=1.7, delays=0.02/0/1.7/0.06, dsn=2.0.0, status=sent (250 [Sniper] OK 1539154772 snipe-queue 10549)", + "bounce_id": "" + } + ] +} +{ + "time": "0000-10-10T15:59:31+00:09", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "6526CDB7400B", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "153915476795520900002087@example.aaa", + "from": "test@example.bbb", + "size": "4118", + "nrcpt": "1", + "messages": [ + { + "time": "0000-10-10T15:59:31+00:09", + "to": "test@example.ccc", + "status": "sent", + "message": "to=, relay=example.ccc[192.168.0.10]:25, delay=0.1, delays=0.02/0/0.03/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 71111424269E)", + "bounce_id": "" + } + ] +} +{ + "time": "0000-10-10T15:59:28+00:09", + "hostname": "mail", + "process": "postfix/smtpd[1830]", + "queue_id": "C6E0DDB74006", + "client_hostname": "example.com", + "client_ip": "127.0.0.1", + "sasl_method": "", + "sasl_username": "", + "message_id": "A40CF64D-7F2D-42E4-8A76-CBFFF64A6EB1@example.com", + "from": "test@example.com", + "size": "309891", + "nrcpt": "1", + "messages": [ + { + "time": "0000-10-10T15:59:32+00:09", + "to": "test@example.ddd", + "status": "sent", + "message": "to=, relay=example.ddd[192.168.0.30]:25, delay=3.4, delays=0.11/0/0.38/2.9, dsn=2.0.0, status=sent (250 2.0.0 OK 1539154772 az9-v6si5976496plb.190 - gsmtp)", + "bounce_id": "" + } + ] +} diff --git a/test/test.rcpt.147.json b/test/test.rcpt.147.json new file mode 100644 index 0000000..a8cc988 --- /dev/null +++ b/test/test.rcpt.147.json @@ -0,0 +1,44 @@ +{ + "time": "2025-03-15T13:30:30.342887+01:00", + "hostname": "smtp.example.org", + "process": "postfix/smtpd[17507]", + "queue_id": "53AEC4F144", + "client_hostname": "unknown", + "client_ip": "192.168.0.22", + "sasl_method": "LOGIN", + "sasl_username": "smtpuser@smtp.example.org", + "message_id": "94851c4c5f9b5ef98755296606bf32ab@example.org", + "from": "sender@example.org", + "size": "", + "nrcpt": "4", + "messages": [ + { + "time": "2025-03-15T13:30:31.206043+01:00", + "to": "recipient1@domain1.net", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit \"to_ip_from\" exceeded; from= to= proto=ESMTP helo=", + "bounce_id": "" + }, + { + "time": "2025-03-15T13:30:31.206043+01:00", + "to": "recipient2@foreign.net", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit \"to_ip_from\" exceeded; from= to= proto=ESMTP helo=", + "bounce_id": "" + }, + { + "time": "2025-03-15T13:30:31.206043+01:00", + "to": "recipient3@somewhere.in", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit \"to_ip_from\" exceeded; from= to= proto=ESMTP helo=", + "bounce_id": "" + }, + { + "time": "2025-03-15T13:30:31.206043+01:00", + "to": "recipient4@anotherdomain.com", + "status": "milter-reject", + "message": "milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit \"to_ip_from\" exceeded; from= to= proto=ESMTP helo=", + "bounce_id": "" + } + ] +} diff --git a/test/test.rcpt.log b/test/test.rcpt.log new file mode 100644 index 0000000..aace8dc --- /dev/null +++ b/test/test.rcpt.log @@ -0,0 +1,11 @@ +2025-03-15T13:30:29.169282+01:00 smtp.example.org postfix/smtpd[17507] warning: hostname smtp.internal.local does not resolve to address 192.168.0.22: Name does not resolve +2025-03-15T13:30:29.169332+01:00 smtp.example.org postfix/smtpd[17507] connect from unknown[192.168.0.22] +2025-03-15T13:30:29.221416+01:00 smtp.example.org postfix/smtpd[17507] Anonymous TLS connection established from unknown[192.168.0.22]: TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits) +2025-03-15T13:30:30.342887+01:00 smtp.example.org postfix/smtpd[17507] 53AEC4F144: client=unknown[192.168.0.22], sasl_method=LOGIN, sasl_username=smtpuser@smtp.example.org +2025-03-15T13:30:30.352537+01:00 smtp.example.org postfix/smtpd[17507] 53AEC4F144: filter: RCPT from unknown[192.168.0.22]: : Recipient address triggers FILTER relay:[pod-02.smtpout.exploit.intra]; from= to= proto=ESMTP helo= +2025-03-15T13:30:30.355033+01:00 smtp.example.org postfix/smtpd[17507] 53AEC4F144: filter: RCPT from unknown[192.168.0.22]: : Recipient address triggers FILTER relay:[pod-02.smtpout.exploit.intra]; from= to= proto=ESMTP helo= +2025-03-15T13:30:30.362445+01:00 smtp.example.org postfix/smtpd[17507] 53AEC4F144: filter: RCPT from unknown[192.168.0.22]: : Recipient address triggers FILTER relay:[pod-02.smtpout.exploit.intra]; from= to= proto=ESMTP helo= +2025-03-15T13:30:31.158051+01:00 smtp.example.org postfix/cleanup[58145] 53AEC4F144: replace: header Received: from smtp.internal.local (unknown [192.168.0.22])??(using TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits))??(No client certificate requested)??(Authenticated sender: smtpuser from unknown[192.168.0.22]; from= to= proto=ESMTP helo=: Received: from smtp.internal.local (unknown [192.168.0.22])??(using TLSv1.2 with cipher ECDHE-ECDSA-AES256-GCM-SHA384 (256/256 bits))??(No client certificate requested)??(Authenticated sender: anonymized)??by smtp.example.org (Postfix) with ESMTPSA id 53AEC4F144;??Sat, 15 Mar 2025 13:30:29 +0100 (CET) +2025-03-15T13:30:31.158169+01:00 smtp.example.org postfix/cleanup[58145] 53AEC4F144: message-id=<94851c4c5f9b5ef98755296606bf32ab@example.org> +2025-03-15T13:30:31.206043+01:00 smtp.example.org postfix/cleanup[58145] 53AEC4F144: milter-reject: END-OF-MESSAGE from unknown[192.168.0.22]: 4.7.1 Ratelimit "to_ip_from" exceeded; from= to= proto=ESMTP helo= +2025-03-15T13:30:31.238801+01:00 smtp.example.org postfix/smtpd[17507] disconnect from unknown[192.168.0.22] ehlo=2 starttls=1 auth=1 mail=1 rcpt=4/4 bdat=0/1 rset=1 quit=1 commands=8/10