From 591d512b11f6f7f0c432ec551f4ce3e0aa25d9ba Mon Sep 17 00:00:00 2001 From: Aveline <352441+ym@users.noreply.github.com> Date: Tue, 18 Feb 2025 17:22:03 +0100 Subject: [PATCH] add extra logging and tune timeout settings for cloud (#167) * chore(config): merge userConfig with defaultConfig and add a lock * chore(cloud): add extra logging and tune timeout settings --- cloud.go | 63 ++++++++++++++++++++++++++++++++++++++------------- config.go | 3 +++ dev_deploy.sh | 6 +++-- log.go | 1 + 4 files changed, 55 insertions(+), 18 deletions(-) diff --git a/cloud.go b/cloud.go index 3520e2f..fc41a36 100644 --- a/cloud.go +++ b/cloud.go @@ -24,6 +24,18 @@ type CloudRegisterRequest struct { ClientId string `json:"clientId"` } +const ( + // CloudWebSocketConnectTimeout is the timeout for the websocket connection to the cloud + CloudWebSocketConnectTimeout = 1 * time.Minute + // CloudAPIRequestTimeout is the timeout for cloud API requests + CloudAPIRequestTimeout = 10 * time.Second + // CloudOidcRequestTimeout is the timeout for OIDC token verification requests + // should be lower than the websocket response timeout set in cloud-api + CloudOidcRequestTimeout = 10 * time.Second + // CloudWebSocketPingInterval is the interval at which the websocket client sends ping messages to the cloud + CloudWebSocketPingInterval = 15 * time.Second +) + func handleCloudRegister(c *gin.Context) { var req CloudRegisterRequest @@ -44,22 +56,31 @@ func handleCloudRegister(c *gin.Context) { return } - resp, err := http.Post(req.CloudAPI+"/devices/token", "application/json", bytes.NewBuffer(jsonPayload)) + client := &http.Client{Timeout: CloudAPIRequestTimeout} + + apiReq, err := http.NewRequest(http.MethodPost, config.CloudURL+"/devices/token", bytes.NewBuffer(jsonPayload)) + if err != nil { + c.JSON(500, gin.H{"error": "Failed to create register request: " + err.Error()}) + return + } + apiReq.Header.Set("Content-Type", "application/json") + + apiResp, err := client.Do(apiReq) if err != nil { c.JSON(500, gin.H{"error": "Failed to exchange token: " + err.Error()}) return } - defer resp.Body.Close() + defer apiResp.Body.Close() - if resp.StatusCode != http.StatusOK { - c.JSON(resp.StatusCode, gin.H{"error": "Failed to exchange token: " + resp.Status}) + if apiResp.StatusCode != http.StatusOK { + c.JSON(apiResp.StatusCode, gin.H{"error": "Failed to exchange token: " + apiResp.Status}) return } var tokenResp struct { SecretToken string `json:"secretToken"` } - if err := json.NewDecoder(resp.Body).Decode(&tokenResp); err != nil { + if err := json.NewDecoder(apiResp.Body).Decode(&tokenResp); err != nil { c.JSON(500, gin.H{"error": "Failed to parse token response: " + err.Error()}) return } @@ -70,7 +91,7 @@ func handleCloudRegister(c *gin.Context) { } if config.CloudToken == "" { - logger.Info("Starting websocket client due to adoption") + cloudLogger.Info("Starting websocket client due to adoption") go RunWebsocketClient() } @@ -122,7 +143,7 @@ func runWebsocketClient() error { header := http.Header{} header.Set("X-Device-ID", GetDeviceID()) header.Set("Authorization", "Bearer "+config.CloudToken) - dialCtx, cancelDial := context.WithTimeout(context.Background(), time.Minute) + dialCtx, cancelDial := context.WithTimeout(context.Background(), CloudWebSocketConnectTimeout) defer cancelDial() c, _, err := websocket.Dial(dialCtx, wsURL.String(), &websocket.DialOptions{ HTTPHeader: header, @@ -131,15 +152,15 @@ func runWebsocketClient() error { return err } defer c.CloseNow() - logger.Infof("WS connected to %v", wsURL.String()) + cloudLogger.Infof("websocket connected to %s", wsURL.String()) runCtx, cancelRun := context.WithCancel(context.Background()) defer cancelRun() go func() { for { - time.Sleep(15 * time.Second) + time.Sleep(CloudWebSocketPingInterval) err := c.Ping(runCtx) if err != nil { - logger.Warnf("websocket ping error: %v", err) + cloudLogger.Warnf("websocket ping error: %v", err) cancelRun() return } @@ -157,24 +178,30 @@ func runWebsocketClient() error { var req WebRTCSessionRequest err = json.Unmarshal(msg, &req) if err != nil { - logger.Warnf("unable to parse ws message: %v", string(msg)) + cloudLogger.Warnf("unable to parse ws message: %v", string(msg)) continue } + cloudLogger.Infof("new session request: %v", req.OidcGoogle) + cloudLogger.Tracef("session request info: %v", req) + err = handleSessionRequest(runCtx, c, req) if err != nil { - logger.Infof("error starting new session: %v", err) + cloudLogger.Infof("error starting new session: %v", err) continue } } } func handleSessionRequest(ctx context.Context, c *websocket.Conn, req WebRTCSessionRequest) error { - oidcCtx, cancelOIDC := context.WithTimeout(ctx, time.Minute) + oidcCtx, cancelOIDC := context.WithTimeout(ctx, CloudOidcRequestTimeout) defer cancelOIDC() provider, err := oidc.NewProvider(oidcCtx, "https://accounts.google.com") if err != nil { - fmt.Println("Failed to initialize OIDC provider:", err) + _ = wsjson.Write(context.Background(), c, gin.H{ + "error": fmt.Sprintf("failed to initialize OIDC provider: %v", err), + }) + cloudLogger.Errorf("failed to initialize OIDC provider: %v", err) return err } @@ -190,6 +217,7 @@ func handleSessionRequest(ctx context.Context, c *websocket.Conn, req WebRTCSess googleIdentity := idToken.Audience[0] + ":" + idToken.Subject if config.GoogleIdentity != googleIdentity { + _ = wsjson.Write(context.Background(), c, gin.H{"error": "google identity mismatch"}) return fmt.Errorf("google identity mismatch") } @@ -216,6 +244,9 @@ func handleSessionRequest(ctx context.Context, c *websocket.Conn, req WebRTCSess _ = peerConn.Close() }() } + + cloudLogger.Info("new session accepted") + cloudLogger.Tracef("new session accepted: %v", session) currentSession = session _ = wsjson.Write(context.Background(), c, gin.H{"sd": sd}) return nil @@ -225,7 +256,7 @@ func RunWebsocketClient() { for { err := runWebsocketClient() if err != nil { - fmt.Println("Websocket client error:", err) + cloudLogger.Errorf("websocket client error: %v", err) time.Sleep(5 * time.Second) } } @@ -254,7 +285,7 @@ func rpcDeregisterDevice() error { } req.Header.Set("Authorization", "Bearer "+config.CloudToken) - client := &http.Client{Timeout: 10 * time.Second} + client := &http.Client{Timeout: CloudAPIRequestTimeout} resp, err := client.Do(req) if err != nil { return fmt.Errorf("failed to send deregister request: %w", err) diff --git a/config.go b/config.go index 3818b7b..d7c96e0 100644 --- a/config.go +++ b/config.go @@ -47,6 +47,9 @@ var ( ) func LoadConfig() { + configLock.Lock() + defer configLock.Unlock() + if config != nil { logger.Info("config already loaded, skipping") return diff --git a/dev_deploy.sh b/dev_deploy.sh index a106395..c5a389e 100755 --- a/dev_deploy.sh +++ b/dev_deploy.sh @@ -58,6 +58,9 @@ make build_dev # Change directory to the binary output directory cd bin +# Kill any existing instances of the application +ssh "${REMOTE_USER}@${REMOTE_HOST}" "killall jetkvm_app_debug || true" + # Copy the binary to the remote host cat jetkvm_app | ssh "${REMOTE_USER}@${REMOTE_HOST}" "cat > $REMOTE_PATH/jetkvm_app_debug" @@ -79,8 +82,7 @@ cd "$REMOTE_PATH" chmod +x jetkvm_app_debug # Run the application in the background -./jetkvm_app_debug - +PION_LOG_TRACE=jetkvm,cloud ./jetkvm_app_debug EOF echo "Deployment complete." diff --git a/log.go b/log.go index 89ad1d2..dbc5f03 100644 --- a/log.go +++ b/log.go @@ -6,3 +6,4 @@ import "github.com/pion/logging" // ref: https://github.com/pion/webrtc/wiki/Debugging-WebRTC var logger = logging.NewDefaultLoggerFactory().NewLogger("jetkvm") var usbLogger = logging.NewDefaultLoggerFactory().NewLogger("usb") +var cloudLogger = logging.NewDefaultLoggerFactory().NewLogger("cloud")