reverse_proxy: Structured logs

2 files changed, 58 insertions, 19 deletions

diff --git a/modules/caddyhttp/reverseproxy/healthchecks.go b/modules/caddyhttp/reverseproxy/healthchecks.go
index a64c21d..56e97bc 100644
--- a/modules/caddyhttp/reverseproxy/healthchecks.go
+++ b/modules/caddyhttp/reverseproxy/healthchecks.go
@@ -19,7 +19,6 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
-	"log"
 	"net"
 	"net/http"
 	"net/url"
@@ -29,6 +28,7 @@ import (
 
 	"github.com/caddyserver/caddy/v2"
 	"github.com/caddyserver/caddy/v2/modules/caddyhttp"
+	"go.uber.org/zap"
 )
 
 // HealthChecks holds configuration related to health checking.
@@ -53,6 +53,7 @@ type ActiveHealthChecks struct {
 	stopChan   chan struct{}
 	httpClient *http.Client
 	bodyRegexp *regexp.Regexp
+	logger     *zap.Logger
 }
 
 // PassiveHealthChecks holds configuration related to passive
@@ -64,6 +65,8 @@ type PassiveHealthChecks struct {
 	UnhealthyRequestCount int            `json:"unhealthy_request_count,omitempty"`
 	UnhealthyStatus       []int          `json:"unhealthy_status,omitempty"`
 	UnhealthyLatency      caddy.Duration `json:"unhealthy_latency,omitempty"`
+
+	logger *zap.Logger
 }
 
 // CircuitBreaker is a type that can act as an early-warning
@@ -101,11 +104,16 @@ func (h *Handler) doActiveHealthChecksForAllHosts() {
 		go func(networkAddr string, host Host) {
 			network, addrs, err := caddy.ParseNetworkAddress(networkAddr)
 			if err != nil {
-				log.Printf("[ERROR] reverse_proxy: active health check for host %s: bad network address: %v", networkAddr, err)
+				h.HealthChecks.Active.logger.Error("bad network address",
+					zap.String("address", networkAddr),
+					zap.Error(err),
+				)
 				return
 			}
 			if len(addrs) != 1 {
-				log.Printf("[ERROR] reverse_proxy: active health check for host %s: multiple addresses (upstream must map to only one address)", networkAddr)
+				h.HealthChecks.Active.logger.Error("multiple addresses (upstream must map to only one address)",
+					zap.String("address", networkAddr),
+				)
 				return
 			}
 			hostAddr := addrs[0]
@@ -117,7 +125,10 @@ func (h *Handler) doActiveHealthChecksForAllHosts() {
 			}
 			err = h.doActiveHealthCheck(DialInfo{Network: network, Address: addrs[0]}, hostAddr, host)
 			if err != nil {
-				log.Printf("[ERROR] reverse_proxy: active health check for host %s: %v", networkAddr, err)
+				h.HealthChecks.Active.logger.Error("active health check failed",
+					zap.String("address", networkAddr),
+					zap.Error(err),
+				)
 			}
 		}(networkAddr, host)
 
@@ -171,7 +182,10 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, host H
 	// do the request, being careful to tame the response body
 	resp, err := h.HealthChecks.Active.httpClient.Do(req)
 	if err != nil {
-		log.Printf("[INFO] reverse_proxy: active health check: %s is down (HTTP request failed: %v)", hostAddr, err)
+		h.HealthChecks.Active.logger.Info("HTTP request failed",
+			zap.String("host", hostAddr),
+			zap.Error(err),
+		)
 		_, err2 := host.SetHealthy(false)
 		if err2 != nil {
 			return fmt.Errorf("marking unhealthy: %v", err2)
@@ -191,7 +205,10 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, host H
 	// if status code is outside criteria, mark down
 	if h.HealthChecks.Active.ExpectStatus > 0 {
 		if !caddyhttp.StatusCodeMatches(resp.StatusCode, h.HealthChecks.Active.ExpectStatus) {
-			log.Printf("[INFO] reverse_proxy: active health check: %s is down (status code %d unexpected)", hostAddr, resp.StatusCode)
+			h.HealthChecks.Active.logger.Info("unexpected status code",
+				zap.Int("status_code", resp.StatusCode),
+				zap.String("host", hostAddr),
+			)
 			_, err := host.SetHealthy(false)
 			if err != nil {
 				return fmt.Errorf("marking unhealthy: %v", err)
@@ -199,7 +216,10 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, host H
 			return nil
 		}
 	} else if resp.StatusCode < 200 || resp.StatusCode >= 400 {
-		log.Printf("[INFO] reverse_proxy: active health check: %s is down (status code %d out of tolerances)", hostAddr, resp.StatusCode)
+		h.HealthChecks.Active.logger.Info("status code out of tolerances",
+			zap.Int("status_code", resp.StatusCode),
+			zap.String("host", hostAddr),
+		)
 		_, err := host.SetHealthy(false)
 		if err != nil {
 			return fmt.Errorf("marking unhealthy: %v", err)
@@ -211,7 +231,10 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, host H
 	if h.HealthChecks.Active.bodyRegexp != nil {
 		bodyBytes, err := ioutil.ReadAll(body)
 		if err != nil {
-			log.Printf("[INFO] reverse_proxy: active health check: %s is down (failed to read response body)", hostAddr)
+			h.HealthChecks.Active.logger.Info("failed to read response body",
+				zap.String("host", hostAddr),
+				zap.Error(err),
+			)
 			_, err := host.SetHealthy(false)
 			if err != nil {
 				return fmt.Errorf("marking unhealthy: %v", err)
@@ -219,7 +242,9 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, host H
 			return nil
 		}
 		if !h.HealthChecks.Active.bodyRegexp.Match(bodyBytes) {
-			log.Printf("[INFO] reverse_proxy: active health check: %s is down (response body failed expectations)", hostAddr)
+			h.HealthChecks.Active.logger.Info("response body failed expectations",
+				zap.String("host", hostAddr),
+			)
 			_, err := host.SetHealthy(false)
 			if err != nil {
 				return fmt.Errorf("marking unhealthy: %v", err)
@@ -231,7 +256,9 @@ func (h *Handler) doActiveHealthCheck(dialInfo DialInfo, hostAddr string, host H
 	// passed health check parameters, so mark as healthy
 	swapped, err := host.SetHealthy(true)
 	if swapped {
-		log.Printf("[INFO] reverse_proxy: active health check: %s is back up", hostAddr)
+		h.HealthChecks.Active.logger.Info("host is up",
+			zap.String("host", hostAddr),
+		)
 	}
 	if err != nil {
 		return fmt.Errorf("marking healthy: %v", err)
@@ -258,8 +285,10 @@ func (h *Handler) countFailure(upstream *Upstream) {
 	// count failure immediately
 	err := upstream.Host.CountFail(1)
 	if err != nil {
-		log.Printf("[ERROR] proxy: upstream %s: counting failure: %v",
-			upstream.Dial, err)
+		h.HealthChecks.Passive.logger.Error("could not count failure",
+			zap.String("host", upstream.Dial),
+			zap.Error(err),
+		)
 	}
 
 	// forget it later
@@ -267,8 +296,10 @@ func (h *Handler) countFailure(upstream *Upstream) {
 		time.Sleep(failDuration)
 		err := host.CountFail(-1)
 		if err != nil {
-			log.Printf("[ERROR] proxy: upstream %s: expiring failure: %v",
-				upstream.Dial, err)
+			h.HealthChecks.Passive.logger.Error("could not forget failure",
+				zap.String("host", upstream.Dial),
+				zap.Error(err),
+			)
 		}
 	}(upstream.Host, failDuration)
 }
diff --git a/modules/caddyhttp/reverseproxy/reverseproxy.go b/modules/caddyhttp/reverseproxy/reverseproxy.go
index c2fb751..daa1f23 100644
--- a/modules/caddyhttp/reverseproxy/reverseproxy.go
+++ b/modules/caddyhttp/reverseproxy/reverseproxy.go
@@ -28,6 +28,7 @@ import (
 	"github.com/caddyserver/caddy/v2"
 	"github.com/caddyserver/caddy/v2/modules/caddyhttp"
 	"github.com/caddyserver/caddy/v2/modules/caddyhttp/headers"
+	"go.uber.org/zap"
 	"golang.org/x/net/http/httpguts"
 )
 
@@ -47,6 +48,8 @@ type Handler struct {
 
 	Transport http.RoundTripper `json:"-"`
 	CB        CircuitBreaker    `json:"-"`
+
+	logger *zap.Logger
 }
 
 // CaddyModule returns the Caddy module information.
@@ -59,6 +62,8 @@ func (Handler) CaddyModule() caddy.ModuleInfo {
 
 // Provision ensures that h is set up properly before use.
 func (h *Handler) Provision(ctx caddy.Context) error {
+	h.logger = ctx.Logger(h)
+
 	// start by loading modules
 	if h.TransportRaw != nil {
 		val, err := ctx.LoadModuleInline("protocol", "http.handlers.reverse_proxy.transport", h.TransportRaw)
@@ -129,6 +134,8 @@ func (h *Handler) Provision(ctx caddy.Context) error {
 	if h.HealthChecks != nil &&
 		h.HealthChecks.Active != nil &&
 		(h.HealthChecks.Active.Path != "" || h.HealthChecks.Active.Port != 0) {
+		h.HealthChecks.Active.logger = h.logger.Named("health_checker.active")
+
 		timeout := time.Duration(h.HealthChecks.Active.Timeout)
 		if timeout == 0 {
 			timeout = 10 * time.Second
@@ -174,11 +181,12 @@ func (h *Handler) Provision(ctx caddy.Context) error {
 		// without MaxRequests), copy the value into this upstream, since the
 		// value in the upstream (MaxRequests) is what is used during
 		// availability checks
-		if h.HealthChecks != nil &&
-			h.HealthChecks.Passive != nil &&
-			h.HealthChecks.Passive.UnhealthyRequestCount > 0 &&
-			upstream.MaxRequests == 0 {
-			upstream.MaxRequests = h.HealthChecks.Passive.UnhealthyRequestCount
+		if h.HealthChecks != nil && h.HealthChecks.Passive != nil {
+			h.HealthChecks.Passive.logger = h.logger.Named("health_checker.passive")
+			if h.HealthChecks.Passive.UnhealthyRequestCount > 0 &&
+				upstream.MaxRequests == 0 {
+				upstream.MaxRequests = h.HealthChecks.Passive.UnhealthyRequestCount
+			}
 		}
 
 		// upstreams need independent access to the passive