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

@@ -4,9 +4,10 @@
 package main
 
 import (
+	"context"
 	"fmt"
 	"io/ioutil"
-	"log"
+	"log/slog"
 	"math/rand"
 	"net/http"
 	"time"
@@ -21,6 +22,7 @@ type gatewayResource struct {
 	encapsulationHandlers map[string]EncapsulationHandler
 	debugResponse         bool
 	metricsFactory        MetricsFactory
+	context               context.Context
 }
 
 const (
@@ -38,10 +40,18 @@ const (
 	metricsResultInvalidContent     = "invalid_content"
 )
 
-func (s *gatewayResource) httpError(w http.ResponseWriter, status int, debugMessage string, metrics Metrics, metricsPrefix string) {
+// verboseLogLevel returns the slog.Level at which verbose messages should be
+// logged.
+func (s *gatewayResource) verboseLogLevel() slog.Level {
 	if s.verbose {
-		log.Println(debugMessage)
+		return slog.LevelInfo
+	} else {
+		return slog.LevelDebug
 	}
+}
+
+func (s *gatewayResource) httpError(w http.ResponseWriter, status int, debugMessage string, metrics Metrics, metricsPrefix string) {
+	slog.Log(s.context, s.verboseLogLevel(), debugMessage)
 	if s.debugResponse {
 		http.Error(w, debugMessage, status)
 	} else {
@@ -51,9 +61,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.Log(s.context, s.verboseLogLevel(), "Handling", "method", r.Method, "path", r.URL.Path)
 
 	metrics := s.metricsFactory.Create(metricsEventGatewayRequest)
 
@@ -92,9 +100,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.Log(s.context, s.verboseLogLevel(), "encap handler error", "error", err)
 
 		errorCode := encapsulationErrorToGatewayStatusCode(err)
 		s.httpError(w, errorCode, http.StatusText(errorCode), metrics, r.Method)
@@ -110,14 +116,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.Log(s.context, s.verboseLogLevel(), "Handling", "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 +138,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.Log(s.context, s.verboseLogLevel(), "Handling", "method", r.Method, "path", r.URL.Path)
 	metrics := s.metricsFactory.Create(metricsEventConfigsRequest)
 
 	// Make expiration time even/random throughout interval 12-36h

handler.go

@@ -7,7 +7,7 @@ import (
 	"bytes"
 	"errors"
 	"io/ioutil"
-	"log"
+	"log/slog"
 	"net/http"
 	"net/http/httputil"
 	"strconv"
@@ -331,7 +331,7 @@ func (h FilteredHttpRequestHandler) Handle(req *http.Request, metrics Metrics) (
 			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)
+				slog.Warn("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"
@@ -60,8 +60,14 @@ const (
 	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 +98,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("Handling", "method", r.Method, "path", r.URL.Path)
 	fmt.Fprint(w, "ok")
 }
 
@@ -133,13 +139,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
+
+	logFormat := getStringEnv(logFormatEnvironmentVariable, logFormatDefault)
+	if logFormat == logFormatDefault {
+		handler = slog.NewTextHandler(os.Stdout, &handlerOptions)
+	} else if logFormat == logFormatJSON {
+		handler = slog.NewJSONHandler(os.Stdout, &handlerOptions)
+	} else {
+		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 +180,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 +207,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)
 		}
 	}
 
@@ -202,7 +230,8 @@ func main() {
 	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,7 +241,8 @@ 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
@@ -267,12 +297,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 +313,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()
 
@@ -343,13 +377,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)
 	}
 }