Structured logging

Adopts `log/slog` (new in Go 1.21) for structured log output. The server
now supports:

- environment variable `LOG_LEVEL` which may be `DEBUG`, `INFO`, `WARN`,
  `ERROR` and governs which messages are written to stdout
- environment variable `LOG_FORMAT` which may be `default` for text
  output and `json` for JSON output

Sample log output with `LOG_FORMAT=default`:

```
time=2024-05-29T23:38:10.129Z level=INFO msg="Using Secret Key Seed provided in environment variable"
```

Sample log output with `LOG_FORMAT=json` and `LOG_LEVEL=debug`:

```json
{"time":"2024-05-29T23:40:03.417537397Z","level":"INFO","msg":"Using Secret Key Seed provided in environment variable"}
{"time":"2024-05-29T23:40:03.417885447Z","level":"DEBUG","msg":"OHTTP Gateway\n----------------\nConfig endpoint: /ohttp-keys\nLegacy config endpoint: /ohttp-configs\nTarget endpoint: /gateway\n   Request content type:  message/bhttp request\n   Response content type: message/bhttp response\nEcho endpoint: /gateway-echo\nMetadata endpoint: /gateway-metadata\n----------------\n"}
{"time":"2024-05-29T23:40:03.417894997Z","level":"DEBUG","msg":"Listening without enabling TLS","port":"81"}
{"time":"2024-05-29T23:40:03.417924067Z","level":"DEBUG","msg":"Listening for Prometheus scrapes","host":"","port":"9466"}
{"time":"2024-05-29T23:40:12.905084819Z","level":"DEBUG","msg":"Handling","method":"GET","path":"/health"}
{"time":"2024-05-29T23:40:22.905008975Z","level":"DEBUG","msg":"Handling","method":"GET","path":"/health"}
{"time":"2024-05-29T23:40:32.904921768Z","level":"DEBUG","msg":"Handling","method":"GET","path":"/health"}
{"time":"2024-05-29T23:40:42.905028673Z","level":"DEBUG","msg":"Handling","method":"GET","path":"/health"}
```

Closes #61

README.md

@@ -29,6 +29,10 @@ The behavior of the gateway is configurable via a number of environment variable
 - ALLOWED_TARGET_ORIGINS: This environment variable contains a comma-separated list of target origin names that the gateway is allowed to access. When configured, the gateway will only attempt to resolve requests to target origins in this list. Any other request will yield a HTTP 403 Forbidden return code.
 - CERT: This environment variable is the name of a file containing the certificate (chain) used to serve TLS connections.
 - KEY: This environment variable is the name of a file containing the private key used to serve TLS connections.
+- LOG_FORMAT: This environment variable controls the format in which events are logged. Supported values are:
+	- `default`: events are run through [`slog.TextHandler`](https://pkg.go.dev/log/slog@master#TextHandler).
+	- `json`: events are run through [`slog.JSONHandler`](https://pkg.go.dev/log/slog#JSONHandler).
+- LOG_LEVEL: This environment variable controls how noisy logs are. The supported values correspond to the [`slog.Level` values](https://pkg.go.dev/log/slog@master#Level).
 - TARGET_REWRITES: This environment variable contains a JSON document instructing the gateway to rewrite the target URL found in an encapsulated request to some specified scheme and host.
 
 ### Target URL rewrites

gateway.go

@@ -6,7 +6,7 @@ package main
 import (
 	"fmt"
 	"io/ioutil"
-	"log"
+	"log/slog"
 	"math/rand"
 	"net/http"
 	"time"
@@ -15,7 +15,6 @@ import (
 )
 
 type gatewayResource struct {
-	verbose               bool
 	legacyKeyID           uint8
 	gateway               ohttp.Gateway
 	encapsulationHandlers map[string]EncapsulationHandler
@@ -39,9 +38,7 @@ const (
 )
 
 func (s *gatewayResource) httpError(w http.ResponseWriter, status int, debugMessage string, metrics Metrics, metricsPrefix string) {
-	if s.verbose {
-		log.Println(debugMessage)
-	}
+	slog.Debug(debugMessage)
 	if s.debugResponse {
 		http.Error(w, debugMessage, status)
 	} else {
@@ -51,9 +48,7 @@ func (s *gatewayResource) httpError(w http.ResponseWriter, status int, debugMess
 }
 
 func (s *gatewayResource) gatewayHandler(w http.ResponseWriter, r *http.Request) {
-	if s.verbose {
-		log.Printf("%s Handling %s\n", r.Method, r.URL.Path)
-	}
+	slog.Debug("HTTP request", "method", r.Method, "path", r.URL.Path)
 
 	metrics := s.metricsFactory.Create(metricsEventGatewayRequest)
 
@@ -92,9 +87,7 @@ func (s *gatewayResource) gatewayHandler(w http.ResponseWriter, r *http.Request)
 
 	encapsulatedResp, err := encapHandler.Handle(r, encapsulatedReq, metrics)
 	if err != nil {
-		if s.verbose {
-			log.Printf(err.Error())
-		}
+		slog.Debug("encap handler", "error", err)
 
 		errorCode := encapsulationErrorToGatewayStatusCode(err)
 		s.httpError(w, errorCode, http.StatusText(errorCode), metrics, r.Method)
@@ -110,14 +103,12 @@ func (s *gatewayResource) gatewayHandler(w http.ResponseWriter, r *http.Request)
 }
 
 func (s *gatewayResource) legacyConfigHandler(w http.ResponseWriter, r *http.Request) {
-	if s.verbose {
-		log.Printf("%s Handling %s\n", r.Method, r.URL.Path)
-	}
+	slog.Debug("HTTP request", "method", r.Method, "path", r.URL.Path)
 	metrics := s.metricsFactory.Create(metricsEventConfigsRequest)
 
 	config, err := s.gateway.Config(s.legacyKeyID)
 	if err != nil {
-		log.Printf("Config unavailable")
+		slog.Warn("Config unavailable")
 		metrics.Fire(metricsResultConfigsUnavalable)
 		s.httpError(w, http.StatusInternalServerError, "Config unavailable", metrics, r.Method)
 		return
@@ -134,9 +125,7 @@ func (s *gatewayResource) legacyConfigHandler(w http.ResponseWriter, r *http.Req
 }
 
 func (s *gatewayResource) configHandler(w http.ResponseWriter, r *http.Request) {
-	if s.verbose {
-		log.Printf("%s Handling %s\n", r.Method, r.URL.Path)
-	}
+	slog.Debug("HTTP request", "method", r.Method, "path", r.URL.Path)
 	metrics := s.metricsFactory.Create(metricsEventConfigsRequest)
 
 	// Make expiration time even/random throughout interval 12-36h

gateway_test.go

@@ -108,10 +108,9 @@ func createMockEchoGatewayServer(t *testing.T) gatewayResource {
 		gateway: gateway,
 		appHandler: ProtoHTTPAppHandler{
 			httpHandler: FilteredHttpRequestHandler{
-				client:             MockHTTPRequestHandler{},
-				allowedOrigins:     allowedOrigins,
-				logForbiddenErrors: false,
-				targetRewrites:     nil,
+				client:         MockHTTPRequestHandler{},
+				allowedOrigins: allowedOrigins,
+				targetRewrites: nil,
 			},
 		},
 	}
@@ -124,10 +123,9 @@ func createMockEchoGatewayServer(t *testing.T) gatewayResource {
 		gateway: gateway,
 		appHandler: BinaryHTTPAppHandler{
 			httpHandler: FilteredHttpRequestHandler{
-				client:             MockHTTPRequestHandler{},
-				allowedOrigins:     nil,
-				logForbiddenErrors: false,
-				targetRewrites:     targetRewrites,
+				client:         MockHTTPRequestHandler{},
+				allowedOrigins: nil,
+				targetRewrites: targetRewrites,
 			},
 		},
 	}

handler.go

@@ -7,7 +7,7 @@ import (
 	"bytes"
 	"errors"
 	"io/ioutil"
-	"log"
+	"log/slog"
 	"net/http"
 	"net/http/httputil"
 	"strconv"
@@ -316,10 +316,9 @@ func (h HTTPClientRequestHandler) Handle(req *http.Request, metrics Metrics) (*h
 // FilteredHttpRequestHandler represents a HttpRequestHandler that restricts
 // outbound HTTP requests to an allowed set of targets.
 type FilteredHttpRequestHandler struct {
-	client             HTTPRequestHandler
-	allowedOrigins     map[string]bool
-	targetRewrites     map[string]TargetRewrite
-	logForbiddenErrors bool
+	client         HTTPRequestHandler
+	allowedOrigins map[string]bool
+	targetRewrites map[string]TargetRewrite
 }
 
 // Handle processes HTTP requests to targets that are permitted according to a list of
@@ -329,10 +328,8 @@ func (h FilteredHttpRequestHandler) Handle(req *http.Request, metrics Metrics) (
 		_, ok := h.allowedOrigins[req.Host]
 		if !ok {
 			metrics.Fire(metricsResultTargetRequestForbidden)
-			if h.logForbiddenErrors {
-				// to allow clients to fix improper third party urls usage (e.g. to change URLs from our direct s3 refs to CDN)
-				log.Printf("TargetForbiddenError: %s, %s", req.Host, req.URL)
-			}
+			// to allow clients to fix improper third party urls usage (e.g. to change URLs from our direct s3 refs to CDN)
+			slog.Debug("TargetForbiddenError", "host", req.Host, "URL", req.URL)
 			return nil, GatewayTargetForbiddenError
 		}
 	}

main.go

@@ -11,7 +11,7 @@ import (
 	"flag"
 	"fmt"
 	"io"
-	"log"
+	"log/slog"
 	"net/http"
 	"os"
 	"runtime/debug"
@@ -58,10 +58,15 @@ const (
 	statsdTimeoutVariable                    = "MONITORING_STATSD_TIMEOUT_MS"
 	monitoringServiceNameEnvironmentVariable = "MONITORING_SERVICE_NAME"
 	gatewayDebugEnvironmentVariable          = "GATEWAY_DEBUG"
-	gatewayVerboseEnvironmentVariable        = "VERBOSE"
 	logSecretsEnvironmentVariable            = "LOG_SECRETS"
+	logLevelEnvironmentVariable              = "LOG_LEVEL"
+	logFormatEnvironmentVariable             = "LOG_FORMAT"
 	targetRewritesVariables                  = "TARGET_REWRITES"
 	prometheusConfigVariable                 = "PROMETHEUS_CONFIG"
+
+	// Values for LOG_FORMAT environment variable
+	logFormatDefault = "default"
+	logFormatJSON    = "json"
 )
 
 var versionFlag = flag.Bool("version", false, "print name and version to stdout")
@@ -92,7 +97,7 @@ func (s gatewayServer) indexHandler(w http.ResponseWriter, r *http.Request) {
 }
 
 func (s gatewayServer) healthCheckHandler(w http.ResponseWriter, r *http.Request) {
-	log.Printf("%s Handling %s\n", r.Method, r.URL.Path)
+	slog.Debug("HTTP request", "method", r.Method, "path", r.URL.Path)
 	fmt.Fprint(w, "ok")
 }
 
@@ -133,13 +138,34 @@ func getStringEnv(key string, defaultVal string) string {
 func main() {
 	flag.Parse()
 
+	var logLevel slog.Level
+	if err := logLevel.UnmarshalText([]byte(getStringEnv(logLevelEnvironmentVariable, "info"))); err != nil {
+		slog.Error("invalid log level")
+		os.Exit(1)
+	}
+
+	handlerOptions := slog.HandlerOptions{Level: logLevel}
+	var handler slog.Handler
+
+	switch logFormat := getStringEnv(logFormatEnvironmentVariable, logFormatDefault); logFormat {
+	case logFormatDefault:
+		handler = slog.NewTextHandler(os.Stdout, &handlerOptions)
+	case logFormatJSON:
+		handler = slog.NewJSONHandler(os.Stdout, &handlerOptions)
+	default:
+		slog.Error("invalid log format", "format", logFormat)
+		os.Exit(1)
+	}
+
+	slog.SetDefault(slog.New(handler))
+
 	if *versionFlag {
 		buildInfo, ok := debug.ReadBuildInfo()
 		if !ok {
-			log.Printf("could not determine build info")
+			slog.Error("could not determine build info")
 			os.Exit(1)
 		}
-		fmt.Printf("%s\n%+v", os.Args[0], buildInfo)
+		slog.Info(os.Args[0], "buildInfo", buildInfo)
 		os.Exit(0)
 	}
 
@@ -153,9 +179,9 @@ func main() {
 	var seed []byte
 	if seedHex := os.Getenv(secretSeedEnvironmentVariable); seedHex != "" {
 		if logSecrets {
-			log.Printf("Using Secret Key Seed: [%v]", seedHex)
+			slog.Info("Using Secret Key Seed", "seed", seedHex)
 		} else {
-			log.Print("Using Secret Key Seed provided in environment variable")
+			slog.Info("Using Secret Key Seed provided in environment variable")
 		}
 		var err error
 		seed, err = hex.DecodeString(seedHex)
@@ -180,7 +206,8 @@ func main() {
 	var targetRewrites map[string]TargetRewrite
 	if targetRewritesJson := os.Getenv(targetRewritesVariables); targetRewritesJson != "" {
 		if err := json.Unmarshal([]byte(targetRewritesJson), &targetRewrites); err != nil {
-			log.Fatalf("Failed to parse target rewrites: %s", err)
+			slog.Error("Failed to parse target rewrites", "error", err)
+			os.Exit(1)
 		}
 	}
 
@@ -197,12 +224,12 @@ func main() {
 	}
 
 	debugResponse := getBoolEnv(gatewayDebugEnvironmentVariable, false)
-	verbose := getBoolEnv(gatewayVerboseEnvironmentVariable, false)
 
 	configID := uint8(getUintEnv(configurationIdEnvironmentVariable, 0))
 	config, err := ohttp.NewConfigFromSeed(configID, hpke.KEM_X25519_KYBER768_DRAFT00, hpke.KDF_HKDF_SHA256, hpke.AEAD_AES128GCM, seed)
 	if err != nil {
-		log.Fatalf("Failed to create gateway configuration from seed: %s", err)
+		slog.Error("Failed to create gateway configuration from seed", "error", err)
+		os.Exit(1)
 	}
 
 	// From the primary configuration ID, create a key ID for the legacy configuration that old
@@ -212,15 +239,15 @@ func main() {
 	seed[len(seed)-1] ^= 0xFF
 	legacyConfig, err := ohttp.NewConfigFromSeed(legacyConfigID, hpke.KEM_X25519_HKDF_SHA256, hpke.KDF_HKDF_SHA256, hpke.AEAD_AES128GCM, seed)
 	if err != nil {
-		log.Fatalf("Failed to create legacy gateway configuration from seed: %s", err)
+		slog.Error("Failed to create legacy gateway configuration from seed", "error", err)
+		os.Exit(1)
 	}
 
 	// Create the default HTTP handler
 	httpHandler := FilteredHttpRequestHandler{
-		client:             HTTPClientRequestHandler{client: &http.Client{}},
-		allowedOrigins:     allowedOrigins,
-		logForbiddenErrors: verbose,
-		targetRewrites:     targetRewrites,
+		client:         HTTPClientRequestHandler{client: &http.Client{}},
+		allowedOrigins: allowedOrigins,
+		targetRewrites: targetRewrites,
 	}
 
 	// Create the default gateway and its request handler chain
@@ -267,12 +294,14 @@ func main() {
 	if prometheusConfigJSON := os.Getenv(prometheusConfigVariable); prometheusConfigJSON != "" {
 		var prometheusConfig PrometheusConfig
 		if err := json.Unmarshal([]byte(prometheusConfigJSON), &prometheusConfig); err != nil {
-			log.Fatalf("Failed to parse Prometheus config: %s", err)
+			slog.Error("Failed to parse Prometheus config", "error", err)
+			os.Exit(1)
 		}
 
 		metricsFactory, err = NewPrometheusMetricsFactory(prometheusConfig)
 		if err != nil {
-			log.Fatalf("Failed to configure Prometheus metrics: %s", err)
+			slog.Error("Failed to configure Prometheus metrics", "error", err)
+			os.Exit(1)
 		}
 	} else {
 		// Default to StatsD metrics
@@ -281,11 +310,13 @@ func main() {
 		metricsPort := os.Getenv(statsdPortVariable)
 		metricsTimeout, err := strconv.ParseInt(getStringEnv(statsdTimeoutVariable, "100"), 10, 64)
 		if err != nil {
-			log.Fatalf("Failed parsing metrics timeout: %s", err)
+			slog.Error("Failed parsing metrics timeout", "error", err)
+			os.Exit(1)
 		}
 		client, err := createStatsDClient(metricsHost, metricsPort, int(metricsTimeout))
 		if err != nil {
-			log.Fatalf("Failed to create statsd client: %s", err)
+			slog.Error("Failed to create statsd client", "error", err)
+			os.Exit(1)
 		}
 		defer client.Close()
 
@@ -310,7 +341,6 @@ func main() {
 	handlers[echoEndpoint] = echoHandler         // Content-agnostic handler
 	handlers[metadataEndpoint] = metadataHandler // Metadata handler
 	target := &gatewayResource{
-		verbose:               verbose,
 		legacyKeyID:           legacyConfigID,
 		gateway:               gateway,
 		encapsulationHandlers: handlers,
@@ -343,13 +373,15 @@ func main() {
 
 	var b bytes.Buffer
 	server.formatConfiguration(io.Writer(&b))
-	log.Println(b.String())
+	slog.Debug(b.String())
 
 	if enableTLSServe {
-		log.Printf("Listening on port %v with cert %v and key %v\n", port, certFile, keyFile)
-		log.Fatal(http.ListenAndServeTLS(fmt.Sprintf(":%s", port), certFile, keyFile, nil))
+		slog.Debug("Listening", "cert", certFile, "key", "keyFile", "port", port)
+		slog.Error("error serving TLS", "error", http.ListenAndServeTLS(fmt.Sprintf(":%s", port), certFile, keyFile, nil))
+		os.Exit(1)
 	} else {
-		log.Printf("Listening on port %v without enabling TLS\n", port)
-		log.Fatal(http.ListenAndServe(fmt.Sprintf(":%s", port), nil))
+		slog.Debug("Listening without enabling TLS", "port", port)
+		slog.Error("error serving non-TLS", "error", http.ListenAndServe(fmt.Sprintf(":%s", port), nil))
+		os.Exit(1)
 	}
 }

prometheus_metrics.go

@@ -6,9 +6,10 @@ package main
 import (
 	"errors"
 	"fmt"
-	"log"
+	"log/slog"
 	"net"
 	"net/http"
+	"os"
 	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
@@ -63,8 +64,9 @@ func NewPrometheusMetricsFactory(config PrometheusConfig) (MetricsFactory, error
 	}
 
 	go func() {
-		log.Printf("Listening for Prometheus scrapes on %s:%s\n", config.Host, config.Port)
-		log.Fatal(server.ListenAndServe())
+		slog.Debug("Listening for Prometheus scrapes", "host", config.Host, "port", config.Port)
+		slog.Error("Error serving Prometheus scrapes", "error", server.ListenAndServe())
+		os.Exit(1)
 	}()
 
 	return &PrometheusMetricsFactory{metricName: config.MetricName}, nil

statsd_metrics.go

@@ -2,7 +2,7 @@ package main
 
 import (
 	"fmt"
-	"log"
+	"log/slog"
 	"net"
 	"time"
 
@@ -22,7 +22,7 @@ func (s *StatsDMetrics) Fire(result string) {
 
 	err := s.client.TimeInMilliseconds(s.metricsName, float64(time.Since(s.startedAt).Milliseconds()), tags, 1)
 	if err != nil {
-		log.Printf("Cannot send metrics to statsd: %s", err)
+		slog.Warn("Cannot send metrics to statsd", "error", err)
 	}
 }