From 318c1f6c4abb8d569ad325593cdffe2ffb26898b Mon Sep 17 00:00:00 2001 From: squizzling Date: Tue, 15 Jun 2021 14:38:54 +1000 Subject: [PATCH] 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. --- README.md | 35 +++++++++----- ca/ca.go | 25 ++++++---- cmd/pebble/main.go | 99 +++++++++++++++++++++++++++++++++++++- cmd/pebble/main_test.go | 104 ++++++++++++++++++++++++++++++++++++++++ va/va.go | 59 +++++++---------------- va/va_test.go | 2 +- 6 files changed, 257 insertions(+), 67 deletions(-) diff --git a/README.md b/README.md index fbf369e7..2504ae68 100644 --- a/README.md +++ b/README.md @@ -129,7 +129,7 @@ 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 ``` @@ -137,9 +137,9 @@ services: 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 diff --git a/ca/ca.go b/ca/ca.go index f7fad6e1..dc202ae9 100644 --- a/ca/ca.go +++ b/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 diff --git a/cmd/pebble/main.go b/cmd/pebble/main.go index 01ab3e87..c9ec4576 100644 --- a/cmd/pebble/main.go +++ b/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 +} diff --git a/cmd/pebble/main_test.go b/cmd/pebble/main_test.go index 06ab7d0f..f4d1b704 100644 --- a/cmd/pebble/main_test.go +++ b/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()) + }) + } +} diff --git a/va/va.go b/va/va.go index 8cb8e746..f05766fa 100644 --- a/va/va.go +++ b/va/va.go @@ -24,6 +24,7 @@ import ( "github.com/miekg/dns" "github.com/letsencrypt/challtestsrv" + "github.com/letsencrypt/pebble/acme" "github.com/letsencrypt/pebble/core" ) @@ -42,24 +43,6 @@ const ( // How many concurrent validations are performed? concurrentValidations = 3 - // noSleepEnvVar defines the environment variable name used to signal that the - // VA should *not* sleep between validation attempts. Set this to 1 when you - // invoke Pebble if you wish validation to be done at full speed, e.g.: - // PEBBLE_VA_NOSLEEP=1 pebble - noSleepEnvVar = "PEBBLE_VA_NOSLEEP" - - // sleepTimeEnvVar defines the environment variable name used to set the time - // the VA should sleep between validation attempts (if not disabled). Set this - // e.g. to 5 when you invoke Pebble if you wish the delays to be between 0 - // and 5 seconds (instead between 0 and 15 seconds): - // PEBBLE_VA_SLEEPTIME=5 pebble - sleepTimeEnvVar = "PEBBLE_VA_SLEEPTIME" - - // defaultSleepTime defines the default sleep time (in seconds) between - // validation attempts. Can be disabled or modified by the environment - // variables PEBBLE_VA_NOSLEEP resp. PEBBLE_VA_SLEEPTIME (see above). - defaultSleepTime = 5 - // validationTimeout defines the timeout for validation attempts. validationTimeout = 15 * time.Second @@ -99,7 +82,6 @@ type VAImpl struct { httpPort int tlsPort int tasks chan *vaTask - sleep bool sleepTime int alwaysValid bool strict bool @@ -110,14 +92,15 @@ type VAImpl struct { func New( log *log.Logger, httpPort, tlsPort int, - strict bool, customResolverAddr string) *VAImpl { + strict bool, + customResolverAddr string, + sleepTime int) *VAImpl { va := &VAImpl{ log: log, httpPort: httpPort, tlsPort: tlsPort, tasks: make(chan *vaTask, taskQueueSize), - sleep: true, - sleepTime: defaultSleepTime, + sleepTime: sleepTime, strict: strict, customResolverAddr: customResolverAddr, } @@ -129,22 +112,6 @@ func New( va.log.Print("Using system DNS resolver for ACME challenges") } - // Read the PEBBLE_VA_NOSLEEP environment variable string - noSleep := os.Getenv(noSleepEnvVar) - // If it is set to something true-like, then the VA shouldn't sleep - switch noSleep { - case "1", "true", "True", "TRUE": - va.sleep = false - va.log.Printf("Disabling random VA sleeps") - } - - sleepTime := os.Getenv(sleepTimeEnvVar) - sleepTimeInt, err := strconv.Atoi(sleepTime) - if err == nil && va.sleep && sleepTimeInt >= 1 { - va.sleepTime = sleepTimeInt - va.log.Printf("Setting maximum random VA sleep time to %d seconds", va.sleepTime) - } - noValidate := os.Getenv(noValidateEnvVar) switch noValidate { case "1", "true", "True", "TRUE": @@ -251,6 +218,13 @@ func (va VAImpl) process(task *vaTask) { } err := va.firstError(results) + + if va.sleepTime > 0 { + sleepLen := time.Duration(rand.Intn(va.sleepTime)) + va.log.Printf("Sleeping for %s seconds before marking authz %s valid", time.Second*sleepLen, authz.ID) + time.Sleep(time.Second * sleepLen) + } + // If one of the results was an error, the challenge fails if err != nil { va.setAuthzInvalid(authz, chal, err) @@ -266,11 +240,10 @@ func (va VAImpl) process(task *vaTask) { } func (va VAImpl) performValidation(task *vaTask, results chan<- *core.ValidationRecord) { - if va.sleep { - // Sleep for a random amount of time between 0 and va.sleepTime seconds - len := time.Duration(rand.Intn(va.sleepTime)) - va.log.Printf("Sleeping for %s seconds before validating", time.Second*len) - time.Sleep(time.Second * len) + if va.sleepTime > 0 { + sleepLen := time.Duration(rand.Intn(va.sleepTime)) + va.log.Printf("Sleeping for %s seconds before attempting validation for authz %s", time.Second*sleepLen, task.Challenge.Authz.ID) + time.Sleep(time.Second * sleepLen) } // If `alwaysValid` is true then return a validation record immediately diff --git a/va/va_test.go b/va/va_test.go index cd5492cf..31f77d0f 100644 --- a/va/va_test.go +++ b/va/va_test.go @@ -31,7 +31,7 @@ func TestAuthzRace(t *testing.T) { // This whole test can be removed if/when the MemoryStore becomes 100% by value ms := db.NewMemoryStore() - va := New(log.New(os.Stdout, "Pebble/TestRace", log.LstdFlags), 14000, 15000, false, "") + va := New(log.New(os.Stdout, "Pebble/TestRace", log.LstdFlags), 14000, 15000, false, "", 0) authz := &core.Authorization{ ID: "auth-id",