✨ Add access logs to serve commands and auth_proxy log target

cmd/info/version.go

@@ -1,3 +1,3 @@
 package info
 
-var Version = "0.0.57"
+var Version = "0.0.58"

cmd/logs/logs.go

@@ -12,7 +12,7 @@ import (
 
 var validLogLevels = []string{"debug", "info", "warn", "error"}
 
-var validLogTargets = []string{"main", "metrics", "docker"}
+var validLogTargets = []string{"main", "metrics", "docker", "auth_proxy"}
 
 var LogsCmd = &cobra.Command{
 	Use:   "logs",
@@ -42,6 +42,7 @@ func execute(cmd *cobra.Command, args []string) error {
 			{"main", "Combined workspace log"},
 			{"metrics", "Metrics exporter log"},
 			{"docker", "In-container Docker daemon log"},
+			{"auth_proxy", "OIDC authentication proxy log"},
 		})
 		return fmt.Errorf("invalid log target")
 	}
@@ -70,5 +71,5 @@ func init() {
 	LogsCmd.Flags().BoolP("follow", "f", false, "Follow log output in real-time")
 	LogsCmd.Flags().IntP("tail", "t", 0, "Number of lines to show from the end (0 for all)")
 	LogsCmd.Flags().StringP("level", "l", "", "Filter by log level (debug|info|warn|error)")
-	LogsCmd.Flags().String("target", "main", "Log target to read (main|metrics|docker)")
+	LogsCmd.Flags().String("target", "main", "Log target to read (main|metrics|docker|auth_proxy)")
 }

cmd/logs/logs_test.go

@@ -36,9 +36,10 @@ func _seedLogs(t *testing.T) {
 	tempDir := t.TempDir()
 
 	files := map[string]string{
-		"workspace.log": "main marker",
-		"metrics.log":   "metrics marker",
-		"dockerd.log":   "docker marker",
+		"workspace.log":  "main marker",
+		"metrics.log":    "metrics marker",
+		"dockerd.log":    "docker marker",
+		"auth-proxy.log": "auth proxy marker",
 	}
 
 	for name, content := range files {
@@ -49,6 +50,7 @@ func _seedLogs(t *testing.T) {
 	t.Setenv("WS_LOGGING_MAIN_FILE", "workspace.log")
 	t.Setenv("WS_LOGGING_METRICS_FILE", "metrics.log")
 	t.Setenv("WS_LOGGING_DOCKER_FILE", "dockerd.log")
+	t.Setenv("WS_LOGGING_AUTH_PROXY_FILE", "auth-proxy.log")
 }
 
 func TestLogsDefaultTargetIsMain(t *testing.T) {
@@ -67,6 +69,7 @@ func TestLogsValidTargets(t *testing.T) {
 		{"main", "main marker"},
 		{"metrics", "metrics marker"},
 		{"docker", "docker marker"},
+		{"auth_proxy", "auth proxy marker"},
 	}
 
 	for _, tt := range tests {

cmd/serve/current.go

@@ -28,7 +28,7 @@ var currentCmd = &cobra.Command{
 			return fmt.Errorf("error getting current directory: %v", err)
 		}
 
-		return server.ServeDirectory(config, currentDir, "current directory")
+		return server.ServeDirectory(config, currentDir, "current directory", cmd.OutOrStdout())
 	},
 }
 

cmd/serve/font.go

@@ -22,7 +22,7 @@ var fontCmd = &cobra.Command{
 			Bind: bind,
 		}
 
-		return server.ServeDirectory(config, "/usr/share/fonts/", "fonts")
+		return server.ServeDirectory(config, "/usr/share/fonts/", "fonts", cmd.OutOrStdout())
 	},
 }
 

cmd/serve/metrics.go

@@ -2,9 +2,9 @@ package serve
 
 import (
 	"fmt"
-	"net/http"
 
 	"github.com/kloudkit/ws-cli/internals/metrics"
+	"github.com/kloudkit/ws-cli/internals/server"
 	"github.com/kloudkit/ws-cli/internals/styles"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"github.com/spf13/cobra"
@@ -38,13 +38,9 @@ var metricsCmd = &cobra.Command{
 		}
 		fmt.Fprintln(out)
 
-		addr := fmt.Sprintf(":%d", port)
-		http.Handle("/", promhttp.HandlerFor(result.Registry, promhttp.HandlerOpts{}))
+		handler := promhttp.HandlerFor(result.Registry, promhttp.HandlerOpts{})
 
-		styles.PrintSuccess(out, fmt.Sprintf("Serving metrics at http://0.0.0.0%s", addr))
-		fmt.Fprintln(out, styles.Info().Render("Press Ctrl+C to stop"))
-
-		return http.ListenAndServe(addr, nil)
+		return server.Serve(server.Config{Port: port, Bind: "0.0.0.0"}, handler, "metrics", out)
 	},
 }
 

internals/server/access_log.go

@@ -0,0 +1,52 @@
+package server
+
+import (
+	"fmt"
+	"io"
+	"net/http"
+	"time"
+
+	"github.com/kloudkit/ws-cli/internals/logger"
+)
+
+type responseRecorder struct {
+	http.ResponseWriter
+	status int
+	size   int
+}
+
+func (r *responseRecorder) WriteHeader(status int) {
+	r.status = status
+	r.ResponseWriter.WriteHeader(status)
+}
+
+func (r *responseRecorder) Write(b []byte) (int, error) {
+	n, err := r.ResponseWriter.Write(b)
+	r.size += n
+	return n, err
+}
+
+func accessLogMiddleware(next http.Handler, w io.Writer) http.Handler {
+	return http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
+		start := time.Now()
+		rec := &responseRecorder{ResponseWriter: rw, status: http.StatusOK}
+
+		next.ServeHTTP(rec, req)
+
+		logger.Log(
+			w,
+			"info",
+			fmt.Sprintf(
+				"%s %s %d %s %s %d",
+				req.Method,
+				req.URL.Path,
+				rec.status,
+				time.Since(start),
+				req.RemoteAddr,
+				rec.size,
+			),
+			0,
+			true,
+		)
+	})
+}

internals/server/access_log_test.go

@@ -0,0 +1,103 @@
+package server
+
+import (
+	"bytes"
+	"net/http"
+	"net/http/httptest"
+	"regexp"
+	"strings"
+	"testing"
+
+	"gotest.tools/v3/assert"
+	"gotest.tools/v3/assert/cmp"
+)
+
+func stripAnsi(s string) string {
+	return regexp.MustCompile(`\x1b\[[0-9;]*m`).ReplaceAllString(s, "")
+}
+
+func TestResponseRecorderStatusAndSize(t *testing.T) {
+	cases := []struct {
+		name       string
+		handler    http.HandlerFunc
+		wantStatus int
+		wantSize   int
+	}{
+		{
+			"defaults to 200 when WriteHeader not called",
+			func(w http.ResponseWriter, r *http.Request) { _, _ = w.Write([]byte("hello")) },
+			http.StatusOK,
+			5,
+		},
+		{
+			"captures explicit 404 with empty body",
+			func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusNotFound) },
+			http.StatusNotFound,
+			0,
+		},
+		{
+			"captures explicit 500 with empty body",
+			func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusInternalServerError) },
+			http.StatusInternalServerError,
+			0,
+		},
+		{
+			"captures size after explicit 200",
+			func(w http.ResponseWriter, r *http.Request) {
+				w.WriteHeader(http.StatusOK)
+				_, _ = w.Write([]byte("twelve bytes"))
+			},
+			http.StatusOK,
+			12,
+		},
+	}
+
+	for _, c := range cases {
+		t.Run(c.name, func(t *testing.T) {
+			rec := &responseRecorder{ResponseWriter: httptest.NewRecorder(), status: http.StatusOK}
+
+			c.handler(rec, httptest.NewRequest(http.MethodGet, "/", nil))
+
+			assert.Equal(t, c.wantStatus, rec.status)
+			assert.Equal(t, c.wantSize, rec.size)
+		})
+	}
+}
+
+func TestAccessLogMiddlewareLineFormat(t *testing.T) {
+	buffer := new(bytes.Buffer)
+
+	handler := accessLogMiddleware(
+		http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			_, _ = w.Write([]byte("ok"))
+		}),
+		buffer,
+	)
+
+	req := httptest.NewRequest(http.MethodGet, "/healthz", nil)
+	req.RemoteAddr = "10.0.0.5:53124"
+
+	handler.ServeHTTP(httptest.NewRecorder(), req)
+
+	line := strings.TrimRight(stripAnsi(buffer.String()), "\n")
+
+	assert.Assert(t, cmp.Regexp(`^\[.*?\]\s+(\w+)\s*(.*)$`, line))
+	assert.Assert(t, strings.Contains(line, "info"))
+	assert.Assert(t, strings.Contains(line, "GET"))
+	assert.Assert(t, strings.Contains(line, "/healthz"))
+	assert.Assert(t, strings.Contains(line, "200"))
+	assert.Assert(t, strings.Contains(line, "10.0.0.5:53124"))
+	assert.Assert(t, cmp.Regexp(`\d+(\.\d+)?(ns|µs|ms|s)`, line))
+}
+
+func TestAccessLogServesAndLogs(t *testing.T) {
+	buffer := new(bytes.Buffer)
+	rec := httptest.NewRecorder()
+
+	handler := accessLogMiddleware(http.FileServer(http.Dir("/tmp")), buffer)
+	handler.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/", nil))
+
+	assert.Equal(t, http.StatusOK, rec.Code)
+	assert.Assert(t, rec.Body.Len() > 0)
+	assert.Assert(t, strings.Contains(stripAnsi(buffer.String()), "GET /"))
+}

internals/server/server.go

@@ -2,6 +2,7 @@ package server
 
 import (
 	"fmt"
+	"io"
 	"net"
 	"net/http"
 	"strconv"
@@ -18,13 +19,15 @@ func formatAddr(c Config) string {
 	return net.JoinHostPort(c.Bind, strconv.Itoa(c.Port))
 }
 
-func ServeDirectory(config Config, directory string, description string) error {
+func Serve(config Config, handler http.Handler, description string, w io.Writer) error {
 	host := formatAddr(config)
 
-	handler := http.FileServer(http.Dir(directory))
+	fmt.Fprintln(w, styles.Success().Render(fmt.Sprintf("Serving %s at port %d", description, config.Port)))
+	fmt.Fprintln(w, styles.Info().Render("To stop serving, press Ctrl+C"))
 
-	fmt.Println(styles.Success().Render(fmt.Sprintf("Serving %s at port %d", description, config.Port)))
-	fmt.Println(styles.Info().Render("To stop serving, press Ctrl+C"))
+	return http.ListenAndServe(host, accessLogMiddleware(handler, w))
+}
 
-	return http.ListenAndServe(host, handler)
+func ServeDirectory(config Config, directory string, description string, w io.Writer) error {
+	return Serve(config, http.FileServer(http.Dir(directory)), description, w)
 }

internals/server/server_test.go

@@ -1,6 +1,7 @@
 package server
 
 import (
+	"io"
 	"net/http"
 	"net/http/httptest"
 	"strings"
@@ -62,7 +63,7 @@ func TestServeDirectory(t *testing.T) {
 
 		done := make(chan error, 1)
 		go func() {
-			err := ServeDirectory(config, "/nonexistent/directory", "test")
+			err := ServeDirectory(config, "/nonexistent/directory", "test", io.Discard)
 			done <- err
 		}()