From 01e8b0ba443ea1957ba03b3f692f12b921ea9d20 Mon Sep 17 00:00:00 2001 From: mrhid6 Date: Fri, 31 Jul 2026 16:31:19 +0100 Subject: [PATCH] feat: Better debugging for console --- server/internal/api/console.go | 68 +++++++++++++++++++++++++++++++--- 1 file changed, 62 insertions(+), 6 deletions(-) diff --git a/server/internal/api/console.go b/server/internal/api/console.go index a14be12..07c964a 100644 --- a/server/internal/api/console.go +++ b/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") }