From 0523537d20d6927604d7318a220a74d3983fb4ac Mon Sep 17 00:00:00 2001 From: Thomas Paradis Date: Wed, 14 Apr 2021 12:40:02 +0200 Subject: [PATCH] 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) + } +}