tsidp-server.go,server: switch to slog

Switch to slog for structured logging with appropriate log levels for
activity within the app.

- log all token api errors at WARN level
- move tsnet.Server logging to new flag: -debug-tsnet
- move request/response logging to new flag: -debug-all-requests
- unify API error handling logic to writeHTTPError
- switch funnel error to http.StatusUnauthorized

Updates #25

Signed-off-by: Benson Wong <[email protected]>

Author: mostlygeek

server/appcap.go

@@ -91,13 +91,13 @@ func (s *IDPServer) addGrantAccessContext(handler http.HandlerFunc) http.Handler
 
 		who, err = s.lc.WhoIs(r.Context(), remoteAddr)
 		if err != nil {
-			http.Error(w, fmt.Sprintf("Error getting WhoIs: %v", err), http.StatusInternalServerError)
+			writeHTTPError(w, r, http.StatusInternalServerError, "server_error", fmt.Sprintf("Error getting WhoIs: %v", err))
 			return
 		}
 
 		rules, err := tailcfg.UnmarshalCapJSON[capRule](who.CapMap, "tailscale.com/cap/tsidp")
 		if err != nil {
-			http.Error(w, fmt.Sprintf("failed unmarshaling app cap rule %s", err.Error()), http.StatusInternalServerError)
+			writeHTTPError(w, r, http.StatusInternalServerError, "server_error", fmt.Sprintf("failed unmarshaling app cap rule %s", err.Error()))
 			return
 		}
 		accessRules.rules = rules

server/authorize.go

@@ -6,7 +6,7 @@ package server
 import (
 	"crypto/subtle"
 	"fmt"
-	"log"
+	"log/slog"
 	"net/http"
 	"net/url"
 	"slices"
@@ -22,9 +22,8 @@ func (s *IDPServer) serveAuthorize(w http.ResponseWriter, r *http.Request) {
 	// This URL is visited by the user who is being authenticated. If they are
 	// visiting the URL over Funnel, that means they are not part of the
 	// tailnet that they are trying to be authenticated for.
-	// NOTE: Funnel request behavior is the same regardless of secure or insecure mode.
 	if isFunnelRequest(r) {
-		http.Error(w, "tsidp: unauthorized", http.StatusUnauthorized)
+		writeHTTPError(w, r, http.StatusUnauthorized, "access_denied", "not allowed over funnel")
 		return
 	}
 
@@ -33,13 +32,13 @@ func (s *IDPServer) serveAuthorize(w http.ResponseWriter, r *http.Request) {
 
 	redirectURI := uq.Get("redirect_uri")
 	if redirectURI == "" {
-		http.Error(w, "tsidp: must specify redirect_uri", http.StatusBadRequest)
+		writeHTTPError(w, r, http.StatusBadRequest, "invalid_request", "tsidp: must specify redirect_uri")
 		return
 	}
 
 	clientID := uq.Get("client_id")
 	if clientID == "" {
-		http.Error(w, "tsidp: must specify client_id", http.StatusBadRequest)
+		writeHTTPError(w, r, http.StatusBadRequest, "invalid_request", "tsidp: must specify client_id")
 		return
 	}
 
@@ -48,20 +47,20 @@ func (s *IDPServer) serveAuthorize(w http.ResponseWriter, r *http.Request) {
 	s.mu.Unlock()
 
 	if !ok {
-		http.Error(w, "tsidp: invalid client ID", http.StatusBadRequest)
+		writeHTTPError(w, r, http.StatusBadRequest, "invalid_client", "tsidp: invalid client ID")
 		return
 	}
 
 	// Validate client_id matches (public identifier validation)
 	clientIDcmp := subtle.ConstantTimeCompare([]byte(clientID), []byte(funnelClient.ID))
 	if clientIDcmp != 1 {
-		http.Error(w, "tsidp: invalid client ID", http.StatusBadRequest)
+		writeHTTPError(w, r, http.StatusBadRequest, "invalid_client", "tsidp: invalid client ID")
 		return
 	}
 
 	// check for exact match of redirect_uri (OAuth 2.1 requirement)
 	if !slices.Contains(funnelClient.RedirectURIs, redirectURI) {
-		http.Error(w, "tsidp: redirect_uri mismatch", http.StatusBadRequest)
+		writeHTTPError(w, r, http.StatusBadRequest, "invalid_request", "tsidp: redirect_uri mismatch")
 		return
 	}
 
@@ -78,8 +77,8 @@ func (s *IDPServer) serveAuthorize(w http.ResponseWriter, r *http.Request) {
 	var err error
 	who, err = s.lc.WhoIs(r.Context(), remoteAddr)
 	if err != nil {
-		log.Printf("Error getting WhoIs: %v", err)
-		http.Error(w, err.Error(), http.StatusInternalServerError)
+		slog.Error("Error getting WhoIs", slog.Any("error", err))
+		writeHTTPError(w, r, http.StatusInternalServerError, "server_error", err.Error())
 		return
 	}
 
@@ -134,13 +133,12 @@ func (s *IDPServer) serveAuthorize(w http.ResponseWriter, r *http.Request) {
 	}
 	parsedURL, err := url.Parse(redirectURI)
 	if err != nil {
-		http.Error(w, "invalid redirect URI", http.StatusInternalServerError)
+		writeHTTPError(w, r, http.StatusInternalServerError, "server_error", "invalid redirect URI")
 		return
 	}
 	parsedURL.RawQuery = queryString.Encode()
 	u := parsedURL.String()
-	log.Printf("Redirecting to %q", u)
-
+	slog.Debug("authorize redirect", slog.String("url", u))
 	http.Redirect(w, r, u, http.StatusFound)
 }
 
@@ -178,7 +176,8 @@ func redirectAuthError(w http.ResponseWriter, r *http.Request, redirectURI, erro
 	u, err := url.Parse(redirectURI)
 	if err != nil {
 		// If redirect URI is invalid, return error directly
-		http.Error(w, "invalid redirect_uri", http.StatusBadRequest)
+		slog.Warn("Invalid redirect_uri", slog.String("error", err.Error()))
+		writeHTTPError(w, r, http.StatusBadRequest, "invalid_request", "invalid redirect_uri")
 		return
 	}
 
@@ -192,5 +191,10 @@ func redirectAuthError(w http.ResponseWriter, r *http.Request, redirectURI, erro
 	}
 	u.RawQuery = q.Encode()
 
+	slog.Info("Redirecting to client with error",
+		slog.String("error_code", errorCode),
+		slog.String("state", state),
+		slog.String("redirect_uri", u.String()),
+	)
 	http.Redirect(w, r, u.String(), http.StatusFound)
 }

server/client_test.go

@@ -249,7 +249,7 @@ func TestServeDynamicClientRegistration(t *testing.T) {
 			method:       "POST",
 			body:         `{"redirect_uris": ["https://example.com/callback"]}`,
 			isFunnel:     true,
-			expectStatus: http.StatusForbidden,
+			expectStatus: http.StatusUnauthorized,
 			checkResponse: func(t *testing.T, body []byte) {
 				var errResp map[string]interface{}
 				if err := json.Unmarshal(body, &errResp); err != nil {

server/clients.go

@@ -7,7 +7,7 @@ import (
 	"bytes"
 	"encoding/json"
 	"fmt"
-	"log"
+	"log/slog"
 	"net/http"
 	"os"
 	"path/filepath"
@@ -89,7 +89,7 @@ func (s *IDPServer) LoadFunnelClients() error {
 		}
 	}
 	if migrationPerformed {
-		log.Println("Migrated old funnel clients with single redirect_uri to redirect_uris field.")
+		slog.Info("Migrated old funnel clients with single redirect_uri to redirect_uris field.")
 		if err := s.storeFunnelClientsLocked(); err != nil {
 			return fmt.Errorf("failed to store migrated clients: %w", err)
 		}
@@ -122,7 +122,7 @@ func (s *IDPServer) storeFunnelClientsLocked() error {
 // Migrated from legacy/tsidp.go:2055-2094
 func (s *IDPServer) serveClients(w http.ResponseWriter, r *http.Request) {
 	if isFunnelRequest(r) {
-		http.Error(w, "tsidp: not found", http.StatusNotFound)
+		writeHTTPError(w, r, http.StatusUnauthorized, "access_denied", "not available over funnel")
 		return
 	}
 
@@ -142,7 +142,7 @@ func (s *IDPServer) serveClients(w http.ResponseWriter, r *http.Request) {
 	s.mu.Unlock()
 
 	if !ok {
-		http.Error(w, "tsidp: client not found", http.StatusNotFound)
+		writeHTTPError(w, r, http.StatusNotFound, "not_found", "tsidp: client not found")
 		return
 	}
 
@@ -157,21 +157,21 @@ func (s *IDPServer) serveClients(w http.ResponseWriter, r *http.Request) {
 			RedirectURIs: c.RedirectURIs,
 		})
 	default:
-		http.Error(w, "tsidp: method not allowed", http.StatusMethodNotAllowed)
+		writeHTTPError(w, r, http.StatusMethodNotAllowed, "invalid_request", "tsidp: method not allowed")
 	}
 }
 
 // serveNewClient creates a new OAuth client
 // Migrated from legacy/tsidp.go:2096-2126
 func (s *IDPServer) serveNewClient(w http.ResponseWriter, r *http.Request) {
 	if r.Method != "POST" {
-		http.Error(w, "tsidp: method not allowed", http.StatusMethodNotAllowed)
+		writeHTTPError(w, r, http.StatusMethodNotAllowed, "invalid_request", "tsidp: method not allowed")
 		return
 	}
 	redirectURI := r.FormValue("redirect_uri")
 	name := r.FormValue("name")
 	if redirectURI == "" || name == "" {
-		http.Error(w, "tsidp: missing redirect_uri or name", http.StatusBadRequest)
+		writeHTTPError(w, r, http.StatusBadRequest, "invalid_request", "tsidp: missing redirect_uri or name")
 		return
 	}
 
@@ -196,7 +196,7 @@ func (s *IDPServer) serveNewClient(w http.ResponseWriter, r *http.Request) {
 	s.funnelClients[clientID] = client
 
 	if err := s.storeFunnelClientsLocked(); err != nil {
-		http.Error(w, fmt.Sprintf("tsidp: failed to store client: %v", err), http.StatusInternalServerError)
+		writeHTTPError(w, r, http.StatusInternalServerError, "server_error", fmt.Sprintf("tsidp: failed to store client: %v", err))
 		return
 	}
 
@@ -207,7 +207,7 @@ func (s *IDPServer) serveNewClient(w http.ResponseWriter, r *http.Request) {
 // Migrated from legacy/tsidp.go:2128-2145
 func (s *IDPServer) serveGetClientsList(w http.ResponseWriter, r *http.Request) {
 	if r.Method != "GET" {
-		http.Error(w, "tsidp: method not allowed", http.StatusMethodNotAllowed)
+		writeHTTPError(w, r, http.StatusMethodNotAllowed, "invalid_request", "tsidp: method not allowed")
 		return
 	}
 	s.mu.Lock()
@@ -231,14 +231,14 @@ func (s *IDPServer) serveGetClientsList(w http.ResponseWriter, r *http.Request)
 // Migrated from legacy/tsidp.go:2239-2265
 func (s *IDPServer) serveDeleteClient(w http.ResponseWriter, r *http.Request, clientID string) {
 	if r.Method != "DELETE" {
-		http.Error(w, "tsidp: method not allowed", http.StatusMethodNotAllowed)
+		writeHTTPError(w, r, http.StatusMethodNotAllowed, "invalid_request", "tsidp: method not allowed")
 		return
 	}
 	s.mu.Lock()
 	defer s.mu.Unlock()
 
 	if _, ok := s.funnelClients[clientID]; !ok {
-		http.Error(w, "tsidp: client not found", http.StatusNotFound)
+		writeHTTPError(w, r, http.StatusNotFound, "not_found", "tsidp: client not found")
 		return
 	}
 
@@ -262,7 +262,7 @@ func (s *IDPServer) serveDeleteClient(w http.ResponseWriter, r *http.Request, cl
 	}
 
 	if err := s.storeFunnelClientsLocked(); err != nil {
-		http.Error(w, fmt.Sprintf("tsidp: failed to store clients: %v", err), http.StatusInternalServerError)
+		writeHTTPError(w, r, http.StatusInternalServerError, "server_error", fmt.Sprintf("tsidp: failed to store clients: %v", err))
 		return
 	}
 
@@ -274,9 +274,10 @@ func (s *IDPServer) serveDeleteClient(w http.ResponseWriter, r *http.Request, cl
 func (s *IDPServer) serveDynamicClientRegistration(w http.ResponseWriter, r *http.Request) {
 	// Block funnel requests - dynamic registration is only available over tailnet
 	if isFunnelRequest(r) {
-		writeJSONError(w, http.StatusForbidden, "access_denied", "dynamic client registration not available over funnel")
+		writeHTTPError(w, r, http.StatusUnauthorized, "access_denied", "not available over funnel")
 		return
 	}
+
 	h := w.Header()
 	h.Set("Access-Control-Allow-Origin", "*")
 	h.Set("Access-Control-Allow-Method", "POST, OPTIONS")
@@ -288,18 +289,18 @@ func (s *IDPServer) serveDynamicClientRegistration(w http.ResponseWriter, r *htt
 	}
 
 	if r.Method != "POST" {
-		writeJSONError(w, http.StatusMethodNotAllowed, "invalid_request", "method not allowed")
+		writeHTTPError(w, r, http.StatusMethodNotAllowed, "invalid_request", "method not allowed")
 		return
 	}
 
 	access, ok := r.Context().Value(appCapCtxKey).(*accessGrantedRules)
 	if !ok {
-		writeJSONError(w, http.StatusForbidden, "access_denied", "application capability not found")
+		writeHTTPError(w, r, http.StatusForbidden, "access_denied", "application capability not found")
 		return
 	}
 
 	if !access.allowDCR {
-		writeJSONError(w, http.StatusForbidden, "access_denied", "application capability not granted")
+		writeHTTPError(w, r, http.StatusForbidden, "access_denied", "application capability not granted")
 		return
 	}
 
@@ -317,13 +318,13 @@ func (s *IDPServer) serveDynamicClientRegistration(w http.ResponseWriter, r *htt
 	}
 
 	if err := json.NewDecoder(r.Body).Decode(&registrationRequest); err != nil {
-		writeJSONError(w, http.StatusBadRequest, "invalid_request", "invalid request body")
+		writeHTTPError(w, r, http.StatusBadRequest, "invalid_request", "invalid request body")
 		return
 	}
 
 	// Validate required fields
 	if len(registrationRequest.RedirectURIs) == 0 {
-		writeJSONError(w, http.StatusBadRequest, "invalid_client_metadata", "redirect_uris is required")
+		writeHTTPError(w, r, http.StatusBadRequest, "invalid_client_metadata", "redirect_uris is required")
 		return
 	}
 
@@ -371,7 +372,7 @@ func (s *IDPServer) serveDynamicClientRegistration(w http.ResponseWriter, r *htt
 	s.funnelClients[clientID] = client
 
 	if err := s.storeFunnelClientsLocked(); err != nil {
-		writeJSONError(w, http.StatusInternalServerError, "server_error", "failed to store client")
+		writeHTTPError(w, r, http.StatusInternalServerError, "server_error", "failed to store client")
 		return
 	}
 

server/extraclaims.go

@@ -5,7 +5,7 @@ package server
 
 import (
 	"fmt"
-	"log"
+	"log/slog"
 )
 
 // withExtraClaims merges flattened extra claims from a list of capRule into the provided map[string]any,
@@ -27,7 +27,7 @@ func withExtraClaims(claimMap map[string]any, rules []capRule) (map[string]any,
 	extra := flattenExtraClaims(rules)
 	for k, v := range extra {
 		if _, isProtected := protected[k]; isProtected {
-			log.Printf("Skip overwriting of existing claim %q", k)
+			slog.Info("Skip overwriting of existing claim", slog.String("claim", k))
 			return nil, fmt.Errorf("extra claim %q overwriting existing claim", k)
 		}