feat: Better debugging for console

server/internal/api/console.go

@@ -88,75 +88,109 @@ func queryIntDefault(r *http.Request, key string, def int) int {
 	return v
 }
 
+// consoleTunnel upgrades the browser's WebSocket and joins it to guacd.
+//
+// Every branch here logs. That is deliberate and worth keeping: this handler
+// spans four hops (session store, agent dispatch, relay announcement, guacd),
+// any of which can fail, and the client is told the same near-useless thing by
+// most of them — a 500 that guacamole then reports as an *upstream* error,
+// naming the wrong hop entirely. Without a line per branch the only evidence a
+// failure leaves is a GIN status code, and with several replicas you cannot
+// even tell which process produced it.
+//
+// Lines are prefixed with the session ID so one attempt can be followed across
+// pods, and the pod's own hostname so it is obvious which one served it.
 func consoleTunnel(c *gin.Context) {
+	host, _ := os.Hostname()
+
 	token := c.Query("token")
 	sessionID, err := services.VerifySessionToken(token)
 	if err != nil {
+		log.Printf("console[%s]: reject: invalid session token: %v", host, err)
 		c.JSON(http.StatusUnauthorized, gin.H{"error": "invalid token"})
 		return
 	}
+
+	// Bound to the session from here on, so every later line correlates.
+	tlog := func(format string, args ...any) {
+		log.Printf("console[%s %s]: "+format, append([]any{host, sessionID}, args...)...)
+	}
+	tlog("tunnel opened by %s", actorFromCtx(c))
+
 	instanceID := auth.InstanceID(c)
 	sess, err := services.GetConsoleSession(instanceID, sessionID)
 	if err != nil {
+		tlog("reject: console session not found: %v", err)
 		c.JSON(http.StatusNotFound, gin.H{"error": "session not found"})
 		return
 	}
 
 	if actor := actorFromCtx(c); actor != sess.User {
+		tlog("reject: session belongs to %s, not %s", sess.User, actor)
 		c.JSON(http.StatusForbidden, gin.H{"error": "session belongs to another user"})
 		return
 	}
 
 	if err := services.ConsumeSessionToken(instanceID, sessionID); err != nil {
+		tlog("reject: token already consumed: %v", err)
 		c.JSON(http.StatusUnauthorized, gin.H{"error": "token already used"})
 		return
 	}
 
 	srv, err := services.GetServer(auth.InstanceID(c), sess.ServerID)
 	if err != nil {
+		tlog("reject: server %s not found: %v", sess.ServerID, err)
 		c.JSON(http.StatusNotFound, gin.H{"error": "server not found"})
 		return
 	}
+	tlog("server %s (%s), protocol %s", srv.ServerID, srv.Hostname, sess.Protocol)
 
 	var privKey, passphrase string
 	if sess.Protocol == "ssh" && sess.KeyID != "" {
 		privKey, err = services.GetPrivateKey(auth.InstanceID(c), sess.KeyID)
 		if err != nil {
+			tlog("reject: key %s has no private material: %v", sess.KeyID, err)
 			c.JSON(http.StatusBadRequest, gin.H{"error": "selected key has no private material"})
 			return
 		}
 		passphrase, _ = services.GetPassphrase(sess.KeyID)
+		tlog("ssh key %s loaded (passphrase=%t)", sess.KeyID, passphrase != "")
 	}
 
 	var rdpUser, rdpPass string
 	if sess.Protocol == "rdp" || sess.Protocol == "vnc" {
 		rdpUser, rdpPass, err = services.ConsumeConsoleRDPCreds(instanceID, sessionID)
 		if err != nil {
+			tlog("reject: could not consume %s credentials: %v", sess.Protocol, err)
 			c.JSON(http.StatusInternalServerError, gin.H{"error": "could not load credentials"})
 			return
 		}
+		tlog("%s credentials consumed (user=%t)", sess.Protocol, rdpUser != "")
 	}
+
 	targetPort, err := services.TargetPort(srv, sess.Protocol)
 	if err != nil {
+		tlog("reject: no target port for %s: %v", sess.Protocol, err)
 		c.JSON(http.StatusBadRequest, gin.H{"error": err.Error()})
 		return
 	}
+	tlog("opening relay to %s:%d", srv.ServerID, targetPort)
 
 	relay, err := services.OpenConsoleProxy(instanceID, srv.ServerID, targetPort)
 	if err != nil {
 		if errors.Is(err, services.ErrAgentOffline) {
+			tlog("reject: agent offline")
 			c.JSON(http.StatusConflict, gin.H{"error": "agent_offline"})
 			return
 		}
-		// Logged as well as answered. The client is deliberately told nothing
-		// specific, but this is the only place the real reason exists — a
-		// failed dispatch and a relay that was never announced are the same
-		// generic 500 to the browser, and guacamole then reports the missing
-		// upgrade as an upstream error, which points at the wrong hop entirely.
-		log.Printf("console: open relay for server %s: %v", srv.ServerID, err)
+		// The client is deliberately told nothing specific, so this is the only
+		// place the real reason exists — a failed dispatch and a relay that was
+		// never announced are the same generic 500 to the browser.
+		tlog("reject: open relay: %v", err)
 		c.JSON(http.StatusInternalServerError, gin.H{"error": "could not open relay"})
 		return
 	}
+	tlog("relay %s ready at %s:%d", relay.ProxyID, relay.Host, relay.Port)
 	// guac.WebsocketServer.ServeHTTP returns before installing its
 	// OnDisconnect handler when the connect callback errors, which is exactly
 	// the path every relay failure this proxy introduces takes (the agent
@@ -168,10 +202,14 @@ func consoleTunnel(c *gin.Context) {
 	defer func() {
 		relay.Close()
 		if reason := relay.Reason(); reason != "" {
+			tlog("relay %s ended: %s", relay.ProxyID, reason)
 			services.LogEvent(instanceID, "console.proxy_failed", actorFromCtx(c), srv.ServerID, "",
 				fmt.Sprintf("console relay failed: %s (proxy_id=%s, port=%d)", reason, relay.ProxyID, relay.Port))
+		} else {
+			tlog("relay %s closed cleanly", relay.ProxyID)
 		}
 		_ = services.EndConsoleSession(instanceID, sessionID)
+		tlog("tunnel finished")
 	}()
 
 	services.LogEvent(instanceID, "console.proxy_opened", actorFromCtx(c), srv.ServerID, "",
@@ -180,6 +218,7 @@ func consoleTunnel(c *gin.Context) {
 	gp, err := services.BuildGuacParams(sess.Protocol, sess.SSHUsername, privKey, passphrase,
 		rdpUser, rdpPass, relay.Host, relay.Port)
 	if err != nil {
+		tlog("reject: build guacd parameters: %v", err)
 		c.JSON(http.StatusBadRequest, gin.H{"error": err.Error()})
 		return
 	}
@@ -199,18 +238,33 @@ func consoleTunnel(c *gin.Context) {
 		config.OptimalScreenHeight = queryIntDefault(r, "height", 768)
 		config.OptimalResolution = queryIntDefault(r, "dpi", 96)
 
+		// Resolution is logged separately from the dial: a headless guacd
+		// Service returns pod addresses, and which one was picked is the
+		// difference between "guacd refused" and "we called the wrong guacd".
 		addr, err := net.ResolveTCPAddr("tcp", guacdAddr)
 		if err != nil {
+			tlog("guacd: resolve %s: %v", guacdAddr, err)
 			return nil, err
 		}
+		tlog("guacd: dialling %s (%s)", guacdAddr, addr.String())
+
 		conn, err := net.DialTCP("tcp", nil, addr)
 		if err != nil {
+			tlog("guacd: dial %s: %v", addr.String(), err)
 			return nil, err
 		}
+
+		// The handshake is where guacd connects onward to the relay, so a
+		// failure here is guacd reporting it could not reach %s:%d — the hop
+		// that has been hardest to see from either end.
 		stream := guac.NewStream(conn, guac.SocketTimeout)
 		if err := stream.Handshake(config); err != nil {
+			tlog("guacd: handshake for %s to relay %s:%d: %v",
+				gp.Protocol, relay.Host, relay.Port, err)
 			return nil, err
 		}
+		tlog("guacd: tunnel established (%s %dx%d)",
+			gp.Protocol, config.OptimalScreenWidth, config.OptimalScreenHeight)
 		return guac.NewSimpleTunnel(stream), nil
 	}
 
@@ -218,5 +272,7 @@ func consoleTunnel(c *gin.Context) {
 	// func above, not here: this only fires once a tunnel was actually
 	// established, and letting both paths log would double the audit event.
 	wsServer := guac.NewWebsocketServer(connect)
+	tlog("serving websocket")
 	wsServer.ServeHTTP(c.Writer, c.Request)
+	tlog("websocket returned")
 }