Authz() holds the authz lock while taking the db lock, which can deadlock the whole store #563

Pebble can deadlock when a new-order request, an authorization request and a new-account request arrive at the same time. After that, every request that touches the database hangs, until Pebble is restarted. This still happens on main (1fcb30c), which already has the fixes from #553 and #555.

Two functions take the same two locks in opposite orders

• WebFrontEndImpl.Authz() takes authz.Lock(). While holding it, it looks up the account through getAcctByKey or validPOSTAsGET, which calls MemoryStore.GetAccountByKey and takes m.RLock().
• MemoryStore.FindValidAuthorization(), which every new order calls through makeAuthorizations, holds m.RLock() and calls authz.RLock() on every authorization in the store.

Both are read locks on the MemoryStore, so they only collide when a writer queues up in between. sync.RWMutex then blocks new readers, and the three goroutines wait on each other:

1. NewOrder holds m.RLock() and waits for authz.RLock().
2. Authz holds authz.Lock() and waits for m.RLock(), which is blocked behind the queued writer.
3. NewAccount waits for m.Lock(), which is blocked by the reader in (1).

From then on, every m.Lock() and every new m.RLock() queues behind them. GET /dir and HEAD /nonce-plz still work, because they do not touch the store, so a health check on /dir stays green.

Authz() also takes authz.Order.RLock() while holding authz.Lock(). This is the reverse of Order.GetStatus(), which read-locks the order and then each of its authorizations. That inversion needs a writer queued on the order, for example GetOrderByID's order.Lock().

How we found it

cert-manager's end-to-end tests run dozens of ACME clients in parallel against a single Pebble. In a failing run, Pebble answered requests normally for about 3 seconds. Then it stopped creating accounts and orders, while the log kept showing new calling handler() lines:

POST /sign-me-up -> calling handler()
POST /order-plz -> calling handler()
POST /authZ/ -> calling handler()
POST /sign-me-up -> calling handler()     <- no further account, order or certificate is ever created

Nothing reached /my-order/ or /finalize-order/ before the hang, so it is not the #554 path.

Reproducer

The stress client below runs 40 goroutines. Each one registers an account, creates orders and fetches the order's authorizations. Pebble runs with PEBBLE_VA_ALWAYS_VALID=1 PEBBLE_WFE_NONCEREJECT=0 and test/config/pebble-config.json.

goroutine 24 [sync.RWMutex.RLock]:        // holds the MemoryStore read lock, waits for an authz read lock
    db.(*MemoryStore).FindValidAuthorization(...)   db/memorystore.go:321
    wfe.(*WebFrontEndImpl).makeAuthorizations(...)  wfe/wfe.go:1563
    wfe.(*WebFrontEndImpl).NewOrder(...)            wfe/wfe.go:1824

goroutine 18 [sync.RWMutex.RLock]:        // holds the authz write lock, waits for the MemoryStore read lock
    db.(*MemoryStore).GetAccountByKey(...)          db/memorystore.go:96
    wfe.(*WebFrontEndImpl).getAcctByKey(...)        wfe/wfe.go:2503
    wfe.(*WebFrontEndImpl).validPOSTAsGET(...)      wfe/wfe.go:841
    wfe.(*WebFrontEndImpl).Authz(...)               wfe/wfe.go:2409

goroutine 136 [sync.Mutex.Lock]:          // queued MemoryStore writer
    sync.(*RWMutex).Lock(...)
    db.(*MemoryStore).AddAccount(...)               db/memorystore.go:142
    wfe.(*WebFrontEndImpl).NewAccount(...)          wfe/wfe.go:1410

package main

import (
	"context"
	"crypto/ecdsa"
	"crypto/elliptic"
	"crypto/rand"
	"crypto/tls"
	"fmt"
	"net/http"
	"os"
	"sync/atomic"
	"time"

	"golang.org/x/crypto/acme"
)

var progress atomic.Int64

func worker(id int) {
	hc := &http.Client{Timeout: 5 * time.Second, Transport: &http.Transport{TLSClientConfig: &tls.Config{InsecureSkipVerify: true}}}
	for {
		key, _ := ecdsa.GenerateKey(elliptic.P256(), rand.Reader)
		c := &acme.Client{Key: key, DirectoryURL: "https://localhost:14000/dir", HTTPClient: hc}
		ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
		if _, err := c.Register(ctx, &acme.Account{}, acme.AcceptTOS); err != nil {
			cancel()
			continue
		}
		progress.Add(1)
		for i := 0; i < 5; i++ {
			o, err := c.AuthorizeOrder(ctx, acme.DomainIDs(fmt.Sprintf("w%d.example.com", id%4)))
			if err != nil {
				break
			}
			progress.Add(1)
			for _, u := range o.AuthzURLs {
				if _, err := c.GetAuthorization(ctx, u); err == nil {
					progress.Add(1)
				}
			}
		}
		cancel()
	}
}

func main() {
	for i := 0; i < 40; i++ {
		go worker(i)
	}
	start := time.Now()
	last, stall := int64(0), 0
	for range time.Tick(time.Second) {
		p := progress.Load()
		if p == last {
			stall++
		} else {
			stall = 0
		}
		last = p
		if stall >= 10 {
			fmt.Printf("HANG after %s, progress=%d\n", time.Since(start).Round(time.Second), p)
			os.Exit(2)
		}
		if time.Since(start) > 10*time.Minute {
			fmt.Printf("NO HANG in %s, progress=%d\n", time.Since(start).Round(time.Second), p)
			os.Exit(0)
		}
	}
}

PEBBLE_VA_ALWAYS_VALID=1 PEBBLE_WFE_NONCEREJECT=0 GOTRACEBACK=all \
  ./pebble -config test/config/pebble-config.json > pebble.log 2>&1 &
sleep 2
./stress || kill -QUIT %1   # on a hang, SIGQUIT writes the goroutine dump to pebble.log

Related

• wfe.go Order() takes the order read lock recursively, which can wedge the whole DB #554 and Fix deadlock from recursive RLock in Order() #555 fixed a different deadlock with the same end state: the whole store wedges once a writer queues.
• The authz.RLock() in FindValidAuthorization was proposed in db: missing authz rlock in FindValidAuthorization #270, which was closed in favour of reworking the store. The same lock was later added in Fix current CI builds #350. The lock in Authz() came from fix dataraces, add -race install, add load-gen. #232.

Claude helped find the cause and write the reproducer and the fix.