From dccba71276796999f3e16a6560016dc5dd0a952a Mon Sep 17 00:00:00 2001 From: Matthew Holt Date: Tue, 29 Oct 2019 16:02:40 -0600 Subject: reverse_proxy: Structured logs --- modules/caddyhttp/reverseproxy/healthchecks.go | 59 ++++++++++++++++++++------ 1 file changed, 45 insertions(+), 14 deletions(-) (limited to 'modules/caddyhttp/reverseproxy/healthchecks.go') 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) } -- cgit v1.2.3