diff --git a/account_test.go b/account_test.go index 4fbd404..2fd72f9 100644 --- a/account_test.go +++ b/account_test.go @@ -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 diff --git a/acmeclient.go b/acmeclient.go index 90a06ba..b478573 100644 --- a/acmeclient.go +++ b/acmeclient.go @@ -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 } diff --git a/acmeissuer.go b/acmeissuer.go index 4b49b1f..83073b5 100644 --- a/acmeissuer.go +++ b/acmeissuer.go @@ -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. diff --git a/async.go b/async.go index 67627b2..584a9c2 100644 --- a/async.go +++ b/async.go @@ -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 } } diff --git a/cache.go b/cache.go index 044812b..f5ab868 100644 --- a/cache.go +++ b/cache.go @@ -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 { diff --git a/certificates.go b/certificates.go index 1718e47..5f9d0c8 100644 --- a/certificates.go +++ b/certificates.go @@ -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) diff --git a/certificates_test.go b/certificates_test.go index b5d45ea..a0139fc 100644 --- a/certificates_test.go +++ b/certificates_test.go @@ -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 { diff --git a/certmagic.go b/certmagic.go index 114a74d..9ee121d 100644 --- a/certmagic.go +++ b/certmagic.go @@ -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. diff --git a/certmagic_test.go b/certmagic_test.go index 845fc24..11e0f4d 100644 --- a/certmagic_test.go +++ b/certmagic_test.go @@ -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, +)) diff --git a/config.go b/config.go index d9381fd..3cb11bb 100644 --- a/config.go +++ b/config.go @@ -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) diff --git a/config_test.go b/config_test.go index 84d4ce5..667e87f 100644 --- a/config_test.go +++ b/config_test.go @@ -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 diff --git a/crypto.go b/crypto.go index bd70e54..7a11964 100644 --- a/crypto.go +++ b/crypto.go @@ -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 } diff --git a/handshake.go b/handshake.go index 8d0af13..d1697d5 100644 --- a/handshake.go +++ b/handshake.go @@ -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 } diff --git a/handshake_test.go b/handshake_test.go index e5d6efc..6e4bd77 100644 --- a/handshake_test.go +++ b/handshake_test.go @@ -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") diff --git a/httphandler.go b/httphandler.go index b9653eb..0736c34 100644 --- a/httphandler.go +++ b/httphandler.go @@ -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 diff --git a/httphandler_test.go b/httphandler_test.go index 8b09af8..2447ea6 100644 --- a/httphandler_test.go +++ b/httphandler_test.go @@ -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 diff --git a/maintain.go b/maintain.go index a6a67b6..eb340f1 100644 --- a/maintain.go +++ b/maintain.go @@ -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() diff --git a/storage.go b/storage.go index 0bb34cd..9cae3c3 100644 --- a/storage.go +++ b/storage.go @@ -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) } }