a/certmagic
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Make logger values required

Browse Source 
Eliminates a bajillion nil checks and footguns
(except in tests, which bypass exported APIs, but that is expected)

Most recent #207

Logging can still be disabled via zap.NewNop(), if necessary.
(But disabling logging in CertMagic is a really bad idea.)
This commit is contained in:
Matthew Holt 2022-09-26 10:19:28 -06:00
parent 93fd493922
commit 5deb7c2fb0
18 changed files with 374 additions and 485 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

7
account_test.go
View File

@ -31,6 +31,7 @@ func TestNewAccount(t *testing.T) {
testConfig := &Config{
Issuers: []Issuer{am},
Storage: &FileStorage{Path: "./_testdata_tmp"},
Logger: defaultTestLogger,
certCache: new(Cache),
}
am.config = testConfig
@ -58,6 +59,7 @@ func TestSaveAccount(t *testing.T) {
testConfig := &Config{
Issuers: []Issuer{am},
Storage: &FileStorage{Path: "./_testdata1_tmp"},
Logger: defaultTestLogger,
certCache: new(Cache),
}
am.config = testConfig
@ -93,6 +95,7 @@ func TestGetAccountDoesNotAlreadyExist(t *testing.T) {
testConfig := &Config{
Issuers: []Issuer{am},
Storage: &FileStorage{Path: "./_testdata_tmp"},
Logger: defaultTestLogger,
certCache: new(Cache),
}
am.config = testConfig
@ -114,6 +117,7 @@ func TestGetAccountAlreadyExists(t *testing.T) {
testConfig := &Config{
Issuers: []Issuer{am},
Storage: &FileStorage{Path: "./_testdata2_tmp"},
Logger: defaultTestLogger,
certCache: new(Cache),
}
am.config = testConfig
@ -168,6 +172,7 @@ func TestGetEmailFromPackageDefault(t *testing.T) {
testConfig := &Config{
Issuers: []Issuer{am},
Storage: &FileStorage{Path: "./_testdata2_tmp"},
Logger: defaultTestLogger,
certCache: new(Cache),
}
am.config = testConfig
@ -189,6 +194,7 @@ func TestGetEmailFromUserInput(t *testing.T) {
testConfig := &Config{
Issuers: []Issuer{am},
Storage: &FileStorage{Path: "./_testdata3_tmp"},
Logger: defaultTestLogger,
certCache: new(Cache),
}
am.config = testConfig
@ -223,6 +229,7 @@ func TestGetEmailFromRecent(t *testing.T) {
testConfig := &Config{
Issuers: []Issuer{am},
Storage: &FileStorage{Path: "./_testdata4_tmp"},
Logger: defaultTestLogger,
certCache: new(Cache),
}
am.config = testConfig

28
acmeclient.go
View File

@ -175,9 +175,7 @@ func (iss *ACMEIssuer) newACMEClient(useTestCA bool) (*acmez.Client, error) {
},
ChallengeSolvers: make(map[string]acmez.Solver),
}
if iss.Logger != nil {
client.Logger = iss.Logger.Named("acme_client")
}
client.Logger = iss.Logger.Named("acme_client")
// configure challenges (most of the time, DNS challenge is
// exclusive of other ones because it is usually only used
@ -260,24 +258,20 @@ func (c *acmeClient) throttle(ctx context.Context, names []string) error {
// TODO: stop rate limiter when it is garbage-collected...
}
rateLimitersMu.Unlock()
if c.iss.Logger != nil {
c.iss.Logger.Info("waiting on internal rate limiter",
zap.Strings("identifiers", names),
zap.String("ca", c.acmeClient.Directory),
zap.String("account", email),
)
}
c.iss.Logger.Info("waiting on internal rate limiter",
zap.Strings("identifiers", names),
zap.String("ca", c.acmeClient.Directory),
zap.String("account", email),
)
err := rl.Wait(ctx)
if err != nil {
return err
}
if c.iss.Logger != nil {
c.iss.Logger.Info("done waiting on internal rate limiter",
zap.Strings("identifiers", names),
zap.String("ca", c.acmeClient.Directory),
zap.String("account", email),
)
}
c.iss.Logger.Info("done waiting on internal rate limiter",
zap.Strings("identifiers", names),
zap.String("ca", c.acmeClient.Directory),
zap.String("account", email),
)
return nil
}

40
acmeissuer.go
View File

@ -110,7 +110,9 @@ type ACMEIssuer struct {
// certificate chains
PreferredChains ChainPreference
// Set a logger to enable logging
// Set a logger to configure logging; a default
// logger must always be set; if no logging is
// desired, set this to zap.NewNop().
Logger *zap.Logger
config *Config
@ -197,6 +199,11 @@ func NewACMEIssuer(cfg *Config, template ACMEIssuer) *ACMEIssuer {
template.Logger = DefaultACME.Logger
}
// absolutely do not allow a nil logger; that would panic
if template.Logger == nil {
template.Logger = defaultLogger
}
template.config = cfg
template.mu = new(sync.Mutex)
@ -398,7 +405,7 @@ func (am *ACMEIssuer) doIssue(ctx context.Context, csr *x509.CertificateRequest,
// processing. If there are no matches, the first chain is returned.
func (am *ACMEIssuer) selectPreferredChain(certChains []acme.Certificate) acme.Certificate {
if len(certChains) == 1 {
if am.Logger != nil && (len(am.PreferredChains.AnyCommonName) > 0 || len(am.PreferredChains.RootCommonName) > 0) {
if len(am.PreferredChains.AnyCommonName) > 0 || len(am.PreferredChains.RootCommonName) > 0 {
am.Logger.Debug("there is only one chain offered; selecting it regardless of preferences",
zap.String("chain_url", certChains[0].URL))
}
@ -423,11 +430,9 @@ func (am *ACMEIssuer) selectPreferredChain(certChains []acme.Certificate) acme.C
for i, chain := range certChains {
certs, err := parseCertsFromPEMBundle(chain.ChainPEM)
if err != nil {
if am.Logger != nil {
am.Logger.Error("unable to parse PEM certificate chain",
zap.Int("chain", i),
zap.Error(err))
}
am.Logger.Error("unable to parse PEM certificate chain",
zap.Int("chain", i),
zap.Error(err))
continue
}
decodedChains[i] = certs
@ -438,11 +443,9 @@ func (am *ACMEIssuer) selectPreferredChain(certChains []acme.Certificate) acme.C
for i, chain := range decodedChains {
for _, cert := range chain {
if cert.Issuer.CommonName == prefAnyCN {
if am.Logger != nil {
am.Logger.Debug("found preferred certificate chain by issuer common name",
zap.String("preference", prefAnyCN),
zap.Int("chain", i))
}
am.Logger.Debug("found preferred certificate chain by issuer common name",
zap.String("preference", prefAnyCN),
zap.Int("chain", i))
return certChains[i]
}
}
@ -454,20 +457,16 @@ func (am *ACMEIssuer) selectPreferredChain(certChains []acme.Certificate) acme.C
for _, prefRootCN := range am.PreferredChains.RootCommonName {
for i, chain := range decodedChains {
if chain[len(chain)-1].Issuer.CommonName == prefRootCN {
if am.Logger != nil {
am.Logger.Debug("found preferred certificate chain by root common name",
zap.String("preference", prefRootCN),
zap.Int("chain", i))
}
am.Logger.Debug("found preferred certificate chain by root common name",
zap.String("preference", prefRootCN),
zap.Int("chain", i))
return certChains[i]
}
}
}
}
if am.Logger != nil {
am.Logger.Warn("did not find chain matching preferences; using first")
}
am.Logger.Warn("did not find chain matching preferences; using first")
}
return certChains[0]
@ -509,6 +508,7 @@ type ChainPreference struct {
var DefaultACME = ACMEIssuer{
CA: LetsEncryptProductionCA,
TestCA: LetsEncryptStagingCA,
Logger: defaultLogger,
}
// Some well-known CA endpoints available to use.

31
async.go
View File

@ -71,9 +71,7 @@ func (jm *jobManager) worker() {
jm.queue = jm.queue[1:]
jm.mu.Unlock()
if err := next.job(); err != nil {
if next.logger != nil {
next.logger.Error("job failed", zap.Error(err))
}
next.logger.Error("job failed", zap.Error(err))
}
if next.name != "" {
jm.mu.Lock()
@ -116,22 +114,19 @@ func doWithRetry(ctx context.Context, log *zap.Logger, f func(context.Context) e
intervalIndex++
}
if time.Since(start) < maxRetryDuration {
if log != nil {
log.Error("will retry",
zap.Error(err),
zap.Int("attempt", attempts),
zap.Duration("retrying_in", retryIntervals[intervalIndex]),
zap.Duration("elapsed", time.Since(start)),
zap.Duration("max_duration", maxRetryDuration))
}
log.Error("will retry",
zap.Error(err),
zap.Int("attempt", attempts),
zap.Duration("retrying_in", retryIntervals[intervalIndex]),
zap.Duration("elapsed", time.Since(start)),
zap.Duration("max_duration", maxRetryDuration))
} else {
if log != nil {
log.Error("final attempt; giving up",
zap.Error(err),
zap.Int("attempt", attempts),
zap.Duration("elapsed", time.Since(start)),
zap.Duration("max_duration", maxRetryDuration))
}
log.Error("final attempt; giving up",
zap.Error(err),
zap.Int("attempt", attempts),
zap.Duration("elapsed", time.Since(start)),
zap.Duration("max_duration", maxRetryDuration))
return nil
}
}

75
cache.go
View File

@ -118,6 +118,11 @@ func NewCache(opts CacheOptions) *Cache {
logger: opts.Logger,
}
// absolutely do not allow a nil logger; panics galore
if c.logger == nil {
c.logger = defaultLogger
}
go c.maintainAssets(0)
return c
@ -194,14 +199,12 @@ func (certCache *Cache) cacheCertificate(cert Certificate) {
func (certCache *Cache) unsyncedCacheCertificate(cert Certificate) {
// no-op if this certificate already exists in the cache
if _, ok := certCache.cache[cert.hash]; ok {
if certCache.logger != nil {
certCache.logger.Debug("certificate already cached",
zap.Strings("subjects", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.Bool("managed", cert.managed),
zap.String("issuer_key", cert.issuerKey),
zap.String("hash", cert.hash))
}
certCache.logger.Debug("certificate already cached",
zap.Strings("subjects", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.Bool("managed", cert.managed),
zap.String("issuer_key", cert.issuerKey),
zap.String("hash", cert.hash))
return
}
@ -217,13 +220,11 @@ func (certCache *Cache) unsyncedCacheCertificate(cert Certificate) {
i := 0
for _, randomCert := range certCache.cache {
if i == rnd {
if certCache.logger != nil {
certCache.logger.Debug("cache full; evicting random certificate",
zap.Strings("removing_subjects", randomCert.Names),
zap.String("removing_hash", randomCert.hash),
zap.Strings("inserting_subjects", cert.Names),
zap.String("inserting_hash", cert.hash))
}
certCache.logger.Debug("cache full; evicting random certificate",
zap.Strings("removing_subjects", randomCert.Names),
zap.String("removing_hash", randomCert.hash),
zap.Strings("inserting_subjects", cert.Names),
zap.String("inserting_hash", cert.hash))
certCache.removeCertificate(randomCert)
break
}
@ -239,16 +240,14 @@ func (certCache *Cache) unsyncedCacheCertificate(cert Certificate) {
certCache.cacheIndex[name] = append(certCache.cacheIndex[name], cert.hash)
}
if certCache.logger != nil {
certCache.logger.Debug("added certificate to cache",
zap.Strings("subjects", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.Bool("managed", cert.managed),
zap.String("issuer_key", cert.issuerKey),
zap.String("hash", cert.hash),
zap.Int("cache_size", len(certCache.cache)),
zap.Int("cache_capacity", certCache.options.Capacity))
}
certCache.logger.Debug("added certificate to cache",
zap.Strings("subjects", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.Bool("managed", cert.managed),
zap.String("issuer_key", cert.issuerKey),
zap.String("hash", cert.hash),
zap.Int("cache_size", len(certCache.cache)),
zap.Int("cache_capacity", certCache.options.Capacity))
}
// removeCertificate removes cert from the cache.
@ -275,16 +274,14 @@ func (certCache *Cache) removeCertificate(cert Certificate) {
// delete the actual cert from the cache
delete(certCache.cache, cert.hash)
if certCache.logger != nil {
certCache.logger.Debug("removed certificate from cache",
zap.Strings("subjects", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.Bool("managed", cert.managed),
zap.String("issuer_key", cert.issuerKey),
zap.String("hash", cert.hash),
zap.Int("cache_size", len(certCache.cache)),
zap.Int("cache_capacity", certCache.options.Capacity))
}
certCache.logger.Debug("removed certificate from cache",
zap.Strings("subjects", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.Bool("managed", cert.managed),
zap.String("issuer_key", cert.issuerKey),
zap.String("hash", cert.hash),
zap.Int("cache_size", len(certCache.cache)),
zap.Int("cache_capacity", certCache.options.Capacity))
}
// replaceCertificate atomically replaces oldCert with newCert in
@ -296,11 +293,9 @@ func (certCache *Cache) replaceCertificate(oldCert, newCert Certificate) {
certCache.removeCertificate(oldCert)
certCache.unsyncedCacheCertificate(newCert)
certCache.mu.Unlock()
if certCache.logger != nil {
certCache.logger.Info("replaced certificate in cache",
zap.Strings("subjects", newCert.Names),
zap.Time("new_expiration", expiresAt(newCert.Leaf)))
}
certCache.logger.Info("replaced certificate in cache",
zap.Strings("subjects", newCert.Names),
zap.Time("new_expiration", expiresAt(newCert.Leaf)))
}
func (certCache *Cache) getAllMatchingCerts(name string) []Certificate {

8
certificates.go
View File

@ -177,7 +177,7 @@ func (cfg *Config) CacheUnmanagedTLSCertificate(ctx context.Context, tlsCert tls
return err
}
err = stapleOCSP(ctx, cfg.OCSP, cfg.Storage, &cert, nil)
if err != nil && cfg.Logger != nil {
if err != nil {
cfg.Logger.Warn("stapling OCSP", zap.Error(err))
}
cfg.emit(ctx, "cached_unmanaged_cert", map[string]any{"sans": cert.Names})
@ -225,7 +225,7 @@ func (cfg Config) makeCertificateWithOCSP(ctx context.Context, certPEMBlock, key
return cert, err
}
err = stapleOCSP(ctx, cfg.OCSP, cfg.Storage, &cert, certPEMBlock)
if err != nil && cfg.Logger != nil {
if err != nil {
cfg.Logger.Warn("stapling OCSP", zap.Error(err), zap.Strings("identifiers", cert.Names))
}
return cert, nil
@ -333,9 +333,7 @@ func (cfg *Config) managedCertInStorageExpiresSoon(ctx context.Context, cert Cer
// to the new cert. It assumes that the new certificate for oldCert.Names[0] is
// already in storage. It returns the newly-loaded certificate if successful.
func (cfg *Config) reloadManagedCertificate(ctx context.Context, oldCert Certificate) (Certificate, error) {
if cfg.Logger != nil {
cfg.Logger.Info("reloading managed certificate", zap.Strings("identifiers", oldCert.Names))
}
cfg.Logger.Info("reloading managed certificate", zap.Strings("identifiers", oldCert.Names))
newCert, err := cfg.loadManagedCertificate(ctx, oldCert.Names[0])
if err != nil {
return Certificate{}, fmt.Errorf("loading managed certificate for %v from storage: %v", oldCert.Names, err)

6
certificates_test.go
View File

@ -23,8 +23,8 @@ import (
)
func TestUnexportedGetCertificate(t *testing.T) {
certCache := &Cache{cache: make(map[string]Certificate), cacheIndex: make(map[string][]string)}
cfg := &Config{certCache: certCache}
certCache := &Cache{cache: make(map[string]Certificate), cacheIndex: make(map[string][]string), logger: defaultTestLogger}
cfg := &Config{Logger: defaultTestLogger, certCache: certCache}
// When cache is empty
if _, matched, defaulted := cfg.getCertificateFromCache(&tls.ClientHelloInfo{ServerName: "example.com"}); matched || defaulted {
@ -53,7 +53,7 @@ func TestUnexportedGetCertificate(t *testing.T) {
}
func TestCacheCertificate(t *testing.T) {
certCache := &Cache{cache: make(map[string]Certificate), cacheIndex: make(map[string][]string)}
certCache := &Cache{cache: make(map[string]Certificate), cacheIndex: make(map[string][]string), logger: defaultTestLogger}
certCache.cacheCertificate(Certificate{Names: []string{"example.com", "sub.example.com"}, hash: "foobar", Certificate: tls.Certificate{Leaf: &x509.Certificate{NotAfter: time.Now()}}})
if len(certCache.cache) != 1 {

12
certmagic.go
View File

@ -43,10 +43,14 @@ import (
"log"
"net"
"net/http"
"os"
"sort"
"strings"
"sync"
"time"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)
// HTTPS serves mux for all domainNames using the HTTP
@ -468,8 +472,16 @@ var Default = Config{
RenewalWindowRatio: DefaultRenewalWindowRatio,
Storage: defaultFileStorage,
KeySource: DefaultKeyGenerator,
Logger: defaultLogger,
}
// defaultLogger is guaranteed to be a non-nil fallback logger.
var defaultLogger = zap.New(zapcore.NewCore(
zapcore.NewConsoleEncoder(zap.NewProductionEncoderConfig()),
os.Stderr,
zap.InfoLevel,
))
const (
// HTTPChallengePort is the officially-designated port for
// the HTTP challenge according to the ACME spec.

13
certmagic_test.go
View File

@ -14,4 +14,17 @@
package certmagic
import (
"os"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)
// TODO
var defaultTestLogger = zap.New(zapcore.NewCore(
zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()),
os.Stderr,
zap.DebugLevel,
))

158
config.go
View File

@ -119,7 +119,8 @@ type Config struct {
// TLS assets. Default is the local file system.
Storage Storage
// Set a logger to enable logging.
// Set a logger to enable logging. If not set,
// a default logger will be created.
Logger *zap.Logger
// required pointer to the in-memory cert cache
@ -205,6 +206,16 @@ func newWithCache(certCache *Cache, cfg Config) *Config {
if cfg.OnDemand == nil {
cfg.OnDemand = Default.OnDemand
}
if !cfg.MustStaple {
cfg.MustStaple = Default.MustStaple
}
if len(cfg.Issuers) == 0 {
cfg.Issuers = Default.Issuers
if len(cfg.Issuers) == 0 {
// at least one issuer is absolutely required
cfg.Issuers = []Issuer{NewACMEIssuer(&cfg, DefaultACME)}
}
}
if cfg.RenewalWindowRatio == 0 {
cfg.RenewalWindowRatio = Default.RenewalWindowRatio
}
@ -217,18 +228,11 @@ func newWithCache(certCache *Cache, cfg Config) *Config {
if cfg.DefaultServerName == "" {
cfg.DefaultServerName = Default.DefaultServerName
}
if !cfg.MustStaple {
cfg.MustStaple = Default.MustStaple
}
if cfg.Storage == nil {
cfg.Storage = Default.Storage
}
if len(cfg.Issuers) == 0 {
cfg.Issuers = Default.Issuers
if len(cfg.Issuers) == 0 {
// at least one issuer is absolutely required
cfg.Issuers = []Issuer{NewACMEIssuer(&cfg, DefaultACME)}
}
if cfg.Logger == nil {
cfg.Logger = Default.Logger
}
// absolutely don't allow a nil storage,
@ -238,6 +242,12 @@ func newWithCache(certCache *Cache, cfg Config) *Config {
cfg.Storage = defaultFileStorage
}
// absolutely don't allow a nil logger either,
// because that would result in panics
if cfg.Logger == nil {
cfg.Logger = defaultLogger
}
cfg.certCache = certCache
return &cfg
@ -469,11 +479,9 @@ func (cfg *Config) obtainCert(ctx context.Context, name string, interactive bool
return fmt.Errorf("failed storage check: %v - storage is probably misconfigured", err)
}
log := loggerNamed(cfg.Logger, "obtain")
log := cfg.Logger.Named("obtain")
if log != nil {
log.Info("acquiring lock", zap.String("identifier", name))
}
log.Info("acquiring lock", zap.String("identifier", name))
// ensure idempotency of the obtain operation for this name
lockKey := cfg.lockKey(certIssueLockOp, name)
@ -482,34 +490,24 @@ func (cfg *Config) obtainCert(ctx context.Context, name string, interactive bool
return fmt.Errorf("unable to acquire lock '%s': %v", lockKey, err)
}
defer func() {
if log != nil {
log.Info("releasing lock", zap.String("identifier", name))
}
log.Info("releasing lock", zap.String("identifier", name))
if err := releaseLock(ctx, cfg.Storage, lockKey); err != nil {
if log != nil {
log.Error("unable to unlock",
zap.String("identifier", name),
zap.String("lock_key", lockKey),
zap.Error(err))
}
log.Error("unable to unlock",
zap.String("identifier", name),
zap.String("lock_key", lockKey),
zap.Error(err))
}
}()
if log != nil {
log.Info("lock acquired", zap.String("identifier", name))
}
log.Info("lock acquired", zap.String("identifier", name))
f := func(ctx context.Context) error {
// check if obtain is still needed -- might have been obtained during lock
if cfg.storageHasCertResourcesAnyIssuer(ctx, name) {
if log != nil {
log.Info("certificate already exists in storage", zap.String("identifier", name))
}
log.Info("certificate already exists in storage", zap.String("identifier", name))
return nil
}
if log != nil {
log.Info("obtaining certificate", zap.String("identifier", name))
}
log.Info("obtaining certificate", zap.String("identifier", name))
if err := cfg.emit(ctx, "cert_obtaining", map[string]any{"identifier": name}); err != nil {
return fmt.Errorf("obtaining certificate aborted by event handler: %w", err)
@ -543,10 +541,8 @@ func (cfg *Config) obtainCert(ctx context.Context, name string, interactive bool
for i, issuer := range issuers {
issuerKeys = append(issuerKeys, issuer.IssuerKey())
if log != nil {
log.Debug(fmt.Sprintf("trying issuer %d/%d", i+1, len(cfg.Issuers)),
zap.String("issuer", issuer.IssuerKey()))
}
log.Debug(fmt.Sprintf("trying issuer %d/%d", i+1, len(cfg.Issuers)),
zap.String("issuer", issuer.IssuerKey()))
if prechecker, ok := issuer.(PreChecker); ok {
err = prechecker.PreCheck(ctx, []string{name}, interactive)
@ -568,12 +564,10 @@ func (cfg *Config) obtainCert(ctx context.Context, name string, interactive bool
if errors.As(err, &problem) {
errToLog = problem
}
if log != nil {
log.Error("could not get certificate from issuer",
zap.String("identifier", name),
zap.String("issuer", issuer.IssuerKey()),
zap.Error(errToLog))
}
log.Error("could not get certificate from issuer",
zap.String("identifier", name),
zap.String("issuer", issuer.IssuerKey()),
zap.Error(errToLog))
}
if err != nil {
cfg.emit(ctx, "cert_failed", map[string]any{
@ -599,9 +593,7 @@ func (cfg *Config) obtainCert(ctx context.Context, name string, interactive bool
return fmt.Errorf("[%s] Obtain: saving assets: %v", name, err)
}
if log != nil {
log.Info("certificate obtained successfully", zap.String("identifier", name))
}
log.Info("certificate obtained successfully", zap.String("identifier", name))
cfg.emit(ctx, "cert_obtained", map[string]any{
"renewal": false,
@ -702,11 +694,9 @@ func (cfg *Config) renewCert(ctx context.Context, name string, force, interactiv
return fmt.Errorf("failed storage check: %v - storage is probably misconfigured", err)
}
log := loggerNamed(cfg.Logger, "renew")
log := cfg.Logger.Named("renew")
if log != nil {
log.Info("acquiring lock", zap.String("identifier", name))
}
log.Info("acquiring lock", zap.String("identifier", name))
// ensure idempotency of the renew operation for this name
lockKey := cfg.lockKey(certIssueLockOp, name)
@ -715,21 +705,16 @@ func (cfg *Config) renewCert(ctx context.Context, name string, force, interactiv
return fmt.Errorf("unable to acquire lock '%s': %v", lockKey, err)
}
defer func() {
if log != nil {
log.Info("releasing lock", zap.String("identifier", name))
}
log.Info("releasing lock", zap.String("identifier", name))
if err := releaseLock(ctx, cfg.Storage, lockKey); err != nil {
if log != nil {
log.Error("unable to unlock",
zap.String("identifier", name),
zap.String("lock_key", lockKey),
zap.Error(err))
}
log.Error("unable to unlock",
zap.String("identifier", name),
zap.String("lock_key", lockKey),
zap.Error(err))
}
}()
if log != nil {
log.Info("lock acquired", zap.String("identifier", name))
}
log.Info("lock acquired", zap.String("identifier", name))
f := func(ctx context.Context) error {
// prepare for renewal (load PEM cert, key, and meta)
@ -742,26 +727,20 @@ func (cfg *Config) renewCert(ctx context.Context, name string, force, interactiv
timeLeft, needsRenew := cfg.managedCertNeedsRenewal(certRes)
if !needsRenew {
if force {
if log != nil {
log.Info("certificate does not need to be renewed, but renewal is being forced",
zap.String("identifier", name),
zap.Duration("remaining", timeLeft))
}
log.Info("certificate does not need to be renewed, but renewal is being forced",
zap.String("identifier", name),
zap.Duration("remaining", timeLeft))
} else {
if log != nil {
log.Info("certificate appears to have been renewed already",
zap.String("identifier", name),
zap.Duration("remaining", timeLeft))
}
log.Info("certificate appears to have been renewed already",
zap.String("identifier", name),
zap.Duration("remaining", timeLeft))
return nil
}
}
if log != nil {
log.Info("renewing certificate",
zap.String("identifier", name),
zap.Duration("remaining", timeLeft))
}
log.Info("renewing certificate",
zap.String("identifier", name),
zap.Duration("remaining", timeLeft))
if err := cfg.emit(ctx, "cert_obtaining", map[string]any{
"renewal": true,
@ -808,12 +787,10 @@ func (cfg *Config) renewCert(ctx context.Context, name string, force, interactiv
if errors.As(err, &problem) {
errToLog = problem
}
if log != nil {
log.Error("could not get certificate from issuer",
zap.String("identifier", name),
zap.String("issuer", issuer.IssuerKey()),
zap.Error(errToLog))
}
log.Error("could not get certificate from issuer",
zap.String("identifier", name),
zap.String("issuer", issuer.IssuerKey()),
zap.Error(errToLog))
}
if err != nil {
cfg.emit(ctx, "cert_failed", map[string]any{
@ -841,9 +818,7 @@ func (cfg *Config) renewCert(ctx context.Context, name string, force, interactiv
return fmt.Errorf("[%s] Renew: saving assets: %v", name, err)
}
if log != nil {
log.Info("certificate renewed successfully", zap.String("identifier", name))
}
log.Info("certificate renewed successfully", zap.String("identifier", name))
cfg.emit(ctx, "cert_obtained", map[string]any{
"renewal": true,
@ -1038,10 +1013,8 @@ func (cfg *Config) checkStorage(ctx context.Context) error {
defer func() {
deleteErr := cfg.Storage.Delete(ctx, key)
if deleteErr != nil {
if cfg.Logger != nil {
cfg.Logger.Error("deleting test key from storage",
zap.String("key", key), zap.Error(err))
}
cfg.Logger.Error("deleting test key from storage",
zap.String("key", key), zap.Error(err))
}
// if there was no other error, make sure
// to return any error returned from Delete
@ -1121,13 +1094,6 @@ func (cfg *Config) emit(ctx context.Context, eventName string, data map[string]a
return cfg.OnEvent(ctx, eventName, data)
}
func loggerNamed(l *zap.Logger, name string) *zap.Logger {
if l == nil {
return nil
}
return l.Named(name)
}
// CertificateSelector is a type which can select a certificate to use given multiple choices.
type CertificateSelector interface {
SelectCertificate(*tls.ClientHelloInfo, []Certificate) (Certificate, error)

1
config_test.go
View File

@ -30,6 +30,7 @@ func TestSaveCertResource(t *testing.T) {
testConfig := &Config{
Issuers: []Issuer{am},
Storage: &FileStorage{Path: "./_testdata_tmp"},
Logger: defaultTestLogger,
certCache: new(Cache),
}
am.config = testConfig

14
crypto.go
View File

@ -226,14 +226,12 @@ func (cfg *Config) loadCertResourceAnyIssuer(ctx context.Context, certNamesKey s
return certResources[j].decoded.NotBefore.Before(certResources[i].decoded.NotBefore)
})
if cfg.Logger != nil {
cfg.Logger.Debug("loading managed certificate",
zap.String("domain", certNamesKey),
zap.Time("expiration", expiresAt(certResources[0].decoded)),
zap.String("issuer_key", certResources[0].issuer.IssuerKey()),
zap.Any("storage", cfg.Storage),
)
}
cfg.Logger.Debug("loading managed certificate",
zap.String("domain", certNamesKey),
zap.Time("expiration", expiresAt(certResources[0].decoded)),
zap.String("issuer_key", certResources[0].issuer.IssuerKey()),
zap.Any("storage", cfg.Storage),
)
return certResources[0].CertificateResource, nil
}

274
handshake.go
View File

@ -46,12 +46,10 @@ func (cfg *Config) GetCertificate(clientHello *tls.ClientHelloInfo) (*tls.Certif
ctx := context.TODO() // TODO: get a proper context? from somewhere...
if err := cfg.emit(ctx, "tls_get_certificate", map[string]any{"client_hello": clientHello}); err != nil {
if cfg.Logger != nil {
cfg.Logger.Error("TLS handshake aborted by event handler",
zap.String("server_name", clientHello.ServerName),
zap.String("remote", clientHello.Conn.RemoteAddr().String()),
zap.Error(err))
}
cfg.Logger.Error("TLS handshake aborted by event handler",
zap.String("server_name", clientHello.ServerName),
zap.String("remote", clientHello.Conn.RemoteAddr().String()),
zap.Error(err))
return nil, fmt.Errorf("handshake aborted by event handler: %w", err)
}
@ -61,20 +59,16 @@ func (cfg *Config) GetCertificate(clientHello *tls.ClientHelloInfo) (*tls.Certif
if proto == acmez.ACMETLS1Protocol {
challengeCert, distributed, err := cfg.getTLSALPNChallengeCert(clientHello)
if err != nil {
if cfg.Logger != nil {
cfg.Logger.Error("tls-alpn challenge",
zap.String("server_name", clientHello.ServerName),
zap.Error(err))
}
cfg.Logger.Error("tls-alpn challenge",
zap.String("server_name", clientHello.ServerName),
zap.Error(err))
return nil, err
}
if cfg.Logger != nil {
cfg.Logger.Info("served key authentication certificate",
zap.String("server_name", clientHello.ServerName),
zap.String("challenge", "tls-alpn-01"),
zap.String("remote", clientHello.Conn.RemoteAddr().String()),
zap.Bool("distributed", distributed))
}
cfg.Logger.Info("served key authentication certificate",
zap.String("server_name", clientHello.ServerName),
zap.String("challenge", "tls-alpn-01"),
zap.String("remote", clientHello.Conn.RemoteAddr().String()),
zap.Bool("distributed", distributed))
return challengeCert, nil
}
}
@ -160,48 +154,44 @@ func (cfg *Config) getCertificateFromCache(hello *tls.ClientHelloInfo) (cert Cer
// then all certificates in the cache will be passed in
// for the cfg.CertSelection to make the final decision.
func (cfg *Config) selectCert(hello *tls.ClientHelloInfo, name string) (Certificate, bool) {
logger := loggerNamed(cfg.Logger, "handshake")
logger := cfg.Logger.Named("handshake")
choices := cfg.certCache.getAllMatchingCerts(name)
if len(choices) == 0 {
if cfg.CertSelection == nil {
if logger != nil {
logger.Debug("no matching certificates and no custom selection logic", zap.String("identifier", name))
}
logger.Debug("no matching certificates and no custom selection logic", zap.String("identifier", name))
return Certificate{}, false
}
if logger != nil {
logger.Debug("no matching certificate; will choose from all certificates", zap.String("identifier", name))
}
logger.Debug("no matching certificate; will choose from all certificates", zap.String("identifier", name))
choices = cfg.certCache.getAllCerts()
}
if logger != nil {
logger.Debug("choosing certificate",
zap.String("identifier", name),
zap.Int("num_choices", len(choices)))
}
logger.Debug("choosing certificate",
zap.String("identifier", name),
zap.Int("num_choices", len(choices)))
if cfg.CertSelection == nil {
cert, err := DefaultCertificateSelector(hello, choices)
if logger != nil {
logger.Debug("default certificate selection results",
zap.Error(err),
zap.String("identifier", name),
zap.Strings("subjects", cert.Names),
zap.Bool("managed", cert.managed),
zap.String("issuer_key", cert.issuerKey),
zap.String("hash", cert.hash))
}
return cert, err == nil
}
cert, err := cfg.CertSelection.SelectCertificate(hello, choices)
if logger != nil {
logger.Debug("custom certificate selection results",
logger.Debug("default certificate selection results",
zap.Error(err),
zap.String("identifier", name),
zap.Strings("subjects", cert.Names),
zap.Bool("managed", cert.managed),
zap.String("issuer_key", cert.issuerKey),
zap.String("hash", cert.hash))
return cert, err == nil
}
cert, err := cfg.CertSelection.SelectCertificate(hello, choices)
logger.Debug("custom certificate selection results",
zap.Error(err),
zap.String("identifier", name),
zap.Strings("subjects", cert.Names),
zap.Bool("managed", cert.managed),
zap.String("issuer_key", cert.issuerKey),
zap.String("hash", cert.hash))
return cert, err == nil
}
@ -243,23 +233,21 @@ func DefaultCertificateSelector(hello *tls.ClientHelloInfo, choices []Certificat
//
// This function is safe for concurrent use.
func (cfg *Config) getCertDuringHandshake(ctx context.Context, hello *tls.ClientHelloInfo, loadIfNecessary, obtainIfNecessary bool) (Certificate, error) {
log := logWithRemote(loggerNamed(cfg.Logger, "handshake"), hello)
log := logWithRemote(cfg.Logger.Named("handshake"), hello)
// First check our in-memory cache to see if we've already loaded it
cert, matched, defaulted := cfg.getCertificateFromCache(hello)
if matched {
if log != nil {
log.Debug("matched certificate in cache",
zap.Strings("subjects", cert.Names),
zap.Bool("managed", cert.managed),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.String("hash", cert.hash))
}
log.Debug("matched certificate in cache",
zap.Strings("subjects", cert.Names),
zap.Bool("managed", cert.managed),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.String("hash", cert.hash))
if cert.managed && cfg.OnDemand != nil && obtainIfNecessary {
// On-demand certificates are maintained in the background, but
// maintenance is triggered by handshakes instead of by a timer
// as in maintain.go.
return cfg.optionalMaintenance(ctx, loggerNamed(cfg.Logger, "on_demand"), cert, hello)
return cfg.optionalMaintenance(ctx, cfg.Logger.Named("on_demand"), cert, hello)
}
return cert, nil
}
@ -308,20 +296,16 @@ func (cfg *Config) getCertDuringHandshake(ctx context.Context, hello *tls.Client
loadedCert, err = cfg.CacheManagedCertificate(ctx, strings.Join(labels, "."))
}
if err == nil {
if log != nil {
log.Debug("loaded certificate from storage",
zap.Strings("subjects", loadedCert.Names),
zap.Bool("managed", loadedCert.managed),
zap.Time("expiration", expiresAt(loadedCert.Leaf)),
zap.String("hash", loadedCert.hash))
}
log.Debug("loaded certificate from storage",
zap.Strings("subjects", loadedCert.Names),
zap.Bool("managed", loadedCert.managed),
zap.Time("expiration", expiresAt(loadedCert.Leaf)),
zap.String("hash", loadedCert.hash))
loadedCert, err = cfg.handshakeMaintenance(ctx, hello, loadedCert)
if err != nil {
if log != nil {
log.Error("maintaining newly-loaded certificate",
zap.String("server_name", name),
zap.Error(err))
}
log.Error("maintaining newly-loaded certificate",
zap.String("server_name", name),
zap.Error(err))
}
return loadedCert, nil
}
@ -333,27 +317,23 @@ func (cfg *Config) getCertDuringHandshake(ctx context.Context, hello *tls.Client
// Fall back to the default certificate if there is one
if defaulted {
if log != nil {
log.Debug("fell back to default certificate",
zap.Strings("subjects", cert.Names),
zap.Bool("managed", cert.managed),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.String("hash", cert.hash))
}
log.Debug("fell back to default certificate",
zap.Strings("subjects", cert.Names),
zap.Bool("managed", cert.managed),
zap.Time("expiration", expiresAt(cert.Leaf)),
zap.String("hash", cert.hash))
return cert, nil
}
if log != nil {
log.Debug("no certificate matching TLS ClientHello",
zap.String("server_name", hello.ServerName),
zap.String("remote", hello.Conn.RemoteAddr().String()),
zap.String("identifier", name),
zap.Uint16s("cipher_suites", hello.CipherSuites),
zap.Float64("cert_cache_fill", float64(cacheSize)/cacheCapacity), // may be approximate! because we are not within the lock
zap.Bool("load_if_necessary", loadIfNecessary),
zap.Bool("obtain_if_necessary", obtainIfNecessary),
zap.Bool("on_demand", cfg.OnDemand != nil))
}
log.Debug("no certificate matching TLS ClientHello",
zap.String("server_name", hello.ServerName),
zap.String("remote", hello.Conn.RemoteAddr().String()),
zap.String("identifier", name),
zap.Uint16s("cipher_suites", hello.CipherSuites),
zap.Float64("cert_cache_fill", float64(cacheSize)/cacheCapacity), // may be approximate! because we are not within the lock
zap.Bool("load_if_necessary", loadIfNecessary),
zap.Bool("obtain_if_necessary", obtainIfNecessary),
zap.Bool("on_demand", cfg.OnDemand != nil))
return Certificate{}, fmt.Errorf("no certificate available for '%s'", name)
}
@ -367,12 +347,10 @@ func (cfg *Config) optionalMaintenance(ctx context.Context, log *zap.Logger, cer
return newCert, nil
}
if log != nil {
log.Error("renewing certificate on-demand failed",
zap.Strings("subjects", cert.Names),
zap.Time("not_after", expiresAt(cert.Leaf)),
zap.Error(err))
}
log.Error("renewing certificate on-demand failed",
zap.Strings("subjects", cert.Names),
zap.Time("not_after", expiresAt(cert.Leaf)),
zap.Error(err))
if cert.Expired() {
return cert, err
@ -408,7 +386,7 @@ func (cfg *Config) checkIfCertShouldBeObtained(name string) error {
//
// This function is safe for use by multiple concurrent goroutines.
func (cfg *Config) obtainOnDemandCertificate(ctx context.Context, hello *tls.ClientHelloInfo) (Certificate, error) {
log := logWithRemote(loggerNamed(cfg.Logger, "on_demand"), hello)
log := logWithRemote(cfg.Logger.Named("on_demand"), hello)
name := cfg.getNameFromClientHello(hello)
@ -457,9 +435,7 @@ func (cfg *Config) obtainOnDemandCertificate(ctx context.Context, hello *tls.Cli
return Certificate{}, err
}
if log != nil {
log.Info("obtaining new certificate", zap.String("server_name", name))
}
log.Info("obtaining new certificate", zap.String("server_name", name))
// TODO: we are only adding a timeout because we don't know if the context passed in is actually cancelable...
// (timeout duration is based on https://caddy.community/t/zerossl-dns-challenge-failing-often-route53-plugin/13822/24?u=matt)
@ -491,35 +467,29 @@ func (cfg *Config) obtainOnDemandCertificate(ctx context.Context, hello *tls.Cli
//
// This function is safe for use by multiple concurrent goroutines.
func (cfg *Config) handshakeMaintenance(ctx context.Context, hello *tls.ClientHelloInfo, cert Certificate) (Certificate, error) {
log := loggerNamed(cfg.Logger, "on_demand")
log := cfg.Logger.Named("on_demand")
// Check OCSP staple validity
if cert.ocsp != nil && !freshOCSP(cert.ocsp) {
if log != nil {
log.Debug("OCSP response needs refreshing",
zap.Strings("identifiers", cert.Names),
zap.Int("ocsp_status", cert.ocsp.Status),
zap.Time("this_update", cert.ocsp.ThisUpdate),
zap.Time("next_update", cert.ocsp.NextUpdate))
}
log.Debug("OCSP response needs refreshing",
zap.Strings("identifiers", cert.Names),
zap.Int("ocsp_status", cert.ocsp.Status),
zap.Time("this_update", cert.ocsp.ThisUpdate),
zap.Time("next_update", cert.ocsp.NextUpdate))
err := stapleOCSP(ctx, cfg.OCSP, cfg.Storage, &cert, nil)
if err != nil {
// An error with OCSP stapling is not the end of the world, and in fact, is
// quite common considering not all certs have issuer URLs that support it.
if log != nil {
log.Warn("stapling OCSP",
zap.String("server_name", hello.ServerName),
zap.Error(err))
}
} else if log != nil {
if log != nil {
log.Debug("successfully stapled new OCSP response",
zap.Strings("identifiers", cert.Names),
zap.Int("ocsp_status", cert.ocsp.Status),
zap.Time("this_update", cert.ocsp.ThisUpdate),
zap.Time("next_update", cert.ocsp.NextUpdate))
}
log.Warn("stapling OCSP",
zap.String("server_name", hello.ServerName),
zap.Error(err))
} else {
log.Debug("successfully stapled new OCSP response",
zap.Strings("identifiers", cert.Names),
zap.Int("ocsp_status", cert.ocsp.Status),
zap.Time("this_update", cert.ocsp.ThisUpdate),
zap.Time("next_update", cert.ocsp.NextUpdate))
}
// our copy of cert has the new OCSP staple, so replace it in the cache
@ -531,14 +501,12 @@ func (cfg *Config) handshakeMaintenance(ctx context.Context, hello *tls.ClientHe
// We attempt to replace any certificates that were revoked.
// Crucially, this happens OUTSIDE a lock on the certCache.
if certShouldBeForceRenewed(cert) {
if log != nil {
log.Warn("on-demand certificate's OCSP status is REVOKED; will try to forcefully renew",
zap.Strings("identifiers", cert.Names),
zap.Int("ocsp_status", cert.ocsp.Status),
zap.Time("revoked_at", cert.ocsp.RevokedAt),
zap.Time("this_update", cert.ocsp.ThisUpdate),
zap.Time("next_update", cert.ocsp.NextUpdate))
}
log.Warn("on-demand certificate's OCSP status is REVOKED; will try to forcefully renew",
zap.Strings("identifiers", cert.Names),
zap.Int("ocsp_status", cert.ocsp.Status),
zap.Time("revoked_at", cert.ocsp.RevokedAt),
zap.Time("this_update", cert.ocsp.ThisUpdate),
zap.Time("next_update", cert.ocsp.NextUpdate))
return cfg.renewDynamicCertificate(ctx, hello, cert)
}
@ -562,7 +530,7 @@ func (cfg *Config) handshakeMaintenance(ctx context.Context, hello *tls.ClientHe
//
// This function is safe for use by multiple concurrent goroutines.
func (cfg *Config) renewDynamicCertificate(ctx context.Context, hello *tls.ClientHelloInfo, currentCert Certificate) (Certificate, error) {
log := loggerNamed(cfg.Logger, "on_demand")
log := cfg.Logger.Named("on_demand")
name := cfg.getNameFromClientHello(hello)
timeLeft := time.Until(expiresAt(currentCert.Leaf))
@ -584,23 +552,19 @@ func (cfg *Config) renewDynamicCertificate(ctx context.Context, hello *tls.Clien
// renewing it, so we might as well serve what we have without blocking, UNLESS
// we're forcing renewal, in which case the current certificate is not usable
if timeLeft > 0 && !revoked {
if log != nil {
log.Debug("certificate expires soon but is already being renewed; serving current certificate",
zap.Strings("subjects", currentCert.Names),
zap.Duration("remaining", timeLeft))
}
log.Debug("certificate expires soon but is already being renewed; serving current certificate",
zap.Strings("subjects", currentCert.Names),
zap.Duration("remaining", timeLeft))
return currentCert, nil
}
// otherwise, we'll have to wait for the renewal to finish so we don't serve
// a revoked or expired certificate
if log != nil {
log.Debug("certificate has expired, but is already being renewed; waiting for renewal to complete",
zap.Strings("subjects", currentCert.Names),
zap.Time("expired", expiresAt(currentCert.Leaf)),
zap.Bool("revoked", revoked))
}
log.Debug("certificate has expired, but is already being renewed; waiting for renewal to complete",
zap.Strings("subjects", currentCert.Names),
zap.Time("expired", expiresAt(currentCert.Leaf)),
zap.Bool("revoked", revoked))
// TODO: see if we can get a proper context in here, for true cancellation
timeout := time.NewTimer(2 * time.Minute)
@ -626,23 +590,19 @@ func (cfg *Config) renewDynamicCertificate(ctx context.Context, hello *tls.Clien
obtainCertWaitChansMu.Unlock()
}
if log != nil {
log = log.With(
zap.String("server_name", name),
zap.Strings("subjects", currentCert.Names),
zap.Time("expiration", expiresAt(currentCert.Leaf)),
zap.Duration("remaining", timeLeft),
zap.Bool("revoked", revoked),
)
}
log = log.With(
zap.String("server_name", name),
zap.Strings("subjects", currentCert.Names),
zap.Time("expiration", expiresAt(currentCert.Leaf)),
zap.Duration("remaining", timeLeft),
zap.Bool("revoked", revoked),
)
// Renew and reload the certificate
renewAndReload := func(ctx context.Context, cancel context.CancelFunc) (Certificate, error) {
defer cancel()
if log != nil {
log.Info("attempting certificate renewal")
}
log.Info("attempting certificate renewal")
// Make sure a certificate for this name should be obtained on-demand
err := cfg.checkIfCertShouldBeObtained(name)
@ -672,9 +632,7 @@ func (cfg *Config) renewDynamicCertificate(ctx context.Context, hello *tls.Clien
// make the replacement as atomic as possible.
newCert, err = cfg.CacheManagedCertificate(ctx, name)
if err != nil {
if log != nil {
log.Error("loading renewed certificate", zap.String("server_name", name), zap.Error(err))
}
log.Error("loading renewed certificate", zap.String("server_name", name), zap.Error(err))
} else {
// replace the old certificate with the new one
cfg.certCache.replaceCertificate(currentCert, newCert)
@ -688,9 +646,7 @@ func (cfg *Config) renewDynamicCertificate(ctx context.Context, hello *tls.Clien
unblockWaiters()
if err != nil {
if log != nil {
log.Error("renewing and reloading certificate", zap.Error(err))
}
log.Error("renewing and reloading certificate", zap.Error(err))
return newCert, err
}
@ -736,9 +692,7 @@ func (cfg *Config) getCertFromAnyCertManager(ctx context.Context, hello *tls.Cli
}
}
if upstreamCert == nil {
if log != nil {
log.Debug("all external certificate managers yielded no certificates and no errors", zap.String("sni", hello.ServerName))
}
log.Debug("all external certificate managers yielded no certificates and no errors", zap.String("sni", hello.ServerName))
return Certificate{}, nil
}
@ -748,12 +702,10 @@ func (cfg *Config) getCertFromAnyCertManager(ctx context.Context, hello *tls.Cli
return Certificate{}, fmt.Errorf("external certificate manager: %s: filling cert from leaf: %v", hello.ServerName, err)
}
if log != nil {
log.Debug("using externally-managed certificate",
zap.String("sni", hello.ServerName),
zap.Strings("names", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)))
}
log.Debug("using externally-managed certificate",
zap.String("sni", hello.ServerName),
zap.Strings("names", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)))
return cert, nil
}

5
handshake_test.go
View File

@ -4,7 +4,7 @@
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
@ -24,8 +24,9 @@ func TestGetCertificate(t *testing.T) {
c := &Cache{
cache: make(map[string]Certificate),
cacheIndex: make(map[string][]string),
logger: defaultTestLogger,
}
cfg := &Config{certCache: c}
cfg := &Config{Logger: defaultTestLogger, certCache: c}
// create a test connection for conn.LocalAddr()
l, _ := net.Listen("tcp", "127.0.0.1:0")

20
httphandler.go
View File

@ -73,11 +73,9 @@ func (am *ACMEIssuer) distributedHTTPChallengeSolver(w http.ResponseWriter, r *h
host := hostOnly(r.Host)
chalInfo, distributed, err := am.config.getChallengeInfo(r.Context(), host)
if err != nil {
if am.Logger != nil {
am.Logger.Error("looking up info for HTTP challenge",
zap.String("host", host),
zap.Error(err))
}
am.Logger.Error("looking up info for HTTP challenge",
zap.String("host", host),
zap.Error(err))
return false
}
return solveHTTPChallenge(am.Logger, w, r, chalInfo.Challenge, distributed)
@ -95,13 +93,11 @@ func solveHTTPChallenge(logger *zap.Logger, w http.ResponseWriter, r *http.Reque
w.Header().Add("Content-Type", "text/plain")
w.Write([]byte(challenge.KeyAuthorization))
r.Close = true
if logger != nil {
logger.Info("served key authentication",
zap.String("identifier", challenge.Identifier.Value),
zap.String("challenge", "http-01"),
zap.String("remote", r.RemoteAddr),
zap.Bool("distributed", distributed))
}
logger.Info("served key authentication",
zap.String("identifier", challenge.Identifier.Value),
zap.String("challenge", "http-01"),
zap.String("remote", r.RemoteAddr),
zap.Bool("distributed", distributed))
return true
}
return false

3
httphandler_test.go
View File

@ -22,10 +22,11 @@ import (
)
func TestHTTPChallengeHandlerNoOp(t *testing.T) {
am := &ACMEIssuer{CA: "https://example.com/acme/directory"}
am := &ACMEIssuer{CA: "https://example.com/acme/directory", Logger: defaultTestLogger}
testConfig := &Config{
Issuers: []Issuer{am},
Storage: &FileStorage{Path: "./_testdata_tmp"},
Logger: defaultTestLogger,
certCache: new(Cache),
}
am.config = testConfig

154
maintain.go
View File

@ -39,18 +39,14 @@ import (
// incrementing panicCount each time. Initial invocation should
// start panicCount at 0.
func (certCache *Cache) maintainAssets(panicCount int) {
log := loggerNamed(certCache.logger, "maintenance")
if log != nil {
log = log.With(zap.String("cache", fmt.Sprintf("%p", certCache)))
}
log := certCache.logger.Named("maintenance")
log = log.With(zap.String("cache", fmt.Sprintf("%p", certCache)))
defer func() {
if err := recover(); err != nil {
buf := make([]byte, stackTraceBufferSize)
buf = buf[:runtime.Stack(buf, false)]
if log != nil {
log.Error("panic", zap.Any("error", err), zap.ByteString("stack", buf))
}
log.Error("panic", zap.Any("error", err), zap.ByteString("stack", buf))
if panicCount < 10 {
certCache.maintainAssets(panicCount + 1)
}
@ -60,9 +56,7 @@ func (certCache *Cache) maintainAssets(panicCount int) {
renewalTicker := time.NewTicker(certCache.options.RenewCheckInterval)
ocspTicker := time.NewTicker(certCache.options.OCSPCheckInterval)
if log != nil {
log.Info("started background certificate maintenance")
}
log.Info("started background certificate maintenance")
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
@ -71,7 +65,7 @@ func (certCache *Cache) maintainAssets(panicCount int) {
select {
case <-renewalTicker.C:
err := certCache.RenewManagedCertificates(ctx)
if err != nil && log != nil {
if err != nil {
log.Error("renewing managed certificates", zap.Error(err))
}
case <-ocspTicker.C:
@ -79,9 +73,7 @@ func (certCache *Cache) maintainAssets(panicCount int) {
case <-certCache.stopChan:
renewalTicker.Stop()
ocspTicker.Stop()
if log != nil {
log.Info("stopped background certificate maintenance")
}
log.Info("stopped background certificate maintenance")
close(certCache.doneChan)
return
}
@ -94,7 +86,7 @@ func (certCache *Cache) maintainAssets(panicCount int) {
// need to call this. This method assumes non-interactive
// mode (i.e. operating in the background).
func (certCache *Cache) RenewManagedCertificates(ctx context.Context) error {
log := loggerNamed(certCache.logger, "maintenance")
log := certCache.logger.Named("maintenance")
// configs will hold a map of certificate name to the config
// to use when managing that certificate
@ -116,9 +108,7 @@ func (certCache *Cache) RenewManagedCertificates(ctx context.Context) error {
// the list of names on this cert should never be empty... programmer error?
if cert.Names == nil || len(cert.Names) == 0 {
if log != nil {
log.Warn("certificate has no names; removing from cache", zap.String("cert_key", certKey))
}
log.Warn("certificate has no names; removing from cache", zap.String("cert_key", certKey))
deleteQueue = append(deleteQueue, cert)
continue
}
@ -126,19 +116,15 @@ func (certCache *Cache) RenewManagedCertificates(ctx context.Context) error {
// get the config associated with this certificate
cfg, err := certCache.getConfig(cert)
if err != nil {
if log != nil {
log.Error("unable to get configuration to manage certificate; unable to renew",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
}
log.Error("unable to get configuration to manage certificate; unable to renew",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
continue
}
if cfg == nil {
// this is bad if this happens, probably a programmer error (oops)
if log != nil {
log.Error("no configuration associated with certificate; unable to manage",
zap.Strings("identifiers", cert.Names))
}
log.Error("no configuration associated with certificate; unable to manage",
zap.Strings("identifiers", cert.Names))
continue
}
if cfg.OnDemand != nil {
@ -156,11 +142,9 @@ func (certCache *Cache) RenewManagedCertificates(ctx context.Context) error {
storedCertExpiring, err := cfg.managedCertInStorageExpiresSoon(ctx, cert)
if err != nil {
// hmm, weird, but not a big deal, maybe it was deleted or something
if log != nil {
log.Warn("error while checking if stored certificate is also expiring soon",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
}
log.Warn("error while checking if stored certificate is also expiring soon",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
} else if !storedCertExpiring {
// if the certificate is NOT expiring soon and there was no error, then we
// are good to just reload the certificate from storage instead of repeating
@ -181,22 +165,18 @@ func (certCache *Cache) RenewManagedCertificates(ctx context.Context) error {
// Reload certificates that merely need to be updated in memory
for _, oldCert := range reloadQueue {
timeLeft := expiresAt(oldCert.Leaf).Sub(time.Now().UTC())
if log != nil {
log.Info("certificate expires soon, but is already renewed in storage; reloading stored certificate",
zap.Strings("identifiers", oldCert.Names),
zap.Duration("remaining", timeLeft))
}
log.Info("certificate expires soon, but is already renewed in storage; reloading stored certificate",
zap.Strings("identifiers", oldCert.Names),
zap.Duration("remaining", timeLeft))
cfg := configs[oldCert.Names[0]]
// crucially, this happens OUTSIDE a lock on the certCache
_, err := cfg.reloadManagedCertificate(ctx, oldCert)
if err != nil {
if log != nil {
log.Error("loading renewed certificate",
zap.Strings("identifiers", oldCert.Names),
zap.Error(err))
}
log.Error("loading renewed certificate",
zap.Strings("identifiers", oldCert.Names),
zap.Error(err))
continue
}
}
@ -206,11 +186,9 @@ func (certCache *Cache) RenewManagedCertificates(ctx context.Context) error {
cfg := configs[oldCert.Names[0]]
err := certCache.queueRenewalTask(ctx, oldCert, cfg)
if err != nil {
if log != nil {
log.Error("queueing renewal task",
zap.Strings("identifiers", oldCert.Names),
zap.Error(err))
}
log.Error("queueing renewal task",
zap.Strings("identifiers", oldCert.Names),
zap.Error(err))
continue
}
}
@ -226,14 +204,12 @@ func (certCache *Cache) RenewManagedCertificates(ctx context.Context) error {
}
func (certCache *Cache) queueRenewalTask(ctx context.Context, oldCert Certificate, cfg *Config) error {
log := loggerNamed(certCache.logger, "maintenance")
log := certCache.logger.Named("maintenance")
timeLeft := expiresAt(oldCert.Leaf).Sub(time.Now().UTC())
if log != nil {
log.Info("certificate expires soon; queuing for renewal",
zap.Strings("identifiers", oldCert.Names),
zap.Duration("remaining", timeLeft))
}
log.Info("certificate expires soon; queuing for renewal",
zap.Strings("identifiers", oldCert.Names),
zap.Duration("remaining", timeLeft))
// Get the name which we should use to renew this certificate;
// we only support managing certificates with one name per cert,
@ -243,11 +219,9 @@ func (certCache *Cache) queueRenewalTask(ctx context.Context, oldCert Certificat
// queue up this renewal job (is a no-op if already active or queued)
jm.Submit(cfg.Logger, "renew_"+renewName, func() error {
timeLeft := expiresAt(oldCert.Leaf).Sub(time.Now().UTC())
if log != nil {
log.Info("attempting certificate renewal",
zap.Strings("identifiers", oldCert.Names),
zap.Duration("remaining", timeLeft))
}
log.Info("attempting certificate renewal",
zap.Strings("identifiers", oldCert.Names),
zap.Duration("remaining", timeLeft))
// perform renewal - crucially, this happens OUTSIDE a lock on certCache
err := cfg.RenewCertAsync(ctx, renewName, false)
@ -280,7 +254,7 @@ func (certCache *Cache) queueRenewalTask(ctx context.Context, oldCert Certificat
// Ryan Sleevi's recommendations for good OCSP support:
// https://gist.github.com/sleevi/5efe9ef98961ecfb4da8
func (certCache *Cache) updateOCSPStaples(ctx context.Context) {
logger := loggerNamed(certCache.logger, "maintenance")
logger := certCache.logger.Named("maintenance")
// temporary structures to store updates or tasks
// so that we can keep our locks short-lived
@ -311,11 +285,9 @@ func (certCache *Cache) updateOCSPStaples(ctx context.Context) {
}
cfg, err := certCache.getConfig(cert)
if err != nil {
if logger != nil {
logger.Error("unable to get automation config for certificate; maintenance for this certificate will likely fail",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
}
logger.Error("unable to get automation config for certificate; maintenance for this certificate will likely fail",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
continue
}
// always try to replace revoked certificates, even if OCSP response is still fresh
@ -347,10 +319,8 @@ func (certCache *Cache) updateOCSPStaples(ctx context.Context) {
if qe.cfg == nil {
// this is bad if this happens, probably a programmer error (oops)
if logger != nil {
logger.Error("no configuration associated with certificate; unable to manage OCSP staples",
zap.Strings("identifiers", cert.Names))
}
logger.Error("no configuration associated with certificate; unable to manage OCSP staples",
zap.Strings("identifiers", cert.Names))
continue
}
@ -358,11 +328,9 @@ func (certCache *Cache) updateOCSPStaples(ctx context.Context) {
if err != nil {
if cert.ocsp != nil {
// if there was no staple before, that's fine; otherwise we should log the error
if logger != nil {
logger.Error("stapling OCSP",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
}
logger.Error("stapling OCSP",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
}
continue
}
@ -372,12 +340,10 @@ func (certCache *Cache) updateOCSPStaples(ctx context.Context) {
// sure we apply the update to all names on the certificate if
// the status is still Good.
if cert.ocsp != nil && cert.ocsp.Status == ocsp.Good && (lastNextUpdate.IsZero() || lastNextUpdate != cert.ocsp.NextUpdate) {
if logger != nil {
logger.Info("advancing OCSP staple",
zap.Strings("identifiers", cert.Names),
zap.Time("from", lastNextUpdate),
zap.Time("to", cert.ocsp.NextUpdate))
}
logger.Info("advancing OCSP staple",
zap.Strings("identifiers", cert.Names),
zap.Time("from", lastNextUpdate),
zap.Time("to", cert.ocsp.NextUpdate))
updated[certHash] = ocspUpdate{rawBytes: cert.Certificate.OCSPStaple, parsed: cert.ocsp}
}
@ -412,7 +378,7 @@ func (certCache *Cache) updateOCSPStaples(ctx context.Context) {
// Crucially, this happens OUTSIDE a lock on the certCache.
for _, renew := range renewQueue {
_, err := renew.cfg.forceRenew(ctx, logger, renew.oldCert)
if err != nil && logger != nil {
if err != nil {
logger.Info("forcefully renewing certificate due to REVOKED status",
zap.Strings("identifiers", renew.oldCert.Names),
zap.Error(err))
@ -567,16 +533,14 @@ func deleteExpiredCerts(ctx context.Context, storage Storage, gracePeriod time.D
// forceRenew forcefully renews cert and replaces it in the cache, and returns the new certificate. It is intended
// for use primarily in the case of cert revocation. This MUST NOT be called within a lock on cfg.certCacheMu.
func (cfg *Config) forceRenew(ctx context.Context, logger *zap.Logger, cert Certificate) (Certificate, error) {
if logger != nil {
if cert.ocsp != nil && cert.ocsp.Status == ocsp.Revoked {
logger.Warn("OCSP status for managed certificate is REVOKED; attempting to replace with new certificate",
zap.Strings("identifiers", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)))
} else {
logger.Warn("forcefully renewing certificate",
zap.Strings("identifiers", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)))
}
if cert.ocsp != nil && cert.ocsp.Status == ocsp.Revoked {
logger.Warn("OCSP status for managed certificate is REVOKED; attempting to replace with new certificate",
zap.Strings("identifiers", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)))
} else {
logger.Warn("forcefully renewing certificate",
zap.Strings("identifiers", cert.Names),
zap.Time("expiration", expiresAt(cert.Leaf)))
}
renewName := cert.Names[0]
@ -591,7 +555,7 @@ func (cfg *Config) forceRenew(ctx context.Context, logger *zap.Logger, cert Cert
var obtainInsteadOfRenew bool
if cert.ocsp != nil && cert.ocsp.RevocationReason == acme.ReasonKeyCompromise {
err := cfg.moveCompromisedPrivateKey(ctx, cert, logger)
if err != nil && logger != nil {
if err != nil {
logger.Error("could not remove compromised private key from use",
zap.Strings("identifiers", cert.Names),
zap.String("issuer", cert.issuerKey),
@ -612,11 +576,9 @@ func (cfg *Config) forceRenew(ctx context.Context, logger *zap.Logger, cert Cert
if err != nil {
if cert.ocsp != nil && cert.ocsp.Status == ocsp.Revoked {
// probably better to not serve a revoked certificate at all
if logger != nil {
logger.Error("unable to obtain new to certificate after OCSP status of REVOKED; removing from cache",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
}
logger.Error("unable to obtain new to certificate after OCSP status of REVOKED; removing from cache",
zap.Strings("identifiers", cert.Names),
zap.Error(err))
cfg.certCache.mu.Lock()
cfg.certCache.removeCertificate(cert)
cfg.certCache.mu.Unlock()

10
storage.go
View File

@ -237,16 +237,14 @@ func CleanUpOwnLocks(ctx context.Context, logger *zap.Logger) {
locksMu.Lock()
defer locksMu.Unlock()
for lockKey, storage := range locks {
err := storage.Unlock(ctx, lockKey)
if err == nil {
delete(locks, lockKey)
} else if logger != nil {
if err := storage.Unlock(ctx, lockKey); err != nil {
logger.Error("unable to clean up lock in storage backend",
zap.Any("storage", storage),
zap.String("lock_key", lockKey),
zap.Error(err),
)
zap.Error(err))
continue
}
delete(locks, lockKey)
}
}