Skip to content

Commit b16585b

Browse files
cpujsha
cpu
authored and
jsha
committed
notify-mailer monitor progress (letsencrypt#2046)
This PR adds a `printStatus` function that is called every iteration of the mailer's `run()` loop. The status output is logged at the `info` level and includes the destination email, the current message being sent, the total number of messages to send, and the elapsed time since `run()` started. The status output can be disabled by lowering the default syslog level in the `notify-mailer` config. Additionally, this PR adds stats support for the mailer package. Three new stats are published during the `MailerImpl`'s `SendMail` function (called in a loop by the mailer utilities): `Mailer.SendMail.Attempts` `Mailer.SendMail.Successes` `Mailer.SendMail.Errors` This PR removes two stats from the `expiration-mailer` that are redundant copies of the above: `Mailer.Expiration.Errors.SendingNag.SendFailure` `Mailer.Expiration.Sent` This resolves letsencrypt#2026.
1 parent c4efb7b commit b16585b

File tree

7 files changed

+88
-18
lines changed

7 files changed

+88
-18
lines changed

‎cmd/expiration-mailer/main.go‎

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -106,13 +106,11 @@ func (m *mailer) sendNags(contacts []*core.AcmeURL, certs []*x509.Certificate) e
106106
startSending := m.clk.Now()
107107
err = m.mailer.SendMail(emails, m.subject, msgBuf.String())
108108
if err != nil {
109-
m.stats.Inc("Mailer.Expiration.Errors.SendingNag.SendFailure", 1, 1.0)
110109
return err
111110
}
112111
finishSending := m.clk.Now()
113112
elapsed := finishSending.Sub(startSending)
114113
m.stats.TimingDuration("Mailer.Expiration.SendLatency", elapsed, 1.0)
115-
m.stats.Inc("Mailer.Expiration.Sent", int64(len(emails)), 1.0)
116114
return nil
117115
}
118116

@@ -398,7 +396,13 @@ func main() {
398396

399397
smtpPassword, err := c.Mailer.PasswordConfig.Pass()
400398
cmd.FailOnError(err, "Failed to load SMTP password")
401-
mailClient := mail.New(c.Mailer.Server, c.Mailer.Port, c.Mailer.Username, smtpPassword, *fromAddress)
399+
mailClient := mail.New(
400+
c.Mailer.Server,
401+
c.Mailer.Port,
402+
c.Mailer.Username,
403+
smtpPassword,
404+
*fromAddress,
405+
stats)
402406
err = mailClient.Connect()
403407
cmd.FailOnError(err, "Couldn't connect to mail server.")
404408
defer func() {

‎cmd/expiration-mailer/main_test.go‎

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -433,8 +433,6 @@ func TestFindCertsAtCapacity(t *testing.T) {
433433
// findExpiringCertificates() ends up invoking sendNags which calls
434434
// TimingDuration so we need to EXPECT that with the mock
435435
statter.EXPECT().TimingDuration("Mailer.Expiration.SendLatency", time.Duration(0), float32(1.0))
436-
// We should send 1 mail, incrementing the corresponding stat
437-
statter.EXPECT().Inc("Mailer.Expiration.Sent", int64(1), float32(1.0))
438436
// Similarly, findExpiringCerticates() sends its latency as well
439437
statter.EXPECT().TimingDuration("Mailer.Expiration.ProcessingCertificatesLatency", time.Duration(0), float32(1.0))
440438

‎cmd/notify-mailer/main.go‎

Lines changed: 26 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ import (
1414
"github.com/letsencrypt/boulder/cmd"
1515
blog "github.com/letsencrypt/boulder/log"
1616
bmail "github.com/letsencrypt/boulder/mail"
17+
"github.com/letsencrypt/boulder/metrics"
1718
"github.com/letsencrypt/boulder/sa"
1819
)
1920

@@ -74,6 +75,19 @@ func (m *mailer) ok() error {
7475
return nil
7576
}
7677

78+
func (m *mailer) printStatus(to string, cur, total int, start time.Time) {
79+
// Should never happen
80+
if total <= 0 || cur < 0 || cur > total {
81+
m.log.AuditErr(fmt.Sprintf(
82+
"invalid cur (%d) or total (%d)\n", cur, total))
83+
}
84+
completion := (float32(cur) / float32(total)) * 100
85+
now := m.clk.Now()
86+
elapsed := now.Sub(start)
87+
m.log.Info(fmt.Sprintf("Sending to %q. Message %d of %d [%.2f%%]. Elapsed: %s\n",
88+
to, cur, total, completion, elapsed.String()))
89+
}
90+
7791
func (m *mailer) run() error {
7892
if err := m.ok(); err != nil {
7993
return err
@@ -84,7 +98,10 @@ func (m *mailer) run() error {
8498
return err
8599
}
86100

87-
for _, dest := range destinations {
101+
startTime := m.clk.Now()
102+
103+
for i, dest := range destinations {
104+
m.printStatus(dest, i, len(destinations), startTime)
88105
if strings.TrimSpace(dest) == "" {
89106
continue
90107
}
@@ -257,6 +274,8 @@ func main() {
257274
cmd.PasswordConfig
258275
cmd.SMTPConfig
259276
}
277+
Statsd cmd.StatsdConfig
278+
Syslog cmd.SyslogConfig
260279
}
261280
configFile := flag.String("config", "", "File containing a JSON config.")
262281

@@ -272,18 +291,20 @@ func main() {
272291
os.Exit(1)
273292
}
274293

275-
_, log := cmd.StatsAndLogging(cmd.StatsdConfig{}, cmd.SyslogConfig{StdoutLevel: 7})
276-
277294
configData, err := ioutil.ReadFile(*configFile)
278295
cmd.FailOnError(err, fmt.Sprintf("Reading %q", *configFile))
279296
var cfg config
280297
err = json.Unmarshal(configData, &cfg)
281298
cmd.FailOnError(err, "Unmarshaling config")
282299

300+
stats, log := cmd.StatsAndLogging(cfg.Statsd, cfg.Syslog)
301+
defer log.AuditPanic()
302+
283303
dbURL, err := cfg.NotifyMailer.DBConfig.URL()
284304
cmd.FailOnError(err, "Couldn't load DB URL")
285305
dbMap, err := sa.NewDbMap(dbURL, 10)
286306
cmd.FailOnError(err, "Could not connect to database")
307+
go sa.ReportDbConnCount(dbMap, metrics.NewStatsdScope(stats, "NotificationMailer"))
287308

288309
// Load email body
289310
body, err := ioutil.ReadFile(*bodyFile)
@@ -311,7 +332,8 @@ func main() {
311332
cfg.NotifyMailer.Port,
312333
cfg.NotifyMailer.Username,
313334
smtpPassword,
314-
*address)
335+
*address,
336+
stats)
315337
}
316338
err = mailClient.Connect()
317339
cmd.FailOnError(err, fmt.Sprintf("Connecting to %s:%s",

‎cmd/notify-mailer/main_test.go‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ import (
99

1010
"github.com/jmhodges/clock"
1111

12+
blog "github.com/letsencrypt/boulder/log"
1213
"github.com/letsencrypt/boulder/mocks"
1314
"github.com/letsencrypt/boulder/test"
1415
)
@@ -58,6 +59,7 @@ func TestSleepInterval(t *testing.T) {
5859

5960
// Set up a mock mailer that sleeps for `sleepLen` seconds
6061
m := &mailer{
62+
log: blog.UseMock(),
6163
mailer: mc,
6264
emailTemplate: "",
6365
sleepInterval: sleepLen * time.Second,
@@ -78,6 +80,7 @@ func TestSleepInterval(t *testing.T) {
7880

7981
// Set up a mock mailer that doesn't sleep at all
8082
m = &mailer{
83+
log: blog.UseMock(),
8184
mailer: mc,
8285
emailTemplate: "",
8386
sleepInterval: 0,
@@ -109,6 +112,7 @@ func TestMailCheckpointing(t *testing.T) {
109112
// Create a mailer with a checkpoint interval larger than the number of
110113
// destinations
111114
m := &mailer{
115+
log: blog.UseMock(),
112116
mailer: mc,
113117
dbMap: dbMap,
114118
subject: testSubject,
@@ -127,6 +131,7 @@ func TestMailCheckpointing(t *testing.T) {
127131

128132
// Create a mailer with a negative sleep interval
129133
m = &mailer{
134+
log: blog.UseMock(),
130135
mailer: mc,
131136
dbMap: dbMap,
132137
subject: testSubject,
@@ -146,6 +151,7 @@ func TestMailCheckpointing(t *testing.T) {
146151
// Create a mailer with a checkpoint interval starting after 4 destinations from
147152
// the start of the file
148153
m = &mailer{
154+
log: blog.UseMock(),
149155
mailer: mc,
150156
dbMap: dbMap,
151157
subject: testSubject,
@@ -181,6 +187,7 @@ func TestMailCheckpointing(t *testing.T) {
181187

182188
// Create a mailer with a checkpoint interval ending after 3 destinations
183189
m = &mailer{
190+
log: blog.UseMock(),
184191
mailer: mc,
185192
dbMap: dbMap,
186193
subject: testSubject,
@@ -217,6 +224,7 @@ func TestMailCheckpointing(t *testing.T) {
217224
// Create a mailer with a checkpoint interval covering 2 destinations from the
218225
// middle of the file
219226
m = &mailer{
227+
log: blog.UseMock(),
220228
mailer: mc,
221229
dbMap: dbMap,
222230
subject: testSubject,
@@ -262,6 +270,7 @@ func TestMessageContent(t *testing.T) {
262270
dbMap := mockEmailResolver{}
263271
mc := &mocks.Mailer{}
264272
m := &mailer{
273+
log: blog.UseMock(),
265274
mailer: mc,
266275
dbMap: dbMap,
267276
subject: testSubject,
@@ -370,6 +379,7 @@ func TestResolveEmails(t *testing.T) {
370379
dbMap := mockEmailResolver{}
371380
mc := &mocks.Mailer{}
372381
m := &mailer{
382+
log: blog.UseMock(),
373383
mailer: mc,
374384
dbMap: dbMap,
375385
subject: "Test",

‎mail/mailer.go‎

Lines changed: 21 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -17,10 +17,12 @@ import (
1717
"strings"
1818
"time"
1919

20+
"github.com/cactus/go-statsd-client/statsd"
2021
"github.com/jmhodges/clock"
2122

2223
"github.com/letsencrypt/boulder/core"
2324
blog "github.com/letsencrypt/boulder/log"
25+
"github.com/letsencrypt/boulder/metrics"
2426
)
2527

2628
type idGenerator interface {
@@ -54,6 +56,7 @@ type MailerImpl struct {
5456
client smtpClient
5557
clk clock.Clock
5658
csprgSource idGenerator
59+
stats *metrics.StatsdScope
5760
}
5861

5962
type dialer interface {
@@ -100,7 +103,7 @@ func (d dryRunClient) Write(p []byte) (n int, err error) {
100103

101104
// New constructs a Mailer to represent an account on a particular mail
102105
// transfer agent.
103-
func New(server, port, username, password string, from mail.Address) *MailerImpl {
106+
func New(server, port, username, password string, from mail.Address, stats statsd.Statter) *MailerImpl {
104107
return &MailerImpl{
105108
dialer: &dialerImpl{
106109
username: username,
@@ -111,6 +114,7 @@ func New(server, port, username, password string, from mail.Address) *MailerImpl
111114
from: from,
112115
clk: clock.Default(),
113116
csprgSource: realSource{},
117+
stats: metrics.NewStatsdScope(stats, "Mailer"),
114118
}
115119
}
116120

@@ -206,9 +210,7 @@ func (di *dialerImpl) Dial() (smtpClient, error) {
206210
return client, nil
207211
}
208212

209-
// SendMail sends an email to the provided list of recipients. The email body
210-
// is simple text.
211-
func (m *MailerImpl) SendMail(to []string, subject, msg string) error {
213+
func (m *MailerImpl) sendOne(to []string, subject, msg string) error {
212214
if m.client == nil {
213215
return errors.New("call Connect before SendMail")
214216
}
@@ -228,19 +230,32 @@ func (m *MailerImpl) SendMail(to []string, subject, msg string) error {
228230
if err != nil {
229231
return err
230232
}
231-
232233
_, err = w.Write(body)
233234
if err != nil {
234235
return err
235236
}
236-
237237
err = w.Close()
238238
if err != nil {
239239
return err
240240
}
241241
return nil
242242
}
243243

244+
// SendMail sends an email to the provided list of recipients. The email body
245+
// is simple text.
246+
func (m *MailerImpl) SendMail(to []string, subject, msg string) error {
247+
m.stats.Inc("SendMail.Attempts", 1)
248+
249+
err := m.sendOne(to, subject, msg)
250+
if err != nil {
251+
m.stats.Inc("SendMail.Errors", 1)
252+
return err
253+
}
254+
255+
m.stats.Inc("SendMail.Successes", 1)
256+
return nil
257+
}
258+
244259
// Close closes the connection.
245260
func (m *MailerImpl) Close() error {
246261
if m.client == nil {

‎mail/mailer_test.go‎

Lines changed: 13 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@ import (
1010
"strings"
1111
"testing"
1212

13+
"github.com/cactus/go-statsd-client/statsd"
1314
"github.com/jmhodges/clock"
1415

1516
"github.com/letsencrypt/boulder/test"
@@ -23,8 +24,9 @@ func (f fakeSource) generate() *big.Int {
2324

2425
func TestGenerateMessage(t *testing.T) {
2526
fc := clock.NewFake()
27+
stats, _ := statsd.NewNoopClient(nil)
2628
fromAddress, _ := mail.ParseAddress("happy sender <send@email.com>")
27-
m := New("", "", "", "", *fromAddress)
29+
m := New("", "", "", "", *fromAddress, stats)
2830
m.clk = fc
2931
m.csprgSource = fakeSource{}
3032
messageBytes, err := m.generateMessage([]string{"recv@email.com"}, "test subject", "this is the body\n")
@@ -46,8 +48,9 @@ func TestGenerateMessage(t *testing.T) {
4648
}
4749

4850
func TestFailNonASCIIAddress(t *testing.T) {
51+
stats, _ := statsd.NewNoopClient(nil)
4952
fromAddress, _ := mail.ParseAddress("send@email.com")
50-
m := New("", "", "", "", *fromAddress)
53+
m := New("", "", "", "", *fromAddress, stats)
5154
_, err := m.generateMessage([]string{"遗憾@email.com"}, "test subject", "this is the body\n")
5255
test.AssertError(t, err, "Allowed a non-ASCII to address incorrectly")
5356
}
@@ -110,8 +113,15 @@ func TestConnect(t *testing.T) {
110113
}()
111114
}
112115
}()
116+
stats, _ := statsd.NewNoopClient(nil)
113117
fromAddress, _ := mail.ParseAddress("send@email.com")
114-
m := New("localhost", port, "user@example.com", "paswd", *fromAddress)
118+
m := New(
119+
"localhost",
120+
port,
121+
"user@example.com",
122+
"paswd",
123+
*fromAddress,
124+
stats)
115125
err = m.Connect()
116126
if err != nil {
117127
t.Errorf("Failed to connect: %s", err)

‎test/config/notify-mailer.json‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,5 +6,16 @@
66
"passwordFile": "test/secrets/smtp_password",
77
"dbConnectFile": "test/secrets/mailer_dburl",
88
"maxDBConns": 10
9+
},
10+
11+
"statsd": {
12+
"server": "localhost:8125",
13+
"prefix": "Boulder"
14+
},
15+
16+
"syslog": {
17+
"network": "",
18+
"server": "",
19+
"stdoutlevel": 6
920
}
1021
}

0 commit comments

Comments
 (0)