expiration-mailer: truncate serials and dns names (#6148)

This avoids sending excessively large emails and excessively large log
lines.

Fixes #6085

cmd/expiration-mailer/main.go

@@ -106,7 +106,18 @@ func (m *mailer) sendNags(conn bmail.Conn, contacts []string, certs []*x509.Cert
 	}
 	domains = core.UniqueLowerNames(domains)
 	sort.Strings(domains)
-	m.log.Debugf("Sending mail for %s (%s)", strings.Join(domains, ", "), strings.Join(serials, ", "))
+
+	const maxSerials = 100
+	truncatedSerials := serials
+	if len(truncatedSerials) > maxSerials {
+		truncatedSerials = serials[0:maxSerials]
+	}
+
+	const maxDomains = 100
+	truncatedDomains := domains
+	if len(truncatedDomains) > maxDomains {
+		truncatedDomains = domains[0:maxDomains]
+	}
 
 	// Construct the information about the expiring certificates for use in the
 	// subject template
@@ -128,13 +139,17 @@ func (m *mailer) sendNags(conn bmail.Conn, contacts []string, certs []*x509.Cert
 	}
 
 	email := struct {
-		ExpirationDate   string
+		ExpirationDate     string
-		DaysToExpiration int
+		DaysToExpiration   int
-		DNSNames         string
+		DNSNames           string
+		TruncatedDNSNames  string
+		NumDNSNamesOmitted int
 	}{
-		ExpirationDate:   expDate.UTC().Format(time.RFC822Z),
+		ExpirationDate:     expDate.UTC().Format(time.RFC822Z),
-		DaysToExpiration: int(expiresIn.Hours() / 24),
+		DaysToExpiration:   int(expiresIn.Hours() / 24),
-		DNSNames:         strings.Join(domains, "\n"),
+		DNSNames:           strings.Join(domains, "\n"),
+		TruncatedDNSNames:  strings.Join(truncatedDomains, "\n"),
+		NumDNSNamesOmitted: len(domains) - len(truncatedDomains),
 	}
 	msgBuf := new(bytes.Buffer)
 	err = m.emailTemplate.Execute(msgBuf, email)
@@ -144,15 +159,15 @@ func (m *mailer) sendNags(conn bmail.Conn, contacts []string, certs []*x509.Cert
 	}
 
 	logItem := struct {
-		Rcpt             []string
+		Rcpt              []string
-		Serials          []string
+		DaysToExpiration  int
-		DaysToExpiration int
+		TruncatedDNSNames []string
-		DNSNames         []string
+		TruncatedSerials  []string
 	}{
-		Rcpt:             emails,
+		Rcpt:              emails,
-		Serials:          serials,
+		DaysToExpiration:  email.DaysToExpiration,
-		DaysToExpiration: email.DaysToExpiration,
+		TruncatedDNSNames: truncatedDomains,
-		DNSNames:         domains,
+		TruncatedSerials:  truncatedSerials,
 	}
 	logStr, err := json.Marshal(logItem)
 	if err != nil {

cmd/expiration-mailer/main_test.go

@@ -85,11 +85,50 @@ var (
   "n":"rFH5kUBZrlPj73epjJjyCxzVzZuV--JjKgapoqm9pOuOt20BUTdHqVfC2oDclqM7HFhkkX9OSJMTHgZ7WaVqZv9u1X2yjdx9oVmMLuspX7EytW_ZKDZSzL-sCOFCuQAuYKkLbsdcA3eHBK_lwc4zwdeHFMKIulNvLqckkqYB9s8GpgNXBDIQ8GjR5HuJke_WUNjYHSd8jY1LU9swKWsLQe2YoQUz_ekQvBvBCoaFEtrtRaSJKNLIVDObXFr2TLIiFiM0Em90kK01-eQ7ZiruZTKomll64bRFPoNo4_uwubddg3xTqur2vdF3NyhTrYdvAgTem4uC0PFjEQ1bK_djBQ",
   "e":"AQAB"
 }`)
-	log      = blog.UseMock()
 	tmpl     = template.Must(template.New("expiry-email").Parse(testTmpl))
 	subjTmpl = template.Must(template.New("expiry-email-subject").Parse("Testing: " + defaultExpirationSubject))
 )
 
+func TestSendNagsManyCerts(t *testing.T) {
+	mc := mocks.Mailer{}
+	rs := newFakeRegStore()
+	fc := newFakeClock(t)
+
+	staticTmpl := template.Must(template.New("expiry-email-subject-static").Parse(testEmailSubject))
+	tmpl := template.Must(template.New("expiry-email").Parse(
+		`cert for DNS names {{.TruncatedDNSNames}} is going to expire in {{.DaysToExpiration}} days ({{.ExpirationDate}})`))
+
+	m := mailer{
+		log:           blog.NewMock(),
+		mailer:        &mc,
+		emailTemplate: tmpl,
+		// Explicitly override the default subject to use testEmailSubject
+		subjectTemplate: staticTmpl,
+		rs:              rs,
+		clk:             fc,
+		stats:           initStats(metrics.NoopRegisterer),
+	}
+
+	var certs []*x509.Certificate
+	for i := 0; i < 101; i++ {
+		certs = append(certs, &x509.Certificate{
+			SerialNumber: big.NewInt(0x0304),
+			NotAfter:     fc.Now().AddDate(0, 0, 2),
+			DNSNames:     []string{fmt.Sprintf("example-%d.com", i)},
+		})
+	}
+
+	conn, err := m.mailer.Connect()
+	test.AssertNotError(t, err, "connecting SMTP")
+	err = m.sendNags(conn, []string{emailA}, certs)
+	test.AssertNotError(t, err, "sending mail")
+
+	test.AssertEquals(t, len(mc.Messages), 1)
+	if len(strings.Split(mc.Messages[0].Body, "\n")) > 100 {
+		t.Errorf("Expected mailed message to truncate after 100 domains, got: %q", mc.Messages[0].Body)
+	}
+}
+
 func TestSendNags(t *testing.T) {
 	mc := mocks.Mailer{}
 	rs := newFakeRegStore()
@@ -97,6 +136,7 @@ func TestSendNags(t *testing.T) {
 
 	staticTmpl := template.Must(template.New("expiry-email-subject-static").Parse(testEmailSubject))
 
+	log := blog.NewMock()
 	m := mailer{
 		log:           log,
 		mailer:        &mc,
@@ -156,13 +196,13 @@ func TestSendNags(t *testing.T) {
 	if !strings.Contains(sendLogs[0], `"Rcpt":["rolandshoemaker@gmail.com"]`) {
 		t.Errorf("expected first 'attempting send' log line to have one address, got %q", sendLogs[0])
 	}
-	if !strings.Contains(sendLogs[0], `"Serials":["000000000000000000000000000000000304"]`) {
+	if !strings.Contains(sendLogs[0], `"TruncatedSerials":["000000000000000000000000000000000304"]`) {
 		t.Errorf("expected first 'attempting send' log line to have one serial, got %q", sendLogs[0])
 	}
 	if !strings.Contains(sendLogs[0], `"DaysToExpiration":2`) {
 		t.Errorf("expected first 'attempting send' log line to have 2 days to expiration, got %q", sendLogs[0])
 	}
-	if !strings.Contains(sendLogs[0], `"DNSNames":["example.com"]`) {
+	if !strings.Contains(sendLogs[0], `"TruncatedDNSNames":["example.com"]`) {
 		t.Errorf("expected first 'attempting send' log line to have 1 domain, 'example.com', got %q", sendLogs[0])
 	}
 }
@@ -193,14 +233,13 @@ func TestProcessCerts(t *testing.T) {
 	testCtx := setup(t, []time.Duration{time.Hour * 24 * 7})
 
 	certs := addExpiringCerts(t, testCtx)
-	log.Clear()
 	testCtx.m.processCerts(context.Background(), certs)
 	// Test that the lastExpirationNagSent was updated for the certificate
 	// corresponding to serial4, which is set up as "already renewed" by
 	// addExpiringCerts.
-	if len(log.GetAllMatching("DEBUG: SQL:  UPDATE certificateStatus .*2006-01-02 15:04:05.999999999.*\"000000000000000000000000000000001339\"")) != 1 {
+	if len(testCtx.log.GetAllMatching("DEBUG: SQL:  UPDATE certificateStatus .*2006-01-02 15:04:05.999999999.*\"000000000000000000000000000000001339\"")) != 1 {
 		t.Errorf("Expected an update to certificateStatus, got these log lines:\n%s",
-			strings.Join(log.GetAllMatching(".*"), "\n"))
+			strings.Join(testCtx.log.GetAllMatching(".*"), "\n"))
 	}
 }
 
@@ -223,7 +262,6 @@ func TestNoContactCertIsNotRenewed(t *testing.T) {
 	err = insertCertificate(cert, time.Time{})
 	test.AssertNotError(t, err, "inserting certificate")
 
-	log.Clear()
 	err = testCtx.m.findExpiringCertificates(context.Background())
 	test.AssertNotError(t, err, "finding expired certificates")
 
@@ -275,7 +313,6 @@ func TestNoContactCertIsRenewed(t *testing.T) {
 	})
 	test.AssertNotError(t, err, "inserting FQDNSet for renewal")
 
-	log.Clear()
 	err = testCtx.m.findExpiringCertificates(context.Background())
 	test.AssertNotError(t, err, "finding expired certificates")
 
@@ -299,14 +336,13 @@ func TestProcessCertsParallel(t *testing.T) {
 
 	testCtx.m.parallelSends = 2
 	certs := addExpiringCerts(t, testCtx)
-	log.Clear()
 	testCtx.m.processCerts(context.Background(), certs)
 	// Test that the lastExpirationNagSent was updated for the certificate
 	// corresponding to serial4, which is set up as "already renewed" by
 	// addExpiringCerts.
-	if len(log.GetAllMatching("DEBUG: SQL:  UPDATE certificateStatus .*2006-01-02 15:04:05.999999999.*\"000000000000000000000000000000001339\"")) != 1 {
+	if len(testCtx.log.GetAllMatching("DEBUG: SQL:  UPDATE certificateStatus .*2006-01-02 15:04:05.999999999.*\"000000000000000000000000000000001339\"")) != 1 {
 		t.Errorf("Expected an update to certificateStatus, got these log lines:\n%s",
-			strings.Join(log.GetAllMatching(".*"), "\n"))
+			strings.Join(testCtx.log.GetAllMatching(".*"), "\n"))
 	}
 }
 
@@ -330,12 +366,10 @@ func TestFindExpiringCertificates(t *testing.T) {
 
 	addExpiringCerts(t, testCtx)
 
-	log.Clear()
 	err := testCtx.m.findExpiringCertificates(context.Background())
 	test.AssertNotError(t, err, "Failed on no certificates")
-	test.AssertEquals(t, len(log.GetAllMatching("Searching for certificates that expire between.*")), 3)
+	test.AssertEquals(t, len(testCtx.log.GetAllMatching("Searching for certificates that expire between.*")), 3)
 
-	log.Clear()
 	err = testCtx.m.findExpiringCertificates(context.Background())
 	test.AssertNotError(t, err, "Failed to find expiring certs")
 	// Should get 001 and 003
@@ -364,11 +398,10 @@ func TestFindExpiringCertificates(t *testing.T) {
 	}, testCtx.mc.Messages[1])
 
 	// Check that regC's only certificate being renewed does not cause a log
-	test.AssertEquals(t, len(log.GetAllMatching("no certs given to send nags for")), 0)
+	test.AssertEquals(t, len(testCtx.log.GetAllMatching("no certs given to send nags for")), 0)
 
 	// A consecutive run shouldn't find anything
 	testCtx.mc.Clear()
-	log.Clear()
 	err = testCtx.m.findExpiringCertificates(context.Background())
 	test.AssertNotError(t, err, "Failed to find expiring certs")
 	test.AssertEquals(t, len(testCtx.mc.Messages), 0)
@@ -528,8 +561,6 @@ func TestFindCertsAtCapacity(t *testing.T) {
 
 	addExpiringCerts(t, testCtx)
 
-	log.Clear()
-
 	// Set the limit to 1 so we are "at capacity" with one result
 	testCtx.m.limit = 1
 
@@ -546,7 +577,6 @@ func TestFindCertsAtCapacity(t *testing.T) {
 
 	// A consecutive run shouldn't find anything
 	testCtx.mc.Clear()
-	log.Clear()
 	err = testCtx.m.findExpiringCertificates(context.Background())
 	test.AssertNotError(t, err, "Failed to find expiring certs")
 	test.AssertEquals(t, len(testCtx.mc.Messages), 0)
@@ -844,6 +874,7 @@ type testCtx struct {
 	mc      *mocks.Mailer
 	fc      clock.FakeClock
 	m       *mailer
+	log     *blog.Mock
 	cleanUp func()
 }
 
@@ -856,6 +887,7 @@ func setup(t *testing.T, nagTimes []time.Duration) *testCtx {
 	}
 
 	fc := newFakeClock(t)
+	log := blog.NewMock()
 	ssa, err := sa.NewSQLStorageAuthority(dbMap, dbMap, nil, nil, fc, log, metrics.NoopRegisterer, 1)
 	if err != nil {
 		t.Fatalf("unable to create SQLStorageAuthority: %s", err)
@@ -887,6 +919,7 @@ func setup(t *testing.T, nagTimes []time.Duration) *testCtx {
 		mc:      mc,
 		fc:      fc,
 		m:       m,
+		log:     log,
 		cleanUp: cleanUp,
 	}
 }

test/config-next/expiration-mailer.gotmpl

@@ -0,0 +1,6 @@
+Hello,
+
+Your SSL certificate for names {{.TruncatedDNSNames}}{{if(gt .NumDNSNamesOmitted 0)}} (and {{.NumDNSNamesOmitted}} more){{end}} is going to expire in {{.DaysToExpiration}}
+days ({{.ExpirationDate}}), make sure you run the renewer before then!
+
+Regards

test/config-next/expiration-mailer.json

@@ -11,7 +11,7 @@
     },
     "certLimit": 100000,
     "nagTimes": ["480h", "240h"],
-    "emailTemplate": "test/example-expiration-template",
+    "emailTemplate": "test/config-next/expiration-mailer.gotmpl",
     "debugAddr": ":8008",
     "parallelSends": 10,
     "tls": {

test/config/expiration-mailer.json

@@ -12,7 +12,7 @@
     "certLimit": 100000,
     "nagTimes": ["480h", "240h"],
     "nagCheckInterval": "24h",
-    "emailTemplate": "test/example-expiration-template",
+    "emailTemplate": "test/config/expiration-mailer.gotmpl",
     "debugAddr": ":8008",
     "tls": {
       "caCertFile": "test/grpc-creds/minica.pem",