This implements more sleeps when clients are expected to poll

Specifically this adds two additional delay points:
- Between completing validation but before updating the order state
- After signing the certificate and before marking it as ready

It also completely refactors how these sleeps are controlled, by
replacing PEBBLE_VA_* with a single PEBBLE_SLEEPTIME environment
variable.

Author: squizzling

README.md

@@ -129,17 +129,17 @@ services:
     - 14000:14000  # ACME port
     - 15000:15000  # Management port
   environment:
-    - PEBBLE_VA_NOSLEEP=1
+    - PEBBLE_SLEEPTIME=0
   volumes:
     - ./my-pebble-config.json:/test/my-pebble-config.json
 ```
 
 With a Docker command:
 
 ```bash
-docker run -e "PEBBLE_VA_NOSLEEP=1" letsencrypt/pebble
+docker run -e "PEBBLE_SLEEPTIME=0" letsencrypt/pebble
 # or
-docker run -e "PEBBLE_VA_NOSLEEP=1" --mount src=$(pwd)/my-pebble-config.json,target=/test/my-pebble-config.json,type=bind letsencrypt/pebble pebble -config /test/my-pebble-config.json
+docker run -e "PEBBLE_SLEEPTIME=0" --mount src=$(pwd)/my-pebble-config.json,target=/test/my-pebble-config.json,type=bind letsencrypt/pebble pebble -config /test/my-pebble-config.json
 ```
 
 **Note**: The Pebble dockerfile uses [multi-stage builds](https://docs.docker.com/develop/develop-images/multistage-build/) and requires Docker CE 17.05.0-ce or newer.
@@ -197,19 +197,28 @@ for more information.
 
 ### Testing at full speed
 
-By default Pebble will sleep a random number of seconds (from 0 to 15) between
-individual challenge validation attempts. This ensures clients don't make
-assumptions about when the challenge is solved from the CA side by observing
-a single request for a challenge response. Instead clients must poll the
-challenge to observe the state since the CA may send many validation requests.
+By default, Pebble will sleep a random number of seconds (from 0 to 5) during
+specific stages of the workflow. This ensures clients don't make assumptions
+about the state of the system based on observing external behavior. Instead,
+clients must poll at the appropriate time.
 
-To test issuance "at full speed" with no artificial sleeps set the environment
-variable `PEBBLE_VA_NOSLEEP` to `1`. E.g.
+These sleeps occur at the following 3 points:
 
-`PEBBLE_VA_NOSLEEP=1 pebble -config ./test/config/pebble-config.json`
+1. Before attempting to perform a validation
+2. Between validating and updating the order state
+3. After creating the certificate and marking it as ready
 
-The maximal number of seconds to sleep can be configured by defining
-`PEBBLE_VA_SLEEPTIME`. It must be set to a positive integer.
+The maximum sleep time can be configured through the `PEBBLE_SLEEPTIME` environment
+variable. To test "at full speed" with no artificial sleeps, set the environment
+variable to `0`.
+
+For example, to test polling code by forcing a large delay:
+
+`PEBBLE_SLEEPTIME=60 pebble -config ./test/config/pebble-config.json`
+
+and to disable sleeping entirely:
+
+`PEBBLE_SLEEPTIME=0 pebble -config ./test/config/pebble-config.json`
 
 ### Skipping Validation
 

ca/ca.go

@@ -2,7 +2,7 @@ package ca
 
 import (
 	"crypto"
-	"crypto/rand"
+	crand "crypto/rand"
 	"crypto/rsa"
 	"crypto/sha1"
 	"crypto/x509"
@@ -13,6 +13,7 @@ import (
 	"log"
 	"math"
 	"math/big"
+	mrand "math/rand"
 	"net"
 	"strings"
 	"time"
@@ -31,6 +32,7 @@ type CAImpl struct {
 	log              *log.Logger
 	db               *db.MemoryStore
 	ocspResponderURL string
+	sleepTime        int
 
 	chains []*chain
 }
@@ -57,7 +59,7 @@ type issuer struct {
 }
 
 func makeSerial() *big.Int {
-	serial, err := rand.Int(rand.Reader, big.NewInt(math.MaxInt64))
+	serial, err := crand.Int(crand.Reader, big.NewInt(math.MaxInt64))
 	if err != nil {
 		panic(fmt.Sprintf("unable to create random serial number: %s", err.Error()))
 	}
@@ -92,7 +94,7 @@ func makeSubjectKeyID(key crypto.PublicKey) ([]byte, error) {
 
 // makeKey creates a new 2048 bit RSA private key and a Subject Key Identifier
 func makeKey() (*rsa.PrivateKey, []byte, error) {
-	key, err := rsa.GenerateKey(rand.Reader, 2048)
+	key, err := rsa.GenerateKey(crand.Reader, 2048)
 	if err != nil {
 		return nil, nil, err
 	}
@@ -133,7 +135,7 @@ func (ca *CAImpl) makeRootCert(
 		parent = template
 	}
 
-	der, err := x509.CreateCertificate(rand.Reader, template, parent, subjectKey.Public(), signerKey)
+	der, err := x509.CreateCertificate(crand.Reader, template, parent, subjectKey.Public(), signerKey)
 	if err != nil {
 		return nil, err
 	}
@@ -307,7 +309,7 @@ func (ca *CAImpl) newCertificate(domains []string, ips []net.IP, key crypto.Publ
 		template.OCSPServer = []string{ca.ocspResponderURL}
 	}
 
-	der, err := x509.CreateCertificate(rand.Reader, template, issuer.cert.Cert, key, issuer.key)
+	der, err := x509.CreateCertificate(crand.Reader, template, issuer.cert.Cert, key, issuer.key)
 	if err != nil {
 		return nil, err
 	}
@@ -340,10 +342,11 @@ func (ca *CAImpl) newCertificate(domains []string, ips []net.IP, key crypto.Publ
 	return newCert, nil
 }
 
-func New(log *log.Logger, db *db.MemoryStore, ocspResponderURL string, alternateRoots int, chainLength int) *CAImpl {
+func New(log *log.Logger, db *db.MemoryStore, ocspResponderURL string, alternateRoots int, chainLength int, sleepTime int) *CAImpl {
 	ca := &CAImpl{
-		log: log,
-		db:  db,
+		log:       log,
+		db:        db,
+		sleepTime: sleepTime,
 	}
 
 	if ocspResponderURL != "" {
@@ -398,6 +401,12 @@ func (ca *CAImpl) CompleteOrder(order *core.Order) {
 	}
 	ca.log.Printf("Issued certificate serial %s for order %s\n", cert.ID, order.ID)
 
+	if ca.sleepTime > 0 {
+		sleepLen := time.Duration(mrand.Intn(ca.sleepTime))
+		ca.log.Printf("Sleeping for %s seconds before marking order %s complete", time.Second*sleepLen, order.ID)
+		time.Sleep(time.Second * sleepLen)
+	}
+
 	// Lock and update the order to store the issued certificate
 	order.Lock()
 	order.CertificateObject = cert

cmd/pebble/main.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"os"
 	"strconv"
+	"strings"
 
 	"github.com/letsencrypt/pebble/ca"
 	"github.com/letsencrypt/pebble/cmd"
@@ -31,6 +32,24 @@ type config struct {
 	}
 }
 
+const (
+	// vaNoSleepEnvVar and vaSleepTimeEnvVar are deprecated environment variable
+	// names used to control sleeping in the VA. Now sleepTimeEnvVar is the proper
+	// method to manage it.  Exists for deprecation warning purposes.
+	vaNoSleepEnvVar   = "PEBBLE_VA_NOSLEEP"
+	vaSleepTimeEnvVar = "PEBBLE_VA_SLEEPTIME"
+
+	// sleepTimeEnvVar is the variable used to control if and how much the process
+	// sleeps during specific stages of the workflow. 0 disables sleeping, negative
+	// and non-integers will be ignored, and positive integers are the maximum
+	// number of seconds to sleep for.
+	sleepTimeEnvVar = "PEBBLE_SLEEPTIME"
+
+	// defaultSleepTime defines the default sleep time (in seconds) at various
+	// stages in the workflow.
+	defaultSleepTime = 5
+)
+
 func main() {
 	configFile := flag.String(
 		"config",
@@ -69,9 +88,16 @@ func main() {
 		chainLength = int(val)
 	}
 
+	sleepTime := getEnvSleepTime(logger, os.Getenv(sleepTimeEnvVar), os.Getenv(vaNoSleepEnvVar), os.Getenv(vaSleepTimeEnvVar))
+	if sleepTime == 0 {
+		logger.Print("Disabled random sleeps")
+	} else {
+		logger.Printf("Setting maximum random sleep interval to %d seconds", sleepTime)
+	}
+
 	db := db.NewMemoryStore()
-	ca := ca.New(logger, db, c.Pebble.OCSPResponderURL, alternateRoots, chainLength)
-	va := va.New(logger, c.Pebble.HTTPPort, c.Pebble.TLSPort, *strictMode, *resolverAddress)
+	ca := ca.New(logger, db, c.Pebble.OCSPResponderURL, alternateRoots, chainLength, sleepTime)
+	va := va.New(logger, c.Pebble.HTTPPort, c.Pebble.TLSPort, *strictMode, *resolverAddress, sleepTime)
 
 	for keyID, key := range c.Pebble.ExternalAccountMACKeys {
 		err := db.AddExternalAccountKeyByID(keyID, key)
@@ -117,3 +143,72 @@ func main() {
 		muxHandler)
 	cmd.FailOnError(err, "Calling ListenAndServeTLS()")
 }
+
+// getEnvSleepTime is the abstraction to decide how long to randomly sleep for. This is
+// relatively verbose, due to handling the deprecated PEBBLE_VA_* sleep methods.  Most
+// of this can be removed after a suitable transition period. The deprecated path is not
+// documented.
+func getEnvSleepTime(logger *log.Logger, envSleepTime string, envVaNoSleep string, envVaSleepTime string) int {
+	sleepTime, vaSleepTime, vaNoSleep := parseSleepEnvironment(logger, envSleepTime, envVaNoSleep, envVaSleepTime)
+
+	if sleepTime < 0 && !vaNoSleep && vaSleepTime < 0 { // 1
+		return defaultSleepTime
+	} else if sleepTime >= 0 && !vaNoSleep && vaSleepTime < 0 { // 2
+		return sleepTime
+	} else if sleepTime < 0 && !vaNoSleep && vaSleepTime >= 0 { // 3
+		return vaSleepTime
+	} else if sleepTime >= 0 && !vaNoSleep && vaSleepTime >= 0 { // 4
+		logger.Printf("WARNING: %s is present with %s, ignoring %s", sleepTimeEnvVar, vaSleepTimeEnvVar, vaSleepTimeEnvVar)
+		return sleepTime
+	} else if sleepTime < 0 && vaNoSleep && vaSleepTime < 0 { // 5
+		return 0
+	} else if sleepTime >= 0 && vaNoSleep && vaSleepTime < 0 { // 6
+		logger.Printf("WARNING: %s is present with %s, ignoring %s", sleepTimeEnvVar, vaNoSleepEnvVar, vaNoSleepEnvVar)
+		return sleepTime
+	} else if sleepTime < 0 && vaNoSleep && vaSleepTime >= 0 { // 7
+		logger.Printf("WARNING: %s is present with %s, ignoring %s", vaNoSleepEnvVar, vaSleepTimeEnvVar, vaSleepTimeEnvVar)
+		return 0
+	} else /*if sleepTime >= 0 && vaNoSleep && vaSleepTime >= 0*/ { // 8
+		logger.Printf("WARNING: %s is present with %s and %s, ignoring %s and %s", sleepTimeEnvVar, vaNoSleepEnvVar, vaSleepTimeEnvVar, vaNoSleepEnvVar, vaSleepTimeEnvVar)
+		return sleepTime
+	}
+}
+
+// parseSleepEnvironment exists to make the linter happy.  When PEBBLE_VA_* is removed,
+// whatever remains of this function should be merged with getEnvSleepTime.
+func parseSleepEnvironment(logger *log.Logger, envSleepTime string, envVaNoSleep string, envVaSleepTime string) (int, int, bool) {
+	sleepTime := -1
+	if envSleepTime != "" {
+		i, err := strconv.ParseUint(envSleepTime, 10, 64) // Uint parse makes negatives fail
+		if err != nil {
+			logger.Printf("WARNING: Failed to parse %s", sleepTimeEnvVar)
+		} else {
+			sleepTime = int(i)
+		}
+	}
+
+	vaSleepTime := -1
+	if envVaSleepTime != "" {
+		logger.Printf("WARNING: %s is deprecated, use %s=%s", vaSleepTimeEnvVar, sleepTimeEnvVar, envVaSleepTime)
+		i, err := strconv.ParseUint(envVaSleepTime, 10, 64) // Uint parse makes negatives fail
+		if err != nil {
+			logger.Printf("WARNING: Failed to parse %s", vaSleepTimeEnvVar)
+		} else {
+			vaSleepTime = int(i)
+		}
+	}
+
+	vaNoSleep := false
+	if envVaNoSleep != "" {
+		logger.Printf("WARNING: %s is deprecated, use %s=0", vaNoSleepEnvVar, sleepTimeEnvVar)
+	}
+	switch strings.ToLower(envVaNoSleep) {
+	case "1", "true":
+		vaNoSleep = true
+	case "0", "false", "":
+		// no action
+	default:
+		logger.Printf("WARNING: Failed to parse %s", vaNoSleepEnvVar)
+	}
+	return sleepTime, vaSleepTime, vaNoSleep
+}

cmd/pebble/main_test.go

@@ -1 +1,105 @@
 package main
+
+import (
+	"bytes"
+	"log"
+	"strings"
+	"testing"
+)
+
+func newLoggerAndBuffer(testName string) (*log.Logger, *bytes.Buffer) {
+	buf := &bytes.Buffer{}
+	return log.New(buf, testName+" ", 0), buf
+}
+
+func validateLogs(t *testing.T, logs string, expected []string) {
+	t.Helper()
+
+	if len(expected) == 0 && len(logs) != 0 {
+		t.Errorf("got logs when none were expected: %s", logs)
+	} else if strings.Count(logs, "\n") != len(expected) {
+		t.Errorf("unexpected log count actual=%d, expected=%d", strings.Count(logs, "\n"), len(expected))
+	}
+
+	for _, e := range expected {
+		if !strings.Contains(logs, e) {
+			t.Errorf("expected log message [%s] not present", e)
+		}
+	}
+}
+
+func TestGetEnvSleepTime(t *testing.T) {
+	// Summary from https://github.com/letsencrypt/pebble/pull/347#issuecomment-861634804:
+	//
+	// a. PEBBLE_VA_* missing, PEBBLE_SLEEPTIME missing, 5s delay on both
+	// b. PEBBLE_VA_* present, PEBBLE_SLEEPTIME missing, VA delay (possibly 0 if NOSLEEP) on both, emit a deprecated message on startup
+	// c. PEBBLE_VA_* missing, PEBBLE_SLEEPTIME present, specified delay on both
+	// d. PEBBLE_VA_* present, PEBBLE_SLEEPTIME present, use PEBBLE_SLEEPTIME, emit a warning message on startup that both are present and one is deprecated.
+	//
+	// Invalid or negative integers are treated as missing.
+	//
+	// This expands to:
+	// 1. PEBBLE_SLEEPTIME invalid, PEBBLE_VA_NOSLEEP clear, PEBBLE_VA_SLEEPTIME invalid - a
+	// 2. PEBBLE_SLEEPTIME   valid, PEBBLE_VA_NOSLEEP clear, PEBBLE_VA_SLEEPTIME invalid - c
+	// 3. PEBBLE_SLEEPTIME invalid, PEBBLE_VA_NOSLEEP clear, PEBBLE_VA_SLEEPTIME   valid - b (deprecated)
+	// 4. PEBBLE_SLEEPTIME   valid, PEBBLE_VA_NOSLEEP clear, PEBBLE_VA_SLEEPTIME   valid - d (deprecated, conflict)
+	// 5. PEBBLE_SLEEPTIME invalid, PEBBLE_VA_NOSLEEP   set, PEBBLE_VA_SLEEPTIME invalid - b (deprecated)
+	// 6. PEBBLE_SLEEPTIME   valid, PEBBLE_VA_NOSLEEP   set, PEBBLE_VA_SLEEPTIME invalid - d (deprecated, conflict)
+	// 7. PEBBLE_SLEEPTIME invalid, PEBBLE_VA_NOSLEEP   set, PEBBLE_VA_SLEEPTIME   valid - b (deprecated, conflict)
+	// 8. PEBBLE_SLEEPTIME   valid, PEBBLE_VA_NOSLEEP   set, PEBBLE_VA_SLEEPTIME   valid - d (deprecated, conflict)
+	t.Parallel()
+
+	const (
+		ignVaSleep     = "ignoring PEBBLE_VA_SLEEPTIME"
+		ignVaNoSleep   = "ignoring PEBBLE_VA_NOSLEEP"
+		ignVaBoth      = "ignoring PEBBLE_VA_NOSLEEP and PEBBLE_VA_SLEEPTIME"
+		depVaSleep     = "PEBBLE_VA_SLEEPTIME is deprecated"
+		depVaNoSleep   = "PEBBLE_VA_NOSLEEP is deprecated"
+		parseSleep     = "parse PEBBLE_SLEEPTIME"
+		parseVaSleep   = "parse PEBBLE_VA_SLEEPTIME"
+		parseVaNoSleep = "parse PEBBLE_VA_NOSLEEP"
+	)
+
+	tests := []struct {
+		name           string
+		envSleepTime   string
+		envVaNoSleep   string
+		envVaSleepTime string
+		expected       int
+		expectedLogs   []string
+	}{
+		// happy paths
+		{"defaults", "", "", "", defaultSleepTime, nil},                                            // 1
+		{"sleep", "3", "", "", 3, nil},                                                             // 2
+		{"vasleep", "", "", "3", 3, []string{depVaSleep}},                                          // 3
+		{"sleep+vasleep", "3", "", "6", 3, []string{depVaSleep, ignVaSleep}},                       // 4
+		{"nosleep", "", "1", "", 0, []string{depVaNoSleep}},                                        // 5
+		{"sleep+nosleep", "3", "1", "", 3, []string{depVaNoSleep, ignVaNoSleep}},                   // 6
+		{"nosleep+vasleep", "", "1", "3", 0, []string{depVaSleep, depVaNoSleep, ignVaSleep}},       // 7
+		{"sleep+vasleep+nosleep", "3", "1", "6", 3, []string{depVaSleep, depVaNoSleep, ignVaBoth}}, // 8
+
+		// parse failures
+		{"sleep-inv", "f", "", "", defaultSleepTime, []string{parseSleep}},
+		{"sleep-inv+vasleep+nosleep", "f", "1", "6", 0, []string{parseSleep, depVaSleep, depVaNoSleep, ignVaSleep}},
+		{"vasleep-inv", "", "", "f", defaultSleepTime, []string{depVaSleep, parseVaSleep}},
+		{"sleep+vasleep-inv+nosleep", "", "1", "f", 0, []string{depVaSleep, parseVaSleep, depVaNoSleep}},
+		{"nosleep-inv", "", "f", "", defaultSleepTime, []string{depVaNoSleep, parseVaNoSleep}},
+	}
+
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			logger, logBuffer := newLoggerAndBuffer(test.name)
+			if actual := getEnvSleepTime(logger, test.envSleepTime, test.envVaNoSleep, test.envVaSleepTime); actual != test.expected {
+				t.Errorf("envSleepTime=[%s], envVaNoSleep=[%s], envVaSleepTime=[%s], expected=%d, actual=%d",
+					test.envSleepTime,
+					test.envVaNoSleep,
+					test.envVaSleepTime,
+					test.expected,
+					actual,
+				)
+			}
+			validateLogs(t, logBuffer.String(), test.expectedLogs)
+			t.Logf("captured logs:\n%s", logBuffer.String())
+		})
+	}
+}