Fix up stats after letsencrypt#3167 (letsencrypt#3185)

jsha · Roland Bracewell Shoemaker · commit 6cd777bd8d2a · 2017-10-18T11:14:59.000-07:00
There were two bugs in letsencrypt#3167: All process-level stats got prefixed with "boulder", which broke dashboards. All request_time stats got dropped, because measured_http was using the prometheus DefaultRegisterer. To fix, this PR plumbs through a scope object to measured_http, and uses an empty prefix when calling NewProcessCollector().
diff --git a/cmd/boulder-wfe/main.go b/cmd/boulder-wfe/main.go
@@ -133,9 +133,10 @@ func main() {
 	wfe.BaseURL = c.Common.BaseURL
 
 	logger.Info(fmt.Sprintf("Server running, listening on %s...\n", c.WFE.ListenAddress))
+	handler := wfe.Handler()
 	srv := &http.Server{
 		Addr:    c.WFE.ListenAddress,
-		Handler: wfe.Handler(),
+		Handler: handler,
 	}
 
 	go func() {
@@ -149,7 +150,7 @@ func main() {
 	if c.WFE.TLSListenAddress != "" {
 		tlsSrv = &http.Server{
 			Addr:    c.WFE.TLSListenAddress,
-			Handler: wfe.Handler(),
+			Handler: handler,
 		}
 		go func() {
 			err := tlsSrv.ListenAndServeTLS(c.WFE.ServerCertificatePath, c.WFE.ServerKeyPath)
diff --git a/cmd/boulder-wfe2/main.go b/cmd/boulder-wfe2/main.go
@@ -133,9 +133,10 @@ func main() {
 	wfe.BaseURL = c.Common.BaseURL
 
 	logger.Info(fmt.Sprintf("Server running, listening on %s...\n", c.WFE.ListenAddress))
+	handler := wfe.Handler()
 	srv := &http.Server{
 		Addr:    c.WFE.ListenAddress,
-		Handler: wfe.Handler(),
+		Handler: handler,
 	}
 
 	go func() {
@@ -149,7 +150,7 @@ func main() {
 	if c.WFE.TLSListenAddress != "" {
 		tlsSrv = &http.Server{
 			Addr:    c.WFE.TLSListenAddress,
-			Handler: wfe.Handler(),
+			Handler: handler,
 		}
 		go func() {
 			err := tlsSrv.ListenAndServeTLS(c.WFE.ServerCertificatePath, c.WFE.ServerKeyPath)
diff --git a/cmd/ocsp-responder/main.go b/cmd/ocsp-responder/main.go
@@ -253,5 +253,5 @@ func mux(scope metrics.Scope, responderPath string, source cfocsp.Source) http.H
 		}
 		stripPrefix.ServeHTTP(w, r)
 	})
-	return measured_http.New(&ocspMux{h}, cmd.Clock())
+	return measured_http.New(&ocspMux{h}, cmd.Clock(), scope)
 }
diff --git a/cmd/shell.go b/cmd/shell.go
@@ -153,7 +153,7 @@ func NewLogger(logConf SyslogConfig) blog.Logger {
 func newScope(addr string, logger blog.Logger) metrics.Scope {
 	registry := prometheus.NewRegistry()
 	registry.MustRegister(prometheus.NewGoCollector())
-	registry.MustRegister(prometheus.NewProcessCollector(os.Getpid(), "boulder"))
+	registry.MustRegister(prometheus.NewProcessCollector(os.Getpid(), ""))
 
 	mux := http.NewServeMux()
 	// Register each of the available pprof handlers. These are all registered on
diff --git a/metrics/measured_http/http.go b/metrics/measured_http/http.go
@@ -5,22 +5,10 @@ import (
 	"net/http"
 
 	"github.com/jmhodges/clock"
+	"github.com/letsencrypt/boulder/metrics"
 	"github.com/prometheus/client_golang/prometheus"
 )
 
-var (
-	responseTime = prometheus.NewHistogramVec(
-		prometheus.HistogramOpts{
-			Name: "response_time",
-			Help: "Time taken to respond to a request",
-		},
-		[]string{"endpoint", "method", "code"})
-)
-
-func init() {
-	prometheus.MustRegister(responseTime)
-}
-
 // responseWriterWithStatus satisfies http.ResponseWriter, but keeps track of the
 // status code for gathering stats.
 type responseWriterWithStatus struct {
@@ -50,7 +38,14 @@ type MeasuredHandler struct {
 	stat *prometheus.HistogramVec
 }
 
-func New(m serveMux, clk clock.Clock) *MeasuredHandler {
+func New(m serveMux, clk clock.Clock, scope metrics.Scope) *MeasuredHandler {
+	responseTime := prometheus.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Name: "response_time",
+			Help: "Time taken to respond to a request",
+		},
+		[]string{"endpoint", "method", "code"})
+	scope.MustRegister(responseTime)
 	return &MeasuredHandler{
 		serveMux: m,
 		clk:      clk,
diff --git a/test/integration-test.py b/test/integration-test.py
@@ -417,6 +417,17 @@ def test_admin_revoker_authz():
     if data['status'] != "revoked":
         raise Exception("Authorization wasn't revoked")
 
+def test_stats():
+    def expect_stat(port, stat):
+        url = "http://localhost:%d/metrics" % port
+        response = requests.get(url)
+        if not stat in response.content:
+            print(response.content)
+            raise Exception("%s not present in %s" % (stat, url))
+    expect_stat(8000, "\nresponse_time_count{")
+    expect_stat(8000, "\ngo_goroutines ")
+    expect_stat(8001, "\ngo_goroutines ")
+
 exit_status = 1
 tempdir = tempfile.mkdtemp()
 
@@ -483,6 +494,7 @@ def run_chisel():
     test_renewal_exemption()
     test_expired_authzs_404()
     test_account_update()
+    test_stats()
 
 if __name__ == "__main__":
     try:
diff --git a/wfe/wfe.go b/wfe/wfe.go
@@ -323,7 +323,7 @@ func (wfe *WebFrontEndImpl) Handler() http.Handler {
 	// meaning we can wind up returning 405 when we mean to return 404. See
 	// https://github.com/letsencrypt/boulder/issues/717
 	m.Handle("/", web.NewTopHandler(wfe.log, web.WFEHandlerFunc(wfe.Index)))
-	return measured_http.New(m, wfe.clk)
+	return measured_http.New(m, wfe.clk, wfe.stats)
 }
 
 // Method implementations
diff --git a/wfe2/wfe.go b/wfe2/wfe.go
@@ -65,6 +65,7 @@ type WebFrontEndImpl struct {
 	log   blog.Logger
 	clk   clock.Clock
 	stats wfe2Stats
+	scope metrics.Scope
 
 	// URL configuration parameters
 	BaseURL string
@@ -99,12 +100,12 @@ type WebFrontEndImpl struct {
 
 // NewWebFrontEndImpl constructs a web service for Boulder
 func NewWebFrontEndImpl(
-	stats metrics.Scope,
+	scope metrics.Scope,
 	clk clock.Clock,
 	keyPolicy goodkey.KeyPolicy,
 	logger blog.Logger,
 ) (WebFrontEndImpl, error) {
-	nonceService, err := nonce.NewNonceService(stats)
+	nonceService, err := nonce.NewNonceService(scope)
 	if err != nil {
 		return WebFrontEndImpl{}, err
 	}
@@ -114,7 +115,8 @@ func NewWebFrontEndImpl(
 		clk:          clk,
 		nonceService: nonceService,
 		keyPolicy:    keyPolicy,
-		stats:        initStats(stats),
+		stats:        initStats(scope),
+		scope:        scope,
 	}, nil
 }
 
@@ -318,7 +320,7 @@ func (wfe *WebFrontEndImpl) Handler() http.Handler {
 	// meaning we can wind up returning 405 when we mean to return 404. See
 	// https://github.com/letsencrypt/boulder/issues/717
 	m.Handle("/", web.NewTopHandler(wfe.log, web.WFEHandlerFunc(wfe.Index)))
-	return measured_http.New(m, wfe.clk)
+	return measured_http.New(m, wfe.clk, wfe.scope)
 }
 
 // Method implementations

Original file line number	Diff line number	Diff line change
`@@ -253,5 +253,5 @@ func mux(scope metrics.Scope, responderPath string, source cfocsp.Source) http.H`
`253`	`253`	`}`
`254`	`254`	`stripPrefix.ServeHTTP(w, r)`
`255`	`255`	`})`
`256`		`- return measured_http.New(&ocspMux{h}, cmd.Clock())`
	`256`	`+ return measured_http.New(&ocspMux{h}, cmd.Clock(), scope)`
`257`	`257`	`}`
Original file line number	Diff line number	Diff line change
`@@ -323,7 +323,7 @@ func (wfe *WebFrontEndImpl) Handler() http.Handler {`
`323`	`323`	`// meaning we can wind up returning 405 when we mean to return 404. See`
`324`	`324`	`// https://github.com/letsencrypt/boulder/issues/717`
`325`	`325`	`m.Handle("/", web.NewTopHandler(wfe.log, web.WFEHandlerFunc(wfe.Index)))`
`326`		`- return measured_http.New(m, wfe.clk)`
	`326`	`+ return measured_http.New(m, wfe.clk, wfe.stats)`
`327`	`327`	`}`
`328`	`328`
`329`	`329`	`// Method implementations`