Merge pull request #137 from rekby/devel

Fix nil exceptions

cmd/main.go

@@ -90,6 +90,8 @@ func startMetrics(ctx context.Context, r prometheus.Gatherer, config config.Conf
 
 	secretMetric := secrethandler.New(zc.L(ctx).Named("metrics_secret"), config.GetSecretHandlerConfig(), m)
 	go func() {
+		defer log.HandlePanic(loggerLocal)
+
 		err := http.Serve(listener, secretMetric)
 		var effectiveError = err
 		if effectiveError == http.ErrServerClosed {
@@ -156,6 +158,8 @@ func startProgram(config *configType) {
 	log.InfoFatal(logger, err, "Apply proxy config")
 
 	go func() {
+		defer log.HandlePanic(logger)
+
 		<-ctx.Done()
 		err := p.Close()
 		log.DebugError(logger, err, "Stop proxy")
@@ -178,6 +182,8 @@ func startProfiler(ctx context.Context, config profiler.Config) {
 	}
 
 	go func() {
+		defer log.HandlePanic(logger)
+
 		httpServer := http.Server{
 			Addr:    config.BindAddress,
 			Handler: profiler.New(logger.Named("profiler"), config),

go.sum

@@ -125,6 +125,7 @@ github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+
 github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
+github.com/stretchr/testify v1.4.0 h1:2E4SXV/wtOkTonXsotYi4li6zVWxYlZuYNCXe9XRJyk=
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
 github.com/ugorji/go/codec v0.0.0-20181204163529-d75b2dcb6bc8/go.mod h1:VFNgLljTbGfSG7qAOspJ7OScBnGdDN/yBr0sguwnwf0=
 github.com/xordataexchange/crypt v0.0.3-0.20170626215501-b2862e3d0a77/go.mod h1:aYKd//L2LvnjZzWKhF00oedf4jCCReLcmhLdhm1A27Q=
@@ -188,4 +189,5 @@ gopkg.in/natefinch/lumberjack.v2 v2.0.0/go.mod h1:l0ndWWf7gzL7RNwBG7wST/UCcT4T24
 gopkg.in/yaml.v2 v2.2.1/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
 gopkg.in/yaml.v2 v2.2.4/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
+gopkg.in/yaml.v2 v2.2.5 h1:ymVxjfMaHvXD8RqPRmzHHsB3VvucivSkIAvJFDI5O3c=
 gopkg.in/yaml.v2 v2.2.5/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=

internal/acme_client_manager/client_manager.go

@@ -130,6 +130,7 @@ func (m *AcmeManager) GetClient(ctx context.Context) (*acme.Client, error) {
 	}
 
 	if m.client != nil {
+		// handlepanic: in accountRenew
 		go m.accountRenew()
 	}
 
@@ -160,7 +161,12 @@ func (m *AcmeManager) accountRenew() {
 			log.InfoCtx(m.ctx, "Stop renew acme account because cancel context", zap.Error(m.ctx.Err()))
 			return
 		case <-ticker.C:
-			newAccount := renewTos(m.ctx, m.client, m.account)
+			var newAccount *acme.Account
+			func() {
+				defer log.HandlePanic(logger)
+
+				newAccount = renewTos(m.ctx, m.client, m.account)
+			}()
 			m.mu.Lock()
 			m.account = newAccount
 			m.mu.Unlock()
@@ -201,6 +207,7 @@ func (m *AcmeManager) loadFromCache(ctx context.Context) (err error) {
 	m.client = &acme.Client{DirectoryURL: m.DirectoryURL, Key: state.PrivateKey}
 	m.account = state.AcmeAccount
 
+	// handlepanic: in accountRenew
 	go m.accountRenew()
 
 	return nil

internal/cache/disk.go

@@ -2,6 +2,8 @@ package cache
 
 import (
 	"context"
+	"github.com/rekby/lets-proxy2/internal/log"
+	"go.uber.org/zap/zapcore"
 	"io/ioutil"
 	"os"
 	"path/filepath"
@@ -28,13 +30,19 @@ func (c *DiskCache) Get(ctx context.Context, key string) ([]byte, error) {
 
 	filePath := c.filepath(key)
 
+	logLevel := zapcore.DebugLevel
 	res, err := ioutil.ReadFile(filePath)
-	if os.IsNotExist(err) {
-		err = ErrCacheMiss
+	if err != nil {
+		if os.IsNotExist(err) {
+			err = ErrCacheMiss
+		} else {
+			logLevel = zapcore.ErrorLevel
+		}
 	}
 
-	zc.L(ctx).Debug("Got from disk cache", zap.String("dir", c.Dir), zap.String("key", key),
+	log.LevelParamCtx(ctx, logLevel, "Got from disk cache", zap.String("dir", c.Dir), zap.String("key", key),
 		zap.String("file", filePath), zap.Error(err))
+
 	return res, err
 }
 

internal/cache/value_lru.go

@@ -69,6 +69,7 @@ func (c *MemoryValueLRU) Put(ctx context.Context, key string, value interface{})
 	c.mu.Lock()
 	c.m[key] = &memoryValueLRUItem{key: key, value: value, lastUsedTime: c.time()}
 	if len(c.m) > c.MaxSize {
+		// handlepanic: no external call
 		go c.clean()
 	}
 	c.mu.Unlock()
@@ -92,6 +93,7 @@ func (c *MemoryValueLRU) Delete(ctx context.Context, key string) (err error) {
 func (c *MemoryValueLRU) time() uint64 {
 	res := atomic.AddUint64(&c.lastTime, 1)
 	if res == math.MaxUint64/2 {
+		// handlepanic: no external call
 		go c.renumberTime()
 	}
 	return res

internal/cert_manager/cert-state_test.go

@@ -94,8 +94,9 @@ func TestCertStateManyIssuers(t *testing.T) {
 
 	for i := 0; i < cnt; i++ {
 		go func() {
+			defer wg.Done()
+
 			lockTimesChan <- lockFunc()
-			wg.Done()
 		}()
 	}
 	wg.Wait()

internal/cert_manager/manager.go

@@ -144,7 +144,7 @@ func (m *Manager) GetCertificate(hello *tls.ClientHelloInfo) (resultCert *tls.Ce
 
 	logger = logger.With(logDomain(needDomain))
 	ctx = zc.WithLogger(ctx, logger)
-	defer handlePanic(logger)
+	defer log.HandlePanic(logger)
 
 	logger.Info("Get certificate", zap.String("original_domain", hello.ServerName))
 	if isTLSALPN01Hello(hello) {
@@ -188,6 +188,7 @@ func (m *Manager) getCertificate(ctx context.Context, needDomain DomainName, cer
 				}
 			}
 			if !locked {
+				// handlepanic: in renewCertInBackground
 				go m.renewCertInBackground(ctx, needDomain, certDescription)
 			}
 		}
@@ -308,6 +309,7 @@ func filterDomains(ctx context.Context, checker DomainChecker, originalDomains [
 
 		go func() {
 			defer wg.Done()
+			defer log.HandlePanic(logger)
 
 			allow, err := checker.IsDomainAllowed(ctx, domain.ASCII())
 			logger.Debug("Check domain", logDomain(domain), zap.Bool("allowed", allow), zap.Error(err))
@@ -422,23 +424,25 @@ authorizeOrderLoop:
 		}
 		var err error
 		order, err = m.Client.AuthorizeOrder(ctx, authIDs)
-		log.DebugError(logger, err, "Create authorization order.")
+		log.DebugError(logger, err, "Create authorization order.", zap.Reflect("order", order))
 		if err != nil {
 			return nil, err
 		}
 
 		//noinspection GoDeferInLoop
-		defer func() {
-			go func() {
+		defer func(order *acme.Order) {
+			go func(order *acme.Order) {
+				defer log.HandlePanic(logger)
+
 				revokeLogger := logger.Named("background_auth_revoker")
 
 				revokeCtx, cancel := context.WithTimeout(context.Background(), revokeAuthorizationTimeout)
 				defer cancel()
 
 				revokeCtx = zc.WithLogger(revokeCtx, revokeLogger)
 				m.deactivatePendingAuthz(revokeCtx, order.AuthzURLs)
-			}()
-		}()
+			}(order)
+		}(order)
 
 		switch order.Status {
 		case acme.StatusReady:
@@ -458,7 +462,8 @@ authorizeOrderLoop:
 	authDomainLoop:
 		for _, zurl := range order.AuthzURLs {
 			z, err := client.GetAuthorization(ctx, zurl)
-			log.DebugError(logger, err, "Get authorization object.", zap.String("domain", z.Identifier.Value))
+
+			log.DebugError(logger, err, "Get authorization object.", zap.Reflect("authorization", z))
 			if err != nil {
 				return nil, err
 			}
@@ -514,7 +519,7 @@ authorizeOrderLoop:
 		// All authorizations are satisfied.
 		// Wait for the CA to update the order status.
 		order, err = client.WaitOrder(ctx, order.URI)
-		log.DebugWarning(logger, err, "Wait order authorization.")
+		log.DebugWarning(logger, err, "Wait order authorization.", zap.Reflect("order", order))
 		if err == nil {
 			break authorizeOrderLoop
 		}
@@ -574,6 +579,7 @@ func (m *Manager) issueCertificate(ctx context.Context, cd CertDescription, orde
 func (m *Manager) renewCertInBackground(ctx context.Context, needDomain DomainName, cd CertDescription) {
 	// detach from request lifetime, but save log context
 	logger := zc.L(ctx).Named("background")
+	defer log.HandlePanic(logger)
 	ctx, ctxCancel := context.WithTimeout(context.Background(), m.CertificateIssueTimeout)
 	defer ctxCancel()
 
@@ -590,7 +596,7 @@ func (m *Manager) deactivatePendingAuthz(ctx context.Context, uries []string) {
 	for _, uri := range uries {
 		localLogger := logger.With(zap.String("uri", uri))
 		authorization, err := m.Client.GetAuthorization(ctx, uri)
-		log.DebugError(localLogger, err, "Get authorization", zap.Any("authorization", authorization))
+		log.DebugError(localLogger, err, "Get authorization", zap.Reflect("authorization", authorization))
 		if err != nil {
 			continue
 		}
@@ -607,7 +613,7 @@ func (m *Manager) certKeyGetOrCreate(ctx context.Context, cd CertDescription) (c
 	logger := zc.L(ctx)
 
 	key, err := getCertificateKey(ctx, m.Cache, cd)
-	log.DebugError(logger, err, "Got certificate key from cache and reuse old key")
+	logger.Debug("Got certificate key from cache and reuse old key", zap.Error(err))
 	if err == nil {
 		return key, nil
 	}
@@ -626,11 +632,15 @@ func (m *Manager) fulfill(ctx context.Context, challenge *acme.Challenge, domain
 	switch challenge.Type {
 	case tlsAlpn01:
 		cert, err := m.Client.TLSALPN01ChallengeCert(challenge.Token, domain.String())
+		log.DebugError(logger, err, "Got TLSALPN01ChallengeCert", log.Cert(&cert))
 		if err != nil {
 			return nil, err
 		}
 		m.putCertToken(ctx, domain, &cert)
-		return func(localContext context.Context) { go m.deleteCertToken(localContext, domain) }, nil
+		return func(localContext context.Context) {
+			// handlepanic: in deleteCertToken
+			go m.deleteCertToken(localContext, domain)
+		}, nil
 	case http01:
 		resp, err := m.Client.HTTP01ChallengeResponse(challenge.Token)
 		if err != nil {
@@ -699,6 +709,8 @@ func (m *Manager) putCertToken(ctx context.Context, key DomainName, certificate
 }
 
 func (m *Manager) deleteCertToken(ctx context.Context, key DomainName) {
+	defer log.HandlePanicCtx(ctx)
+
 	err := m.certForDomainAuthorize.Delete(ctx, key.String())
 	log.DebugDPanicCtx(ctx, err, "Delete cert token", zap.String("key", key.String()))
 }
@@ -917,14 +929,6 @@ func isNeedRenew(cert *tls.Certificate, now time.Time) bool {
 	return cert.Leaf.NotAfter.Add(-renewBeforeExpire).Before(now)
 }
 
-// must called as defer handlepanic(logger)
-func handlePanic(logger *zap.Logger) {
-	err := recover()
-	if err != nil {
-		logger.DPanic("Panic handled", zap.Any("panic", err))
-	}
-}
-
 func isCertLocked(ctx context.Context, storage cache.Bytes, certName CertDescription) (bool, error) {
 	lockName := certName.LockName()
 

internal/cert_manager/manager_functional_test.go

@@ -27,8 +27,11 @@ import (
 )
 
 const forceRsaDomain = "force-rsa.ru"
+const testCertIssueTimeout = time.Second * 30
 
 func TestManager_GetCertificateHttp01(t *testing.T) {
+	t.Parallel()
+
 	ctx, flush := th.TestContext(t)
 	defer flush()
 
@@ -38,6 +41,7 @@ func TestManager_GetCertificateHttp01(t *testing.T) {
 	defer mc.Finish()
 
 	manager := New(createTestClient(t), newCacheMock(mc), nil)
+	manager.CertificateIssueTimeout = testCertIssueTimeout
 	manager.AutoSubdomains = []string{"www."}
 	manager.EnableTLSValidation = false
 	manager.EnableHTTPValidation = true
@@ -78,6 +82,8 @@ func TestManager_GetCertificateHttp01(t *testing.T) {
 }
 
 func TestManager_GetCertificateTls(t *testing.T) {
+	t.Parallel()
+
 	ctx, flush := th.TestContext(t)
 	defer flush()
 
@@ -87,7 +93,10 @@ func TestManager_GetCertificateTls(t *testing.T) {
 	defer mc.Finish()
 
 	manager := New(createTestClient(t), newCacheMock(mc), nil)
+	manager.CertificateIssueTimeout = testCertIssueTimeout
 	manager.AutoSubdomains = []string{"www."}
+	manager.EnableTLSValidation = true
+	manager.EnableHTTPValidation = false
 
 	lisneter, err := net.ListenTCP("tcp", &net.TCPAddr{Port: 5001})
 
@@ -195,18 +204,22 @@ func getCertificatesTests(t *testing.T, manager *Manager, ctx context.Context, l
 
 func getCertificatesTestsKeyType(t *testing.T, manager *Manager, keyType KeyType, ctx context.Context, logger *zap.Logger) {
 	t.Run("OneCert", func(t *testing.T) {
+		t.Parallel()
 		checkOkDomain(ctx, t, manager, keyType, keyType, "onecert.ru")
 	})
 
 	t.Run("punycode-domain", func(t *testing.T) {
+		t.Parallel()
 		checkOkDomain(ctx, t, manager, keyType, keyType, "xn--80adjurfhd.xn--p1ai") // проверка.рф
 	})
 
 	t.Run("OneCertCamelCase", func(t *testing.T) {
+		t.Parallel()
 		checkOkDomain(ctx, t, manager, keyType, keyType, "onecertCamelCase.ru")
 	})
 
 	t.Run("Locked", func(t *testing.T) {
+		t.Parallel()
 		domain := "locked.ru"
 
 		cert, err := manager.GetCertificate(createTLSHello(ctx, keyType, domain))
@@ -216,8 +229,9 @@ func getCertificatesTestsKeyType(t *testing.T, manager *Manager, keyType KeyType
 
 	//nolint[:dupl]
 	t.Run("ParallelCert", func(t *testing.T) {
-		// change top loevel logger
-		// no parallelize
+		t.Parallel()
+
+		// change top level logger
 		oldLogger := logger
 		logger = zap.NewNop()
 		defer func() {
@@ -252,6 +266,7 @@ func getCertificatesTestsKeyType(t *testing.T, manager *Manager, keyType KeyType
 	})
 
 	t.Run("RenewSoonExpiredCert", func(t *testing.T) {
+		t.Parallel()
 		const domain = "soon-expired.com"
 
 		// issue certificate
@@ -294,6 +309,7 @@ func getCertificatesTestsKeyType(t *testing.T, manager *Manager, keyType KeyType
 	})
 
 	t.Run("Force-rsa", func(t *testing.T) {
+		t.Parallel()
 		checkOkDomain(ctx, t, manager, keyType, KeyRSA, forceRsaDomain)
 	})
 }