From 3abd6f4572fb2f2b216dbae6e19bfb21072d0718 Mon Sep 17 00:00:00 2001 From: Thomas Paradis Date: Wed, 7 Apr 2021 15:21:26 +0200 Subject: [PATCH 1/5] Add metric by status for all message processed by smtp --- postfix_exporter.go | 21 ++++++++++++++++++--- postfix_exporter_test.go | 29 +++++++++++++++++++++++++++++ 2 files changed, 47 insertions(+), 3 deletions(-) diff --git a/postfix_exporter.go b/postfix_exporter.go index 226542d..607b185 100644 --- a/postfix_exporter.go +++ b/postfix_exporter.go @@ -56,6 +56,8 @@ type PostfixExporter struct { smtpDelays *prometheus.HistogramVec smtpTLSConnects *prometheus.CounterVec smtpConnectionTimedOut prometheus.Counter + smtpProcesses *prometheus.CounterVec + // should be the same as smtpProcesses{status=deferred}, kept for compatibility, but this doesn't work ! smtpDeferreds prometheus.Counter smtpdConnects prometheus.Counter smtpdDisconnects prometheus.Counter @@ -66,6 +68,7 @@ type PostfixExporter struct { smtpdSASLAuthenticationFailures prometheus.Counter smtpdTLSConnects *prometheus.CounterVec unsupportedLogEntries *prometheus.CounterVec + // same as smtpProcesses{status=deferred}, kept for compatibility smtpStatusDeferred prometheus.Counter opendkimSignatureAdded *prometheus.CounterVec } @@ -289,7 +292,7 @@ var ( logLine = regexp.MustCompile(` ?(postfix|opendkim)(/(\w+))?\[\d+\]: (.*)`) lmtpPipeSMTPLine = regexp.MustCompile(`, relay=(\S+), .*, delays=([0-9\.]+)/([0-9\.]+)/([0-9\.]+)/([0-9\.]+), `) qmgrInsertLine = regexp.MustCompile(`:.*, size=(\d+), nrcpt=(\d+) `) - smtpStatusDeferredLine = regexp.MustCompile(`, status=deferred`) + smtpStatusLine = regexp.MustCompile(`, status=(\w+) `) smtpTLSLine = regexp.MustCompile(`^(\S+) TLS connection established to \S+: (\S+) with cipher (\S+) \((\d+)/(\d+) bits\)`) smtpConnectionTimedOut = regexp.MustCompile(`^connect\s+to\s+(.*)\[(.*)\]:(\d+):\s+(Connection timed out)$`) smtpdFCrDNSErrorsLine = regexp.MustCompile(`^warning: hostname \S+ does not resolve to address `) @@ -359,8 +362,11 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { addToHistogramVec(e.smtpDelays, smtpMatches[3], "queue_manager", "") addToHistogramVec(e.smtpDelays, smtpMatches[4], "connection_setup", "") addToHistogramVec(e.smtpDelays, smtpMatches[5], "transmission", "") - if smtpMatches := smtpStatusDeferredLine.FindStringSubmatch(remainder); smtpMatches != nil { - e.smtpStatusDeferred.Inc() + if smtpStatusMatches := smtpStatusLine.FindStringSubmatch(remainder); smtpStatusMatches != nil { + e.smtpProcesses.WithLabelValues(smtpStatusMatches[1]).Inc() + if smtpStatusMatches[1] == "deferred" { + e.smtpStatusDeferred.Inc() + } } } else if smtpTLSMatches := smtpTLSLine.FindStringSubmatch(remainder); smtpTLSMatches != nil { e.smtpTLSConnects.WithLabelValues(smtpTLSMatches[1:]...).Inc() @@ -504,6 +510,13 @@ func NewPostfixExporter(showqPath string, logSrc LogSource, logUnsupportedLines Name: "smtp_deferred_messages_total", Help: "Total number of messages that have been deferred on SMTP.", }), + smtpProcesses: prometheus.NewCounterVec( + prometheus.CounterOpts{ + Namespace: "postfix", + Name: "smtp_messages_processed_total", + Help: "Total number of messages that have been processed by the smtp process.", + }, + []string{"status"}), smtpConnectionTimedOut: prometheus.NewCounter(prometheus.CounterOpts{ Namespace: "postfix", Name: "smtp_connection_timed_out_total", @@ -598,6 +611,7 @@ func (e *PostfixExporter) Describe(ch chan<- *prometheus.Desc) { e.smtpDelays.Describe(ch) e.smtpTLSConnects.Describe(ch) ch <- e.smtpDeferreds.Desc() + e.smtpProcesses.Describe(ch) ch <- e.smtpdConnects.Desc() ch <- e.smtpdDisconnects.Desc() ch <- e.smtpdFCrDNSErrors.Desc() @@ -673,6 +687,7 @@ func (e *PostfixExporter) Collect(ch chan<- prometheus.Metric) { e.smtpDelays.Collect(ch) e.smtpTLSConnects.Collect(ch) ch <- e.smtpDeferreds + e.smtpProcesses.Collect(ch) ch <- e.smtpdConnects ch <- e.smtpdDisconnects ch <- e.smtpdFCrDNSErrors diff --git a/postfix_exporter_test.go b/postfix_exporter_test.go index a3426a4..a913ddb 100644 --- a/postfix_exporter_test.go +++ b/postfix_exporter_test.go @@ -23,6 +23,8 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpDelays *prometheus.HistogramVec smtpTLSConnects *prometheus.CounterVec smtpDeferreds prometheus.Counter + smtpStatusDeferred prometheus.Counter + smtpProcesses *prometheus.CounterVec smtpdConnects prometheus.Counter smtpdDisconnects prometheus.Counter smtpdFCrDNSErrors prometheus.Counter @@ -39,6 +41,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { saslFailedCount int outgoingTLS int smtpdMessagesProcessed int + smtpMessagesProcessed int } tests := []struct { name string @@ -117,6 +120,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { fields: fields{ smtpdSASLAuthenticationFailures: prometheus.NewCounter(prometheus.CounterOpts{}), unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), + smtpProcesses: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"status"}), }, }, { @@ -146,10 +150,12 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { removedCount: 0, saslFailedCount: 0, outgoingTLS: 2, + smtpdMessagesProcessed: 0, }, fields: fields{ unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), smtpTLSConnects: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"Verified", "TLSv1.2", "ECDHE-RSA-AES256-GCM-SHA384", "256", "256"}), + smtpProcesses: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"status"}), }, }, { @@ -162,9 +168,29 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { saslFailedCount: 0, outgoingTLS: 0, smtpdMessagesProcessed: 0, + smtpMessagesProcessed: 1, }, fields: fields{ smtpDelays: prometheus.NewHistogramVec(prometheus.HistogramOpts{}, []string{"stage"}), + smtpProcesses: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"status"}), + }, + }, + { + name: "Testing different smtp statuses", + args: args{ + line: []string{ + "Dec 29 02:54:09 mail postfix/smtp[7648]: 732BB407C3: host mail.domain.com[1.1.1.1] said: 451 DT:SPM 163 mx13,P8CowECpNVM_oEVaenoEAQ--.23796S3 1514512449, please try again 15min later (in reply to end of DATA command)", + "Dec 29 02:54:12 mail postfix/smtp[7648]: 732BB407C3: to=, relay=mail.domain.com[1.1.1.1]:25, delay=6.2, delays=0.1/0/5.2/0.87, dsn=4.0.0, status=deferred (host mail.domain.com[1.1.1.1] said: 451 DT:SPM 163 mx40,WsCowAAnEhlCoEVa5GjcAA--.20089S3 1514512452, please try again 15min later (in reply to end of DATA command))", + "Dec 29 03:03:48 mail postfix/smtp[8492]: 732BB407C3: to=, relay=mail.domain.com[1.1.1.1]:25, delay=582, delays=563/16/1.7/0.81, dsn=5.0.0, status=bounced (host mail.domain.com[1.1.1.1] said: 554 DT:SPM 163 mx9,O8CowEDJVFKCokVaRhz+AA--.26016S3 1514513028,please see http://mail.domain.com/help/help_spam.htm?ip= (in reply to end of DATA command))", + "Dec 29 03:03:48 mail postfix/bounce[9321]: 732BB407C3: sender non-delivery notification: 5DE184083C", + }, + smtpMessagesProcessed: 2, + }, + fields: fields{ + unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), + smtpDelays: prometheus.NewHistogramVec(prometheus.HistogramOpts{}, []string{"stage"}), + smtpStatusDeferred: prometheus.NewCounter(prometheus.CounterOpts{}), + smtpProcesses: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"status"}), }, }, } @@ -184,6 +210,8 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpDelays: tt.fields.smtpDelays, smtpTLSConnects: tt.fields.smtpTLSConnects, smtpDeferreds: tt.fields.smtpDeferreds, + smtpStatusDeferred: tt.fields.smtpStatusDeferred, + smtpProcesses: tt.fields.smtpProcesses, smtpdConnects: tt.fields.smtpdConnects, smtpdDisconnects: tt.fields.smtpdDisconnects, smtpdFCrDNSErrors: tt.fields.smtpdFCrDNSErrors, @@ -202,6 +230,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { assertCounterEquals(t, e.smtpdSASLAuthenticationFailures, tt.args.saslFailedCount, "Wrong number of Sasl counter counted") assertCounterEquals(t, e.smtpTLSConnects, tt.args.outgoingTLS, "Wrong number of TLS connections counted") assertCounterEquals(t, e.smtpdProcesses, tt.args.smtpdMessagesProcessed, "Wrong number of smtpd messages processed") + assertCounterEquals(t, e.smtpProcesses, tt.args.smtpMessagesProcessed, "Wrong number of smtp messages processed") }) } } From 6531beb3a753b8e9536883d151fb7413255a4703 Mon Sep 17 00:00:00 2001 From: Thomas Paradis Date: Wed, 7 Apr 2021 15:31:44 +0200 Subject: [PATCH 2/5] Add metric for non delivery notifications from bounce --- postfix_exporter.go | 15 +++++++++++++++ postfix_exporter_test.go | 6 ++++++ 2 files changed, 21 insertions(+) diff --git a/postfix_exporter.go b/postfix_exporter.go index 607b185..ccc818c 100644 --- a/postfix_exporter.go +++ b/postfix_exporter.go @@ -71,6 +71,7 @@ type PostfixExporter struct { // same as smtpProcesses{status=deferred}, kept for compatibility smtpStatusDeferred prometheus.Counter opendkimSignatureAdded *prometheus.CounterVec + bounceNonDelivery prometheus.Counter } // A LogSource is an interface to read log lines. @@ -302,6 +303,7 @@ var ( smtpdSASLAuthenticationFailuresLine = regexp.MustCompile(`^warning: \S+: SASL \S+ authentication failed: `) smtpdTLSLine = regexp.MustCompile(`^(\S+) TLS connection established from \S+: (\S+) with cipher (\S+) \((\d+)/(\d+) bits\)`) opendkimSignatureAdded = regexp.MustCompile(`^[\w\d]+: DKIM-Signature field added \(s=(\w+), d=(.*)\)$`) + bounceNonDeliveryLine = regexp.MustCompile(`: sender non-delivery notification: `) ) // CollectFromLogline collects metrict from a Postfix log line. @@ -397,6 +399,12 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { } else { e.addToUnsupportedLine(line, subprocess) } + case "bounce": + if bounceMatches := bounceNonDeliveryLine.FindStringSubmatch(remainder); bounceMatches != nil { + e.bounceNonDelivery.Inc() + } else { + e.addToUnsupportedLine(line, process) + } default: e.addToUnsupportedLine(line, subprocess) } @@ -590,6 +598,11 @@ func NewPostfixExporter(showqPath string, logSrc LogSource, logUnsupportedLines }, []string{"subject", "domain"}, ), + bounceNonDelivery: prometheus.NewCounter(prometheus.CounterOpts{ + Namespace: "postfix", + Name: "bounce_non_delivery_notification_total", + Help: "Total number of non delivery notification sent by bounce.", + }), }, nil } @@ -624,6 +637,7 @@ func (e *PostfixExporter) Describe(ch chan<- *prometheus.Desc) { e.unsupportedLogEntries.Describe(ch) e.smtpConnectionTimedOut.Describe(ch) e.opendkimSignatureAdded.Describe(ch) + ch <- e.bounceNonDelivery.Desc() } func (e *PostfixExporter) StartMetricCollection(ctx context.Context) { @@ -700,4 +714,5 @@ func (e *PostfixExporter) Collect(ch chan<- prometheus.Metric) { e.unsupportedLogEntries.Collect(ch) ch <- e.smtpConnectionTimedOut e.opendkimSignatureAdded.Collect(ch) + ch <- e.bounceNonDelivery } diff --git a/postfix_exporter_test.go b/postfix_exporter_test.go index a913ddb..378b67a 100644 --- a/postfix_exporter_test.go +++ b/postfix_exporter_test.go @@ -33,6 +33,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpdRejects *prometheus.CounterVec smtpdSASLAuthenticationFailures prometheus.Counter smtpdTLSConnects *prometheus.CounterVec + bounceNonDelivery prometheus.Counter unsupportedLogEntries *prometheus.CounterVec } type args struct { @@ -42,6 +43,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { outgoingTLS int smtpdMessagesProcessed int smtpMessagesProcessed int + bounceNonDelivery int } tests := []struct { name string @@ -185,12 +187,14 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { "Dec 29 03:03:48 mail postfix/bounce[9321]: 732BB407C3: sender non-delivery notification: 5DE184083C", }, smtpMessagesProcessed: 2, + bounceNonDelivery: 1, }, fields: fields{ unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), smtpDelays: prometheus.NewHistogramVec(prometheus.HistogramOpts{}, []string{"stage"}), smtpStatusDeferred: prometheus.NewCounter(prometheus.CounterOpts{}), smtpProcesses: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"status"}), + bounceNonDelivery: prometheus.NewCounter(prometheus.CounterOpts{}), }, }, } @@ -220,6 +224,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpdRejects: tt.fields.smtpdRejects, smtpdSASLAuthenticationFailures: tt.fields.smtpdSASLAuthenticationFailures, smtpdTLSConnects: tt.fields.smtpdTLSConnects, + bounceNonDelivery: tt.fields.bounceNonDelivery, unsupportedLogEntries: tt.fields.unsupportedLogEntries, logUnsupportedLines: true, } @@ -231,6 +236,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { assertCounterEquals(t, e.smtpTLSConnects, tt.args.outgoingTLS, "Wrong number of TLS connections counted") assertCounterEquals(t, e.smtpdProcesses, tt.args.smtpdMessagesProcessed, "Wrong number of smtpd messages processed") assertCounterEquals(t, e.smtpProcesses, tt.args.smtpMessagesProcessed, "Wrong number of smtp messages processed") + assertCounterEquals(t, e.bounceNonDelivery, tt.args.bounceNonDelivery, "Wrong number of non delivery notifications") }) } } From 8966f650671051c15877a9129d38f86102574d4c Mon Sep 17 00:00:00 2001 From: Thomas Paradis Date: Wed, 7 Apr 2021 15:41:26 +0200 Subject: [PATCH 3/5] Add another metric for mails delivered locally --- postfix_exporter.go | 14 ++++++++++++++ postfix_exporter_test.go | 16 ++++++++++++++++ 2 files changed, 30 insertions(+) diff --git a/postfix_exporter.go b/postfix_exporter.go index ccc818c..f74dabe 100644 --- a/postfix_exporter.go +++ b/postfix_exporter.go @@ -72,6 +72,7 @@ type PostfixExporter struct { smtpStatusDeferred prometheus.Counter opendkimSignatureAdded *prometheus.CounterVec bounceNonDelivery prometheus.Counter + virtualDelivered prometheus.Counter } // A LogSource is an interface to read log lines. @@ -405,6 +406,12 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { } else { e.addToUnsupportedLine(line, process) } + case "virtual": + if strings.HasSuffix(remainder, ", status=sent (delivered to maildir)") { + e.virtualDelivered.Inc() + } else { + e.addToUnsupportedLine(line, process) + } default: e.addToUnsupportedLine(line, subprocess) } @@ -603,6 +610,11 @@ func NewPostfixExporter(showqPath string, logSrc LogSource, logUnsupportedLines Name: "bounce_non_delivery_notification_total", Help: "Total number of non delivery notification sent by bounce.", }), + virtualDelivered: prometheus.NewCounter(prometheus.CounterOpts{ + Namespace: "postfix", + Name: "virtual_delivered_total", + Help: "Total number of mail delivered to a virtual mailbox.", + }), }, nil } @@ -638,6 +650,7 @@ func (e *PostfixExporter) Describe(ch chan<- *prometheus.Desc) { e.smtpConnectionTimedOut.Describe(ch) e.opendkimSignatureAdded.Describe(ch) ch <- e.bounceNonDelivery.Desc() + ch <- e.virtualDelivered.Desc() } func (e *PostfixExporter) StartMetricCollection(ctx context.Context) { @@ -715,4 +728,5 @@ func (e *PostfixExporter) Collect(ch chan<- prometheus.Metric) { ch <- e.smtpConnectionTimedOut e.opendkimSignatureAdded.Collect(ch) ch <- e.bounceNonDelivery + ch <- e.virtualDelivered } diff --git a/postfix_exporter_test.go b/postfix_exporter_test.go index 378b67a..cb646b1 100644 --- a/postfix_exporter_test.go +++ b/postfix_exporter_test.go @@ -34,6 +34,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpdSASLAuthenticationFailures prometheus.Counter smtpdTLSConnects *prometheus.CounterVec bounceNonDelivery prometheus.Counter + virtualDelivered prometheus.Counter unsupportedLogEntries *prometheus.CounterVec } type args struct { @@ -44,6 +45,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpdMessagesProcessed int smtpMessagesProcessed int bounceNonDelivery int + virtualDelivered int } tests := []struct { name string @@ -197,6 +199,18 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { bounceNonDelivery: prometheus.NewCounter(prometheus.CounterOpts{}), }, }, + { + name: "Testing virtual delivered", + args: args{ + line: []string{ + "Apr 7 15:35:20 123-mail postfix/virtual[20235]: 199041033BE: to=, relay=virtual, delay=0.08, delays=0.08/0/0/0, dsn=2.0.0, status=sent (delivered to maildir)", + }, + virtualDelivered: 1, + }, + fields: fields{ + virtualDelivered: prometheus.NewCounter(prometheus.CounterOpts{}), + }, + }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { @@ -225,6 +239,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpdSASLAuthenticationFailures: tt.fields.smtpdSASLAuthenticationFailures, smtpdTLSConnects: tt.fields.smtpdTLSConnects, bounceNonDelivery: tt.fields.bounceNonDelivery, + virtualDelivered: tt.fields.virtualDelivered, unsupportedLogEntries: tt.fields.unsupportedLogEntries, logUnsupportedLines: true, } @@ -237,6 +252,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { assertCounterEquals(t, e.smtpdProcesses, tt.args.smtpdMessagesProcessed, "Wrong number of smtpd messages processed") assertCounterEquals(t, e.smtpProcesses, tt.args.smtpMessagesProcessed, "Wrong number of smtp messages processed") assertCounterEquals(t, e.bounceNonDelivery, tt.args.bounceNonDelivery, "Wrong number of non delivery notifications") + assertCounterEquals(t, e.virtualDelivered, tt.args.virtualDelivered, "Wrong number of delivered mails") }) } } From 4470123df6d6ef429b5905f38b314d5666343815 Mon Sep 17 00:00:00 2001 From: Thomas Paradis Date: Wed, 14 Apr 2021 10:52:11 +0200 Subject: [PATCH 4/5] Track the number of expired emails form logs --- postfix_exporter.go | 11 +++++++++++ postfix_exporter_test.go | 17 +++++++++++++++++ 2 files changed, 28 insertions(+) diff --git a/postfix_exporter.go b/postfix_exporter.go index f74dabe..6c178b5 100644 --- a/postfix_exporter.go +++ b/postfix_exporter.go @@ -53,6 +53,7 @@ type PostfixExporter struct { qmgrInsertsNrcpt prometheus.Histogram qmgrInsertsSize prometheus.Histogram qmgrRemoves prometheus.Counter + qmgrExpires prometheus.Counter smtpDelays *prometheus.HistogramVec smtpTLSConnects *prometheus.CounterVec smtpConnectionTimedOut prometheus.Counter @@ -294,6 +295,7 @@ var ( logLine = regexp.MustCompile(` ?(postfix|opendkim)(/(\w+))?\[\d+\]: (.*)`) lmtpPipeSMTPLine = regexp.MustCompile(`, relay=(\S+), .*, delays=([0-9\.]+)/([0-9\.]+)/([0-9\.]+)/([0-9\.]+), `) qmgrInsertLine = regexp.MustCompile(`:.*, size=(\d+), nrcpt=(\d+) `) + qmgrExpiredLine = regexp.MustCompile(`:.*, status=(expired|force-expired), returned to sender`) smtpStatusLine = regexp.MustCompile(`, status=(\w+) `) smtpTLSLine = regexp.MustCompile(`^(\S+) TLS connection established to \S+: (\S+) with cipher (\S+) \((\d+)/(\d+) bits\)`) smtpConnectionTimedOut = regexp.MustCompile(`^connect\s+to\s+(.*)\[(.*)\]:(\d+):\s+(Connection timed out)$`) @@ -356,6 +358,8 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { addToHistogram(e.qmgrInsertsNrcpt, qmgrInsertMatches[2], "QMGR nrcpt") } else if strings.HasSuffix(remainder, ": removed") { e.qmgrRemoves.Inc() + } else if qmgrExpired := qmgrExpiredLine.FindStringSubmatch(remainder); qmgrExpired != nil { + e.qmgrExpires.Inc() } else { e.addToUnsupportedLine(line, subprocess) } @@ -505,6 +509,11 @@ func NewPostfixExporter(showqPath string, logSrc LogSource, logUnsupportedLines Name: "qmgr_messages_removed_total", Help: "Total number of messages removed from mail queues.", }), + qmgrExpires: prometheus.NewCounter(prometheus.CounterOpts{ + Namespace: "postfix", + Name: "qmgr_messages_expired_total", + Help: "Total number of messages expired from mail queues.", + }), smtpDelays: prometheus.NewHistogramVec( prometheus.HistogramOpts{ Namespace: "postfix", @@ -633,6 +642,7 @@ func (e *PostfixExporter) Describe(ch chan<- *prometheus.Desc) { ch <- e.qmgrInsertsNrcpt.Desc() ch <- e.qmgrInsertsSize.Desc() ch <- e.qmgrRemoves.Desc() + ch <- e.qmgrExpires.Desc() e.smtpDelays.Describe(ch) e.smtpTLSConnects.Describe(ch) ch <- e.smtpDeferreds.Desc() @@ -711,6 +721,7 @@ func (e *PostfixExporter) Collect(ch chan<- prometheus.Metric) { ch <- e.qmgrInsertsNrcpt ch <- e.qmgrInsertsSize ch <- e.qmgrRemoves + ch <- e.qmgrExpires e.smtpDelays.Collect(ch) e.smtpTLSConnects.Collect(ch) ch <- e.smtpDeferreds diff --git a/postfix_exporter_test.go b/postfix_exporter_test.go index cb646b1..af26a12 100644 --- a/postfix_exporter_test.go +++ b/postfix_exporter_test.go @@ -20,6 +20,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { qmgrInsertsNrcpt prometheus.Histogram qmgrInsertsSize prometheus.Histogram qmgrRemoves prometheus.Counter + qmgrExpires prometheus.Counter smtpDelays *prometheus.HistogramVec smtpTLSConnects *prometheus.CounterVec smtpDeferreds prometheus.Counter @@ -40,6 +41,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { type args struct { line []string removedCount int + expiredCount int saslFailedCount int outgoingTLS int smtpdMessagesProcessed int @@ -110,6 +112,19 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), }, }, + { + name: "qmgr expired", + args: args{ + line: []string{ + "Apr 10 14:50:16 mail postfix/qmgr[3663]: BACE842E72: from=, status=expired, returned to sender", + "Apr 10 14:50:16 mail postfix/qmgr[3663]: BACE842E73: from=, status=force-expired, returned to sender", + }, + expiredCount: 2, + }, + fields: fields{ + qmgrExpires: prometheus.NewCounter(prometheus.CounterOpts{}), + }, + }, { name: "SASL Failed", args: args{ @@ -225,6 +240,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { qmgrInsertsNrcpt: tt.fields.qmgrInsertsNrcpt, qmgrInsertsSize: tt.fields.qmgrInsertsSize, qmgrRemoves: tt.fields.qmgrRemoves, + qmgrExpires: tt.fields.qmgrExpires, smtpDelays: tt.fields.smtpDelays, smtpTLSConnects: tt.fields.smtpTLSConnects, smtpDeferreds: tt.fields.smtpDeferreds, @@ -247,6 +263,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { e.CollectFromLogLine(line) } assertCounterEquals(t, e.qmgrRemoves, tt.args.removedCount, "Wrong number of lines counted") + assertCounterEquals(t, e.qmgrExpires, tt.args.expiredCount, "Wrong number of qmgr expired lines counted") assertCounterEquals(t, e.smtpdSASLAuthenticationFailures, tt.args.saslFailedCount, "Wrong number of Sasl counter counted") assertCounterEquals(t, e.smtpTLSConnects, tt.args.outgoingTLS, "Wrong number of TLS connections counted") assertCounterEquals(t, e.smtpdProcesses, tt.args.smtpdMessagesProcessed, "Wrong number of smtpd messages processed") From 0523537d20d6927604d7318a220a74d3983fb4ac Mon Sep 17 00:00:00 2001 From: Thomas Paradis Date: Wed, 14 Apr 2021 12:40:02 +0200 Subject: [PATCH 5/5] Expose the severity of unsupported lines --- postfix_exporter.go | 33 ++++++++++++++------------- postfix_exporter_test.go | 49 +++++++++++++++++++++++++++++++++++----- 2 files changed, 60 insertions(+), 22 deletions(-) diff --git a/postfix_exporter.go b/postfix_exporter.go index 6c178b5..56691cc 100644 --- a/postfix_exporter.go +++ b/postfix_exporter.go @@ -292,7 +292,7 @@ func CollectShowqFromSocket(path string, ch chan<- prometheus.Metric) error { // Patterns for parsing log messages. var ( - logLine = regexp.MustCompile(` ?(postfix|opendkim)(/(\w+))?\[\d+\]: (.*)`) + logLine = regexp.MustCompile(` ?(postfix|opendkim)(/(\w+))?\[\d+\]: ((?:(warning|error|fatal|panic): )?.*)`) lmtpPipeSMTPLine = regexp.MustCompile(`, relay=(\S+), .*, delays=([0-9\.]+)/([0-9\.]+)/([0-9\.]+)/([0-9\.]+), `) qmgrInsertLine = regexp.MustCompile(`:.*, size=(\d+), nrcpt=(\d+) `) qmgrExpiredLine = regexp.MustCompile(`:.*, status=(expired|force-expired), returned to sender`) @@ -316,10 +316,11 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { if logMatches == nil { // Unknown log entry format. - e.addToUnsupportedLine(line, "") + e.addToUnsupportedLine(line, "", "") return } process := logMatches[1] + level := logMatches[5] remainder := logMatches[4] switch process { case "postfix": @@ -332,7 +333,7 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { } else if strings.Contains(remainder, ": reject: ") { e.cleanupRejects.Inc() } else { - e.addToUnsupportedLine(line, subprocess) + e.addToUnsupportedLine(line, subprocess, level) } case "lmtp": if lmtpMatches := lmtpPipeSMTPLine.FindStringSubmatch(remainder); lmtpMatches != nil { @@ -341,7 +342,7 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { addToHistogramVec(e.lmtpDelays, lmtpMatches[4], "LMTP sdelay", "connection_setup") addToHistogramVec(e.lmtpDelays, lmtpMatches[5], "LMTP xdelay", "transmission") } else { - e.addToUnsupportedLine(line, subprocess) + e.addToUnsupportedLine(line, subprocess, level) } case "pipe": if pipeMatches := lmtpPipeSMTPLine.FindStringSubmatch(remainder); pipeMatches != nil { @@ -350,7 +351,7 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { addToHistogramVec(e.pipeDelays, pipeMatches[4], "PIPE sdelay", pipeMatches[1], "connection_setup") addToHistogramVec(e.pipeDelays, pipeMatches[5], "PIPE xdelay", pipeMatches[1], "transmission") } else { - e.addToUnsupportedLine(line, subprocess) + e.addToUnsupportedLine(line, subprocess, level) } case "qmgr": if qmgrInsertMatches := qmgrInsertLine.FindStringSubmatch(remainder); qmgrInsertMatches != nil { @@ -361,7 +362,7 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { } else if qmgrExpired := qmgrExpiredLine.FindStringSubmatch(remainder); qmgrExpired != nil { e.qmgrExpires.Inc() } else { - e.addToUnsupportedLine(line, subprocess) + e.addToUnsupportedLine(line, subprocess, level) } case "smtp": if smtpMatches := lmtpPipeSMTPLine.FindStringSubmatch(remainder); smtpMatches != nil { @@ -380,7 +381,7 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { } else if smtpMatches := smtpConnectionTimedOut.FindStringSubmatch(remainder); smtpMatches != nil { e.smtpConnectionTimedOut.Inc() } else { - e.addToUnsupportedLine(line, subprocess) + e.addToUnsupportedLine(line, subprocess, level) } case "smtpd": if strings.HasPrefix(remainder, "connect from ") { @@ -402,40 +403,40 @@ func (e *PostfixExporter) CollectFromLogLine(line string) { } else if smtpdTLSMatches := smtpdTLSLine.FindStringSubmatch(remainder); smtpdTLSMatches != nil { e.smtpdTLSConnects.WithLabelValues(smtpdTLSMatches[1:]...).Inc() } else { - e.addToUnsupportedLine(line, subprocess) + e.addToUnsupportedLine(line, subprocess, level) } case "bounce": if bounceMatches := bounceNonDeliveryLine.FindStringSubmatch(remainder); bounceMatches != nil { e.bounceNonDelivery.Inc() } else { - e.addToUnsupportedLine(line, process) + e.addToUnsupportedLine(line, process, level) } case "virtual": if strings.HasSuffix(remainder, ", status=sent (delivered to maildir)") { e.virtualDelivered.Inc() } else { - e.addToUnsupportedLine(line, process) + e.addToUnsupportedLine(line, process, level) } default: - e.addToUnsupportedLine(line, subprocess) + e.addToUnsupportedLine(line, subprocess, level) } case "opendkim": if opendkimMatches := opendkimSignatureAdded.FindStringSubmatch(remainder); opendkimMatches != nil { e.opendkimSignatureAdded.WithLabelValues(opendkimMatches[1], opendkimMatches[2]).Inc() } else { - e.addToUnsupportedLine(line, process) + e.addToUnsupportedLine(line, process, level) } default: // Unknown log entry format. - e.addToUnsupportedLine(line, "") + e.addToUnsupportedLine(line, process, level) } } -func (e *PostfixExporter) addToUnsupportedLine(line string, subprocess string) { +func (e *PostfixExporter) addToUnsupportedLine(line string, subprocess string, level string) { if e.logUnsupportedLines { log.Printf("Unsupported Line: %v", line) } - e.unsupportedLogEntries.WithLabelValues(subprocess).Inc() + e.unsupportedLogEntries.WithLabelValues(subprocess, level).Inc() } func addToHistogram(h prometheus.Histogram, value, fieldName string) { @@ -600,7 +601,7 @@ func NewPostfixExporter(showqPath string, logSrc LogSource, logUnsupportedLines Name: "unsupported_log_entries_total", Help: "Log entries that could not be processed.", }, - []string{"service"}), + []string{"service", "level"}), smtpStatusDeferred: prometheus.NewCounter(prometheus.CounterOpts{ Namespace: "postfix", Name: "smtp_status_deferred", diff --git a/postfix_exporter_test.go b/postfix_exporter_test.go index af26a12..8f057a8 100644 --- a/postfix_exporter_test.go +++ b/postfix_exporter_test.go @@ -48,6 +48,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpMessagesProcessed int bounceNonDelivery int virtualDelivered int + unsupportedLogEntries []string } tests := []struct { name string @@ -65,7 +66,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { }, fields: fields{ qmgrRemoves: prometheus.NewCounter(prometheus.CounterOpts{}), - unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), + unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"service", "level"}), }, }, { @@ -109,7 +110,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { }, fields: fields{ qmgrRemoves: prometheus.NewCounter(prometheus.CounterOpts{}), - unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), + unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"service", "level"}), }, }, { @@ -138,7 +139,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { }, fields: fields{ smtpdSASLAuthenticationFailures: prometheus.NewCounter(prometheus.CounterOpts{}), - unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), + unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"service", "level"}), smtpProcesses: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"status"}), }, }, @@ -155,7 +156,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpdMessagesProcessed: 2, }, fields: fields{ - unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), + unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"service", "level"}), smtpdProcesses: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"sasl_method"}), }, }, @@ -172,7 +173,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { smtpdMessagesProcessed: 0, }, fields: fields{ - unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), + unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"service", "level"}), smtpTLSConnects: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"Verified", "TLSv1.2", "ECDHE-RSA-AES256-GCM-SHA384", "256", "256"}), smtpProcesses: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"status"}), }, @@ -207,7 +208,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { bounceNonDelivery: 1, }, fields: fields{ - unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"process"}), + unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"service", "level"}), smtpDelays: prometheus.NewHistogramVec(prometheus.HistogramOpts{}, []string{"stage"}), smtpStatusDeferred: prometheus.NewCounter(prometheus.CounterOpts{}), smtpProcesses: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"status"}), @@ -226,6 +227,25 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { virtualDelivered: prometheus.NewCounter(prometheus.CounterOpts{}), }, }, + { + name: "Testing levels of unsupported entries", + args: args{ + line: []string{ + "Feb 14 19:05:25 123-mail postfix/smtpd[1517]: table hash:/etc/postfix/virtual_mailbox_maps(0,lock|fold_fix) has changed -- restarting", + "Mar 16 12:28:02 123-mail postfix/smtpd[16268]: fatal: file /etc/postfix/main.cf: parameter default_privs: unknown user name value: nobody", + "Mar 16 23:30:44 123-mail postfix/qmgr[29980]: warning: please avoid flushing the whole queue when you have", + "Mar 16 23:30:44 123-mail postfix/qmgr[29980]: warning: lots of deferred mail, that is bad for performance", + }, + unsupportedLogEntries: []string{ + `label: label: counter: `, + `label: label: counter: `, + `label: label: counter: `, + }, + }, + fields: fields{ + unsupportedLogEntries: prometheus.NewCounterVec(prometheus.CounterOpts{}, []string{"service", "level"}), + }, + }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { @@ -270,6 +290,7 @@ func TestPostfixExporter_CollectFromLogline(t *testing.T) { assertCounterEquals(t, e.smtpProcesses, tt.args.smtpMessagesProcessed, "Wrong number of smtp messages processed") assertCounterEquals(t, e.bounceNonDelivery, tt.args.bounceNonDelivery, "Wrong number of non delivery notifications") assertCounterEquals(t, e.virtualDelivered, tt.args.virtualDelivered, "Wrong number of delivered mails") + assertVecMetricsEquals(t, e.unsupportedLogEntries, tt.args.unsupportedLogEntries, "Wrong number of unsupportedLogEntries") }) } } @@ -309,3 +330,19 @@ func assertCounterEquals(t *testing.T, counter prometheus.Collector, expected in } } } +func assertVecMetricsEquals(t *testing.T, counter *prometheus.CounterVec, expected []string, message string) { + if expected != nil { + metricsChan := make(chan prometheus.Metric) + go func() { + counter.Collect(metricsChan) + close(metricsChan) + }() + var res []string + for metric := range metricsChan { + metricDto := io_prometheus_client.Metric{} + metric.Write(&metricDto) + res = append(res, metricDto.String()) + } + assert.Equal(t, expected, res, message) + } +}