telemetry: add tracing

- telemetry/tace: add traces throughout code
- telemetry/metrics: nest metrics and trace under telemetry
- telemetry/tace: add service name span to HTTPMetricsHandler.
- telemetry/metrics: removed chain dependency middleware_tests.
- telemetry/metrics: wrap and encapsulate variatic view registration.
- telemetry/tace: add jaeger support for tracing.
- cmd/pomerium: move `parseOptions` to internal/config.
- cmd/pomerium: offload server handling to httputil and sub pkgs.
- httputil: standardize creation/shutdown of http listeners.
- httputil: prefer curve X25519 to P256 when negotiating TLS.
- fileutil: use standardized Getw

Signed-off-by: Bobby DeSimone <bobbydesimone@gmail.com>

cmd/pomerium/main.go

@@ -1,12 +1,10 @@
 package main // import "github.com/pomerium/pomerium/cmd/pomerium"
 
 import (
-	"errors"
 	"flag"
 	"fmt"
 	"net/http"
 	"os"
-	"strconv"
 	"time"
 
 	"github.com/fsnotify/fsnotify"
@@ -18,8 +16,9 @@ import (
 	"github.com/pomerium/pomerium/internal/config"
 	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/internal/log"
-	"github.com/pomerium/pomerium/internal/metrics"
 	"github.com/pomerium/pomerium/internal/middleware"
+	"github.com/pomerium/pomerium/internal/telemetry/metrics"
+	"github.com/pomerium/pomerium/internal/telemetry/trace"
 	"github.com/pomerium/pomerium/internal/urlutil"
 	"github.com/pomerium/pomerium/internal/version"
 	pbAuthenticate "github.com/pomerium/pomerium/proto/authenticate"
@@ -36,17 +35,18 @@ func main() {
 		fmt.Println(version.FullVersion())
 		os.Exit(0)
 	}
-	opt, err := parseOptions(*configFile)
+	opt, err := config.ParseOptions(*configFile)
 	if err != nil {
 		log.Fatal().Err(err).Msg("cmd/pomerium: options")
 	}
 	log.Info().Str("version", version.FullVersion()).Msg("cmd/pomerium")
-	grpcAuth := middleware.NewSharedSecretCred(opt.SharedKey)
-	grpcOpts := []grpc.ServerOption{grpc.UnaryInterceptor(grpcAuth.ValidateRequest), grpc.StatsHandler(metrics.NewGRPCServerStatsHandler(opt.Services))}
-	grpcServer := grpc.NewServer(grpcOpts...)
+
+	setupMetrics(opt)
+	setupTracing(opt)
+	setupHTTPRedirectServer(opt)
 
 	mux := http.NewServeMux()
-
+	grpcServer := setupGRPCServer(opt)
 	_, err = newAuthenticateService(*opt, mux, grpcServer)
 	if err != nil {
 		log.Fatal().Err(err).Msg("cmd/pomerium: authenticate")
@@ -61,65 +61,23 @@ func main() {
 	if err != nil {
 		log.Fatal().Err(err).Msg("cmd/pomerium: proxy")
 	}
+	defer proxy.AuthenticateClient.Close()
+	defer proxy.AuthorizeClient.Close()
+
 	go viper.WatchConfig()
 
 	viper.OnConfigChange(func(e fsnotify.Event) {
-		log.Info().
-			Str("file", e.Name).
-			Msg("cmd/pomerium: configuration file changed")
-
-		opt = handleConfigUpdate(opt, []config.OptionsUpdater{authz, proxy})
+		log.Info().Str("file", e.Name).Msg("cmd/pomerium: config file changed")
+		opt = config.HandleConfigUpdate(*configFile, opt, []config.OptionsUpdater{authz, proxy})
 	})
-	// defer statements ignored anyway :  https://stackoverflow.com/a/17888654
-	// defer proxyService.AuthenticateClient.Close()
-	// defer proxyService.AuthorizeClient.Close()
 
-	httpOpts := &httputil.Options{
-		Addr:              opt.Addr,
-		Cert:              opt.Cert,
-		Key:               opt.Key,
-		CertFile:          opt.CertFile,
-		KeyFile:           opt.KeyFile,
-		ReadTimeout:       opt.ReadTimeout,
-		WriteTimeout:      opt.WriteTimeout,
-		ReadHeaderTimeout: opt.ReadHeaderTimeout,
-		IdleTimeout:       opt.IdleTimeout,
+	srv, err := httputil.NewTLSServer(configToServerOptions(opt), mainHandler(opt, mux), grpcServer)
+	if err != nil {
+		log.Fatal().Err(err).Msg("cmd/pomerium: couldn't start pomerium")
 	}
+	httputil.Shutdown(srv)
 
-	if opt.MetricsAddr != "" {
-		go newPromListener(opt.MetricsAddr)
-		metrics.SetBuildInfo(opt.Services)
-	}
-
-	if srv, err := startRedirectServer(opt.HTTPRedirectAddr); err != nil {
-		log.Debug().Str("cause", err.Error()).Msg("cmd/pomerium: http redirect server not started")
-	} else {
-		defer srv.Close()
-	}
-
-	if err := httputil.ListenAndServeTLS(httpOpts, wrapMiddleware(opt, mux), grpcServer); err != nil {
-		log.Fatal().Err(err).Msg("cmd/pomerium: https server")
-	}
-}
-
-// startRedirectServer starts a http server that redirect HTTP to HTTPS traffic
-func startRedirectServer(addr string) (*http.Server, error) {
-	if addr == "" {
-		return nil, errors.New("no http redirect addr provided")
-	}
-	srv := &http.Server{
-		Addr:         addr,
-		ReadTimeout:  5 * time.Second,
-		WriteTimeout: 5 * time.Second,
-		Handler: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-			w.Header().Set("Connection", "close")
-			url := fmt.Sprintf("https://%s%s", urlutil.StripPort(r.Host), r.URL.String())
-			http.Redirect(w, r, url, http.StatusMovedPermanently)
-		}),
-	}
-	log.Info().Str("Addr", addr).Msg("cmd/pomerium: http redirect server started")
-	go func() { log.Error().Err(srv.ListenAndServe()).Msg("cmd/pomerium: http server closed") }()
-	return srv, nil
+	os.Exit(0)
 }
 
 func newAuthenticateService(opt config.Options, mux *http.ServeMux, rpc *grpc.Server) (*authenticate.Authenticate, error) {
@@ -159,21 +117,9 @@ func newProxyService(opt config.Options, mux *http.ServeMux) (*proxy.Proxy, erro
 	return service, nil
 }
 
-func newPromListener(addr string) {
-	metrics.RegisterView(metrics.HTTPClientViews)
-	metrics.RegisterView(metrics.HTTPServerViews)
-	metrics.RegisterView(metrics.GRPCClientViews)
-	metrics.RegisterView(metrics.GRPCServerViews)
-	metrics.RegisterInfoMetrics()
-	metrics.RegisterView(metrics.InfoViews)
-
-	log.Info().Str("MetricsAddr", addr).Msg("cmd/pomerium: starting prometheus endpoint")
-	log.Error().Err(metrics.NewPromHTTPListener(addr)).Str("MetricsAddr", addr).Msg("cmd/pomerium: could not start metrics exporter")
-}
-
-func wrapMiddleware(o *config.Options, mux http.Handler) http.Handler {
+func mainHandler(o *config.Options, mux http.Handler) http.Handler {
 	c := middleware.NewChain()
-	c = c.Append(metrics.HTTPMetricsHandler("proxy"))
+	c = c.Append(metrics.HTTPMetricsHandler(o.Services))
 	c = c.Append(log.NewHandler(log.Logger))
 	c = c.Append(log.AccessHandler(func(r *http.Request, status, size int, duration time.Duration) {
 		log.FromRequest(r).Debug().
@@ -199,60 +145,61 @@ func wrapMiddleware(o *config.Options, mux http.Handler) http.Handler {
 	return c.Then(mux)
 }
 
-func parseOptions(configFile string) (*config.Options, error) {
-	o, err := config.OptionsFromViper(configFile)
-	if err != nil {
-		return nil, err
+func configToServerOptions(opt *config.Options) *httputil.ServerOptions {
+	return &httputil.ServerOptions{
+		Addr:              opt.Addr,
+		Cert:              opt.Cert,
+		Key:               opt.Key,
+		CertFile:          opt.CertFile,
+		KeyFile:           opt.KeyFile,
+		ReadTimeout:       opt.ReadTimeout,
+		WriteTimeout:      opt.WriteTimeout,
+		ReadHeaderTimeout: opt.ReadHeaderTimeout,
+		IdleTimeout:       opt.IdleTimeout,
 	}
-	if o.Debug {
-		log.SetDebugMode()
-	}
-	if o.LogLevel != "" {
-		log.SetLevel(o.LogLevel)
-	}
-	metrics.AddPolicyCountCallback(o.Services, func() int64 {
-		return int64(len(o.Policies))
-	})
-
-	checksumDec, err := strconv.ParseUint(o.Checksum(), 16, 64)
-	if err != nil {
-		log.Warn().Err(err).Msg("Could not parse config checksum into decimal")
-	}
-	metrics.SetConfigChecksum(o.Services, checksumDec)
-
-	return o, nil
 }
 
-func handleConfigUpdate(opt *config.Options, services []config.OptionsUpdater) *config.Options {
-	newOpt, err := parseOptions(*configFile)
-	if err != nil {
-		log.Error().Err(err).Msg("cmd/pomerium: could not reload configuration")
-		metrics.SetConfigInfo(opt.Services, false, "")
-		return opt
-	}
-	optChecksum := opt.Checksum()
-	newOptChecksum := newOpt.Checksum()
-
-	log.Debug().
-		Str("old-checksum", optChecksum).
-		Str("new-checksum", newOptChecksum).
-		Msg("cmd/pomerium: configuration file changed")
-
-	if newOptChecksum == optChecksum {
-		log.Debug().Msg("cmd/pomerium: loaded configuration has not changed")
-		return opt
-	}
-
-	log.Info().Str("checksum", newOptChecksum).Msg("cmd/pomerium: checksum changed")
-	for _, service := range services {
-		if err := service.UpdateOptions(*newOpt); err != nil {
-			log.Error().Err(err).Msg("cmd/pomerium: could not update options")
-			metrics.SetConfigInfo(opt.Services, false, "")
+func setupMetrics(opt *config.Options) {
+	if opt.MetricsAddr != "" {
+		if handler, err := metrics.PrometheusHandler(); err != nil {
+			log.Error().Err(err).Msg("cmd/pomerium: couldn't start metrics server")
+		} else {
+			serverOpts := &httputil.ServerOptions{Addr: opt.MetricsAddr}
+			srv := httputil.NewHTTPServer(serverOpts, handler)
+			go httputil.Shutdown(srv)
 		}
 	}
-	metrics.AddPolicyCountCallback(newOpt.Services, func() int64 {
-		return int64(len(newOpt.Policies))
-	})
-	metrics.SetConfigInfo(newOpt.Services, true, newOptChecksum)
-	return newOpt
+}
+
+func setupTracing(opt *config.Options) {
+	if opt.TracingProvider != "" {
+		tracingOpts := &trace.TracingOptions{
+			Provider:                opt.TracingProvider,
+			Service:                 opt.Services,
+			Debug:                   opt.TracingDebug,
+			JaegerAgentEndpoint:     opt.TracingJaegerAgentEndpoint,
+			JaegerCollectorEndpoint: opt.TracingJaegerCollectorEndpoint,
+		}
+		if err := trace.RegisterTracing(tracingOpts); err != nil {
+			log.Error().Err(err).Msg("cmd/pomerium: couldn't register tracing")
+		} else {
+			log.Info().Interface("options", tracingOpts).Msg("cmd/pomerium: metrics configured")
+		}
+	}
+}
+
+func setupHTTPRedirectServer(opt *config.Options) {
+	if opt.HTTPRedirectAddr != "" {
+		serverOpts := httputil.ServerOptions{Addr: opt.HTTPRedirectAddr}
+		srv := httputil.NewHTTPServer(&serverOpts, httputil.RedirectHandler())
+		go httputil.Shutdown(srv)
+	}
+}
+
+func setupGRPCServer(opt *config.Options) *grpc.Server {
+	grpcAuth := middleware.NewSharedSecretCred(opt.SharedKey)
+	grpcOpts := []grpc.ServerOption{
+		grpc.UnaryInterceptor(grpcAuth.ValidateRequest),
+		grpc.StatsHandler(metrics.NewGRPCServerStatsHandler(opt.Services))}
+	return grpc.NewServer(grpcOpts...)
 }

cmd/pomerium/main_test.go

@@ -7,48 +7,19 @@ import (
 	"net/http/httptest"
 	"net/url"
 	"os"
+	"os/signal"
 	"reflect"
-	"strings"
+	"syscall"
 	"testing"
+	"time"
 
+	"github.com/google/go-cmp/cmp"
 	"github.com/pomerium/pomerium/internal/config"
+	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/internal/middleware"
 	"google.golang.org/grpc"
 )
 
-func Test_startRedirectServer(t *testing.T) {
-
-	tests := []struct {
-		name    string
-		addr    string
-		want    string
-		wantErr bool
-	}{
-		{"empty", "", "", true},
-		{":http", ":http", ":http", false},
-		{"localhost:80", "localhost:80", "localhost:80", false},
-	}
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			got, err := startRedirectServer(tt.addr)
-			if (err != nil) != tt.wantErr {
-				t.Errorf("startRedirectServer() error = %v, wantErr %v", err, tt.wantErr)
-				return
-			}
-			if got != nil {
-				defer got.Close()
-				ts := httptest.NewServer(got.Handler)
-				defer ts.Close()
-				_, err := http.Get(ts.URL)
-				if !strings.Contains(err.Error(), "https") {
-					t.Errorf("startRedirectServer() = %v, want %v", err, tt.want)
-					return
-				}
-			}
-		})
-	}
-}
-
 func Test_newAuthenticateService(t *testing.T) {
 	grpcAuth := middleware.NewSharedSecretCred("test")
 	grpcOpts := []grpc.ServerOption{grpc.UnaryInterceptor(grpcAuth.ValidateRequest)}
@@ -193,7 +164,7 @@ func Test_newProxyeService(t *testing.T) {
 	}
 }
 
-func Test_wrapMiddleware(t *testing.T) {
+func Test_mainHandler(t *testing.T) {
 	o := config.Options{
 		Services: "all",
 		Headers: map[string]string{
@@ -214,7 +185,7 @@ func Test_wrapMiddleware(t *testing.T) {
 	})
 
 	mux.Handle("/404", h)
-	out := wrapMiddleware(&o, mux)
+	out := mainHandler(&o, mux)
 	out.ServeHTTP(rr, req)
 	expected := fmt.Sprintf("OK")
 	body := rr.Body.String()
@@ -223,87 +194,106 @@ func Test_wrapMiddleware(t *testing.T) {
 		t.Errorf("handler returned unexpected body: got %v want %v", body, expected)
 	}
 }
-func Test_parseOptions(t *testing.T) {
+
+func Test_configToServerOptions(t *testing.T) {
 	tests := []struct {
-		name             string
-		envKey           string
-		envValue         string
-		servicesEnvKey   string
-		servicesEnvValue string
-		wantSharedKey    string
-		wantErr          bool
+		name string
+		opt  *config.Options
+		want *httputil.ServerOptions
 	}{
-		{"no shared secret", "", "", "SERVICES", "authenticate", "skip", true},
-		{"no shared secret in all mode", "", "", "", "", "", false},
-		{"good", "SHARED_SECRET", "YixWi1MYh77NMECGGIJQevoonYtVF+ZPRkQZrrmeRqM=", "", "", "YixWi1MYh77NMECGGIJQevoonYtVF+ZPRkQZrrmeRqM=", false},
+		{"simple convert", &config.Options{Addr: ":http"}, &httputil.ServerOptions{Addr: ":http"}},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			os.Setenv(tt.servicesEnvKey, tt.servicesEnvValue)
-			os.Setenv(tt.envKey, tt.envValue)
-			defer os.Unsetenv(tt.envKey)
-			defer os.Unsetenv(tt.servicesEnvKey)
-
-			got, err := parseOptions("")
-			if (err != nil) != tt.wantErr {
-				t.Errorf("parseOptions() error = %v, wantErr %v", err, tt.wantErr)
-				return
-			}
-			if got != nil && got.Services != "all" && got.SharedKey != tt.wantSharedKey {
-				t.Errorf("parseOptions()\n")
-				t.Errorf("got: %+v\n", got.SharedKey)
-				t.Errorf("want: %+v\n", tt.wantSharedKey)
-
+			if diff := cmp.Diff(configToServerOptions(tt.opt), tt.want); diff != "" {
+				t.Errorf("configToServerOptions() = \n %s", diff)
 			}
 		})
 	}
 }
 
-type mockService struct {
-	fail    bool
-	Updated bool
-}
-
-func (m *mockService) UpdateOptions(o config.Options) error {
-
-	m.Updated = true
-	if m.fail {
-		return fmt.Errorf("failed")
-	}
-	return nil
-}
-
-func Test_handleConfigUpdate(t *testing.T) {
-	os.Clearenv()
-	os.Setenv("SHARED_SECRET", "foo")
-	defer os.Unsetenv("SHARED_SECRET")
-
-	blankOpts, err := config.NewOptions("https://authenticate.example", "https://authorize.example")
-	if err != nil {
-		t.Fatal(err)
-	}
-
-	goodOpts, err := config.OptionsFromViper("")
-	if err != nil {
-		t.Fatal(err)
-	}
+func Test_setupGRPCServer(t *testing.T) {
 	tests := []struct {
-		name       string
-		service    *mockService
-		oldOpts    config.Options
-		wantUpdate bool
+		name     string
+		opt      *config.Options
+		dontWant *grpc.Server
 	}{
-		{"good", &mockService{fail: false}, *blankOpts, true},
-		{"bad", &mockService{fail: true}, *blankOpts, true},
-		{"no change", &mockService{fail: false}, *goodOpts, false},
+		{"good", &config.Options{SharedKey: "test"}, nil},
 	}
-
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			handleConfigUpdate(&tt.oldOpts, []config.OptionsUpdater{tt.service})
-			if tt.service.Updated != tt.wantUpdate {
-				t.Errorf("Failed to update config on service")
+			if diff := cmp.Diff(setupGRPCServer(tt.opt), tt.dontWant); diff == "" {
+				t.Errorf("setupGRPCServer() = \n %s", diff)
 			}
 		})
 	}
 }
+
+func Test_setupTracing(t *testing.T) {
+	tests := []struct {
+		name string
+		opt  *config.Options
+	}{
+		{"good jaeger", &config.Options{TracingProvider: "jaeger", TracingJaegerAgentEndpoint: "localhost:0", TracingJaegerCollectorEndpoint: "localhost:0"}},
+		{"dont register aything", &config.Options{}},
+		{"bad provider", &config.Options{TracingProvider: "bad provider"}},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			setupTracing(tt.opt)
+		})
+	}
+}
+
+func Test_setupMetrics(t *testing.T) {
+	tests := []struct {
+		name string
+		opt  *config.Options
+	}{
+		{"dont register aything", &config.Options{}},
+		{"good metrics server", &config.Options{MetricsAddr: "localhost:0"}},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			c := make(chan os.Signal, 1)
+			signal.Notify(c, syscall.SIGINT)
+			defer signal.Stop(c)
+			setupMetrics(tt.opt)
+			syscall.Kill(syscall.Getpid(), syscall.SIGINT)
+			waitSig(t, c, syscall.SIGINT)
+
+		})
+	}
+}
+
+func Test_setupHTTPRedirectServer(t *testing.T) {
+	tests := []struct {
+		name string
+		opt  *config.Options
+	}{
+		{"dont register aything", &config.Options{}},
+		{"good redirect server", &config.Options{HTTPRedirectAddr: "localhost:0"}},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			c := make(chan os.Signal, 1)
+			signal.Notify(c, syscall.SIGINT)
+			defer signal.Stop(c)
+			setupHTTPRedirectServer(tt.opt)
+			syscall.Kill(syscall.Getpid(), syscall.SIGINT)
+			waitSig(t, c, syscall.SIGINT)
+
+		})
+	}
+}
+
+func waitSig(t *testing.T, c <-chan os.Signal, sig os.Signal) {
+	select {
+	case s := <-c:
+		if s != sig {
+			t.Fatalf("signal was %v, want %v", s, sig)
+		}
+	case <-time.After(1 * time.Second):
+		t.Fatalf("timeout waiting for %v", sig)
+	}
+}