From dccba71276796999f3e16a6560016dc5dd0a952a Mon Sep 17 00:00:00 2001
From: Matthew Holt <mholt@users.noreply.github.com>
Date: Tue, 29 Oct 2019 16:02:40 -0600
Subject: [PATCH] reverse_proxy: Structured logs
---
.../caddyhttp/reverseproxy/healthchecks.go | 59 ++++++++++++++-----
.../caddyhttp/reverseproxy/reverseproxy.go | 18 ++++--
2 files changed, 58 insertions(+), 19 deletions(-)
diff --git a/modules/caddyhttp/reverseproxy/healthchecks.go b/modules/caddyhttp/reverseproxy/healthchecks.go
index a64c21dc7..56e97bc0f 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 c2fb751ab..daa1f2320 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