Convert (most of the library) to structured logs (closes #19)

Logging is now configurable through setting the Logging field on the
various relevant struct types. This is a more useful, consistent, and
higher-performing experience with logs than the std lib logger we used
before.

This isn't a 100% complete transition because there are some parts of
the code base that don't have obvious or easy access to a logger.
They are mostly fringe/edge cases though, and most are error logs, so
you shouldn't see them under normal circumstances. They still emit to
the std lib logger, so it's not like any errors get hidden: they are
just unstructured until we find a way to give them access to a logger.

account_test.go

@@ -16,7 +16,6 @@ package certmagic
 
 import (
 	"bytes"
-	"log"
 	"os"
 	"path/filepath"
 	"reflect"
@@ -137,12 +136,8 @@ func TestGetAccountAlreadyExists(t *testing.T) {
 		t.Fatalf("Error getting account: %v", err)
 	}
 
-	log.Printf("CREATED ACCOUNT: %#v", account)
-	log.Printf(" LOADED ACCOUNT: %#v", account)
-
 	// Assert keys are the same
 	if !privateKeysSame(account.PrivateKey, loadedAccount.PrivateKey) {
-		log.Println("OH NOEZ")
 		t.Error("Expected private key to be the same after loading, but it wasn't")
 	}
 

acmeclient.go

@@ -19,7 +19,6 @@ import (
 	"crypto/tls"
 	"crypto/x509"
 	"fmt"
-	"log"
 	weakrand "math/rand"
 	"net"
 	"net/http"
@@ -31,6 +30,7 @@ import (
 
 	"github.com/mholt/acmez"
 	"github.com/mholt/acmez/acme"
+	"go.uber.org/zap"
 )
 
 func init() {
@@ -131,10 +131,12 @@ func (am *ACMEManager) newACMEClient(ctx context.Context, useTestCA, interactive
 			PollTimeout: certObtainTimeout,
 			UserAgent:   buildUAString(),
 			HTTPClient:  hc,
-			// TODO: logging
 		},
 		ChallengeSolvers: make(map[string]acmez.Solver),
-		// TODO: logging
+	}
+	if am.Logger != nil {
+		l := am.Logger.Named("acme_client")
+		client.Client.Logger, client.Logger = l, l
 	}
 
 	// configure challenges (most of the time, DNS challenge is
@@ -249,12 +251,16 @@ func (c *acmeClient) throttle(ctx context.Context, names []string) error {
 		// TODO: stop rate limiter when it is garbage-collected...
 	}
 	rateLimitersMu.Unlock()
-	log.Printf("[INFO]%v Waiting on rate limiter...", names)
+	if c.mgr.Logger != nil {
+		c.mgr.Logger.Info("waiting on internal rate limiter", zap.Strings("identifiers", names))
+	}
 	err := rl.Wait(ctx)
 	if err != nil {
 		return err
 	}
-	log.Printf("[INFO]%v Done waiting", names)
+	if c.mgr.Logger != nil {
+		c.mgr.Logger.Info("done waiting on internal rate limiter", zap.Strings("identifiers", names))
+	}
 	return nil
 }
 
@@ -270,7 +276,7 @@ func (c *acmeClient) revoke(ctx context.Context, cert *x509.Certificate, reason
 func buildUAString() string {
 	ua := "CertMagic"
 	if UserAgent != "" {
-		ua += " " + UserAgent
+		ua = UserAgent + " " + ua
 	}
 	return ua
 }

acmemanager.go

@@ -12,6 +12,7 @@ import (
 
 	"github.com/mholt/acmez"
 	"github.com/mholt/acmez/acme"
+	"go.uber.org/zap"
 )
 
 // ACMEManager gets certificates using ACME. It implements the PreChecker,
@@ -87,6 +88,9 @@ type ACMEManager struct {
 	// when communicating with ACME server
 	Resolver string
 
+	// Set a logger to enable logging
+	Logger *zap.Logger
+
 	config     *Config
 	httpClient *http.Client
 }
@@ -141,6 +145,12 @@ func NewACMEManager(cfg *Config, template ACMEManager) *ACMEManager {
 	if template.CertObtainTimeout == 0 {
 		template.CertObtainTimeout = DefaultACME.CertObtainTimeout
 	}
+	if template.Resolver == "" {
+		template.Resolver = DefaultACME.Resolver
+	}
+	if template.Logger == nil {
+		template.Logger = DefaultACME.Logger
+	}
 	template.config = cfg
 	return &template
 }

async.go

@@ -7,6 +7,8 @@ import (
 	"runtime"
 	"sync"
 	"time"
+
+	"go.uber.org/zap"
 )
 
 var jm = &jobManager{maxConcurrentJobs: 1000}
@@ -20,15 +22,16 @@ type jobManager struct {
 }
 
 type namedJob struct {
-	name string
-	job  func() error
+	name   string
+	job    func() error
+	logger *zap.Logger
 }
 
 // Submit enqueues the given job with the given name. If name is non-empty
 // and a job with the same name is already enqueued or running, this is a
 // no-op. If name is empty, no duplicate prevention will occur. The job
 // manager will then run this job as soon as it is able.
-func (jm *jobManager) Submit(name string, job func() error) {
+func (jm *jobManager) Submit(logger *zap.Logger, name string, job func() error) {
 	jm.mu.Lock()
 	defer jm.mu.Unlock()
 	if jm.names == nil {
@@ -41,7 +44,7 @@ func (jm *jobManager) Submit(name string, job func() error) {
 		}
 		jm.names[name] = struct{}{}
 	}
-	jm.queue = append(jm.queue, namedJob{name, job})
+	jm.queue = append(jm.queue, namedJob{name, job, logger})
 	if jm.activeWorkers < jm.maxConcurrentJobs {
 		jm.activeWorkers++
 		go jm.worker()
@@ -68,7 +71,9 @@ func (jm *jobManager) worker() {
 		jm.queue = jm.queue[1:]
 		jm.mu.Unlock()
 		if err := next.job(); err != nil {
-			log.Printf("[ERROR] %v", err)
+			if next.logger != nil {
+				next.logger.Error("job failed", zap.Error(err))
+			}
 		}
 		if next.name != "" {
 			jm.mu.Lock()
@@ -78,7 +83,7 @@ func (jm *jobManager) worker() {
 	}
 }
 
-func doWithRetry(ctx context.Context, f func(context.Context) error) error {
+func doWithRetry(ctx context.Context, log *zap.Logger, f func(context.Context) error) error {
 	var attempts int
 	ctx = context.WithValue(ctx, AttemptsCtxKey, &attempts)
 
@@ -111,11 +116,22 @@ func doWithRetry(ctx context.Context, f func(context.Context) error) error {
 				intervalIndex++
 			}
 			if time.Since(start) < maxRetryDuration {
-				log.Printf("[ERROR] attempt %d: %v - retrying in %s (%s/%s elapsed)...",
-					attempts, err, retryIntervals[intervalIndex], 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))
+				}
 			} else {
-				log.Printf("[ERROR] final attempt: %v - giving up (%s/%s elapsed)...",
-					err, time.Since(start), maxRetryDuration)
+				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))
+				}
 				return nil
 			}
 		}

cache.go

@@ -16,11 +16,12 @@ package certmagic
 
 import (
 	"fmt"
-	"log"
 	weakrand "math/rand" // seeded elsewhere
 	"strings"
 	"sync"
 	"time"
+
+	"go.uber.org/zap"
 )
 
 // Cache is a structure that stores certificates in memory.
@@ -63,6 +64,8 @@ type Cache struct {
 
 	// Used to signal when stopping is completed
 	doneChan chan struct{}
+
+	logger *zap.Logger
 }
 
 // NewCache returns a new, valid Cache for efficiently
@@ -112,6 +115,7 @@ func NewCache(opts CacheOptions) *Cache {
 		cacheIndex: make(map[string][]string),
 		stopChan:   make(chan struct{}),
 		doneChan:   make(chan struct{}),
+		logger:     opts.Logger,
 	}
 
 	go c.maintainAssets(0)
@@ -162,6 +166,9 @@ type CacheOptions struct {
 	// If reached, certificates will be randomly evicted to
 	// make room for new ones. 0 means unlimited.
 	Capacity int
+
+	// Set a logger to enable logging
+	Logger *zap.Logger
 }
 
 // ConfigGetter is a function that returns a prepared,
@@ -251,8 +258,11 @@ func (certCache *Cache) replaceCertificate(oldCert, newCert Certificate) {
 	certCache.removeCertificate(oldCert)
 	certCache.unsyncedCacheCertificate(newCert)
 	certCache.mu.Unlock()
-	log.Printf("[INFO] Replaced certificate in cache for %v (new expiration date: %s)",
-		newCert.Names, newCert.Leaf.NotAfter.Format("2006-01-02 15:04:05"))
+	if certCache.logger != nil {
+		certCache.logger.Info("replaced certificate in cache",
+			zap.Strings("identifiers", newCert.Names),
+			zap.Time("new_expiration", newCert.Leaf.NotAfter))
+	}
 }
 
 func (certCache *Cache) getFirstMatchingCert(name string) (Certificate, bool) {

certificates.go

@@ -19,11 +19,11 @@ import (
 	"crypto/x509"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net"
 	"strings"
 	"time"
 
+	"go.uber.org/zap"
 	"golang.org/x/crypto/ocsp"
 )
 
@@ -108,7 +108,7 @@ func (cfg *Config) loadManagedCertificate(domain string) (Certificate, error) {
 	if err != nil {
 		return Certificate{}, err
 	}
-	cert, err := makeCertificateWithOCSP(cfg.Storage, certRes.CertificatePEM, certRes.PrivateKeyPEM)
+	cert, err := cfg.makeCertificateWithOCSP(certRes.CertificatePEM, certRes.PrivateKeyPEM)
 	if err != nil {
 		return cert, err
 	}
@@ -122,7 +122,7 @@ func (cfg *Config) loadManagedCertificate(domain string) (Certificate, error) {
 //
 // This method is safe for concurrent use.
 func (cfg *Config) CacheUnmanagedCertificatePEMFile(certFile, keyFile string, tags []string) error {
-	cert, err := makeCertificateFromDiskWithOCSP(cfg.Storage, certFile, keyFile)
+	cert, err := cfg.makeCertificateFromDiskWithOCSP(cfg.Storage, certFile, keyFile)
 	if err != nil {
 		return err
 	}
@@ -143,8 +143,8 @@ func (cfg *Config) CacheUnmanagedTLSCertificate(tlsCert tls.Certificate, tags []
 		return err
 	}
 	_, err = stapleOCSP(cfg.Storage, &cert, nil)
-	if err != nil {
-		log.Printf("[WARNING] Stapling OCSP: %v", err)
+	if err != nil && cfg.Logger != nil {
+		cfg.Logger.Warn("stapling OCSP", zap.Error(err))
 	}
 	cfg.emit("cached_unmanaged_cert", cert.Names)
 	cert.Tags = tags
@@ -157,7 +157,7 @@ func (cfg *Config) CacheUnmanagedTLSCertificate(tlsCert tls.Certificate, tags []
 //
 // This method is safe for concurrent use.
 func (cfg *Config) CacheUnmanagedCertificatePEMBytes(certBytes, keyBytes []byte, tags []string) error {
-	cert, err := makeCertificateWithOCSP(cfg.Storage, certBytes, keyBytes)
+	cert, err := cfg.makeCertificateWithOCSP(certBytes, keyBytes)
 	if err != nil {
 		return err
 	}
@@ -171,7 +171,7 @@ func (cfg *Config) CacheUnmanagedCertificatePEMBytes(certBytes, keyBytes []byte,
 // certificate and key files. It fills out all the fields in
 // the certificate except for the Managed and OnDemand flags.
 // (It is up to the caller to set those.) It staples OCSP.
-func makeCertificateFromDiskWithOCSP(storage Storage, certFile, keyFile string) (Certificate, error) {
+func (cfg Config) makeCertificateFromDiskWithOCSP(storage Storage, certFile, keyFile string) (Certificate, error) {
 	certPEMBlock, err := ioutil.ReadFile(certFile)
 	if err != nil {
 		return Certificate{}, err
@@ -180,19 +180,19 @@ func makeCertificateFromDiskWithOCSP(storage Storage, certFile, keyFile string)
 	if err != nil {
 		return Certificate{}, err
 	}
-	return makeCertificateWithOCSP(storage, certPEMBlock, keyPEMBlock)
+	return cfg.makeCertificateWithOCSP(certPEMBlock, keyPEMBlock)
 }
 
 // makeCertificateWithOCSP is the same as makeCertificate except that it also
 // staples OCSP to the certificate.
-func makeCertificateWithOCSP(storage Storage, certPEMBlock, keyPEMBlock []byte) (Certificate, error) {
+func (cfg Config) makeCertificateWithOCSP(certPEMBlock, keyPEMBlock []byte) (Certificate, error) {
 	cert, err := makeCertificate(certPEMBlock, keyPEMBlock)
 	if err != nil {
 		return cert, err
 	}
-	_, err = stapleOCSP(storage, &cert, certPEMBlock)
-	if err != nil {
-		log.Printf("[WARNING] Stapling OCSP: %v", err)
+	_, err = stapleOCSP(cfg.Storage, &cert, certPEMBlock)
+	if err != nil && cfg.Logger != nil {
+		cfg.Logger.Warn("stapling OCSP", zap.Error(err))
 	}
 	return cert, nil
 }
@@ -304,7 +304,9 @@ func (cfg *Config) managedCertInStorageExpiresSoon(cert Certificate) (bool, erro
 // to the new cert. It assumes that the new certificate for oldCert.Names[0] is
 // already in storage.
 func (cfg *Config) reloadManagedCertificate(oldCert Certificate) error {
-	log.Printf("[INFO] Reloading managed certificate for %v", oldCert.Names)
+	if cfg.Logger != nil {
+		cfg.Logger.Info("reloading managed certificate", zap.Strings("identifiers", oldCert.Names))
+	}
 	newCert, err := cfg.loadManagedCertificate(oldCert.Names[0])
 	if err != nil {
 		return fmt.Errorf("loading managed certificate for %v from storage: %v", oldCert.Names, err)