Expose the severity of unsupported lines

This commit is contained in:
Thomas Paradis 2021-04-14 12:40:02 +02:00
parent 4470123df6
commit 0523537d20
2 changed files with 60 additions and 22 deletions

View File

@ -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",

View File

@ -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:<name:"level" value:"" > label:<name:"service" value:"smtpd" > counter:<value:1 > `,
`label:<name:"level" value:"fatal" > label:<name:"service" value:"smtpd" > counter:<value:1 > `,
`label:<name:"level" value:"warning" > label:<name:"service" value:"qmgr" > counter:<value:2 > `,
},
},
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)
}
}