From d205df50e901875f4ccf85b59a1ce7de6ec22b59 Mon Sep 17 00:00:00 2001 From: Siyuan Date: Tue, 18 Nov 2025 03:10:01 +0000 Subject: [PATCH] chore: add requestID to update status API calls and increase timeout to 10s --- internal/ota/ota.go | 65 +++++++++++++++++++++++++++++++++++++---- jsonrpc.go | 3 +- ota.go | 2 ++ ui/src/utils/jsonrpc.ts | 2 ++ 4 files changed, 65 insertions(+), 7 deletions(-) diff --git a/internal/ota/ota.go b/internal/ota/ota.go index 534c6976..e04da314 100644 --- a/internal/ota/ota.go +++ b/internal/ota/ota.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "net/http" + "net/http/httptrace" "net/url" "time" @@ -58,16 +59,46 @@ func (s *State) getUpdateURL(params UpdateParams) (string, error, bool) { func (s *State) fetchUpdateMetadata(ctx context.Context, params UpdateParams) (*UpdateMetadata, error) { metadata := &UpdateMetadata{} + logger := s.l.With().Logger() + if params.RequestID != "" { + logger = logger.With().Str("requestID", params.RequestID).Logger() + } + t := time.Now() + traceLogger := func() *zerolog.Event { + return logger.Trace().Dur("duration", time.Since(t)) + } + url, err, isCustomVersion := s.getUpdateURL(params) + traceLogger().Err(err). + Msg("fetchUpdateMetadata: getUpdateURL") if err != nil { return nil, fmt.Errorf("error getting update URL: %w", err) } - s.l.Trace(). + traceLogger(). Str("url", url). Msg("fetching update metadata") - req, err := http.NewRequestWithContext(ctx, "GET", url, nil) + localCtx := ctx + if s.l.GetLevel() <= zerolog.TraceLevel { + clientTrace := &httptrace.ClientTrace{ + GetConn: func(hostPort string) { traceLogger().Str("hostPort", hostPort).Msg("starting to create conn") }, + DNSStart: func(info httptrace.DNSStartInfo) { + traceLogger().Interface("info", info).Msg("starting to look up dns") + }, + DNSDone: func(info httptrace.DNSDoneInfo) { traceLogger().Interface("info", info).Msg("done looking up dns") }, + ConnectStart: func(network, addr string) { + traceLogger().Str("network", network).Str("addr", addr).Msg("starting tcp connection") + }, + ConnectDone: func(network, addr string, err error) { + traceLogger().Str("network", network).Str("addr", addr).Err(err).Msg("tcp connection created") + }, + GotConn: func(info httptrace.GotConnInfo) { traceLogger().Interface("info", info).Msg("connection established") }, + } + localCtx = httptrace.WithClientTrace(localCtx, clientTrace) + } + + req, err := http.NewRequestWithContext(localCtx, "GET", url, nil) if err != nil { return nil, fmt.Errorf("error creating request: %w", err) } @@ -80,6 +111,10 @@ func (s *State) fetchUpdateMetadata(ctx context.Context, params UpdateParams) (* } defer resp.Body.Close() + traceLogger(). + Int("status", resp.StatusCode). + Msg("fetchUpdateMetadata: response") + if isCustomVersion && resp.StatusCode == http.StatusNotFound { return nil, ErrVersionNotFound } @@ -93,6 +128,9 @@ func (s *State) fetchUpdateMetadata(ctx context.Context, params UpdateParams) (* return nil, fmt.Errorf("error decoding response: %w", err) } + traceLogger(). + Msg("fetchUpdateMetadata: completed") + return metadata, nil } @@ -225,6 +263,9 @@ type UpdateParams struct { Components map[string]string `json:"components"` IncludePreRelease bool `json:"includePreRelease"` ResetConfig bool `json:"resetConfig"` + // RequestID is a unique identifier for the update request + // When it's set, detailed trace logs will be enabled (if the log level is Trace) + RequestID string } // getUpdateStatus gets the update status for the given components @@ -274,9 +315,16 @@ func (s *State) checkUpdateStatus( appUpdateStatus.localVersion = appVersionLocal.String() systemUpdateStatus.localVersion = systemVersionLocal.String() - s.l.Trace(). + logger := s.l.With().Logger() + if params.RequestID != "" { + logger = logger.With().Str("requestID", params.RequestID).Logger() + } + t := time.Now() + + logger.Trace(). Str("appVersionLocal", appVersionLocal.String()). Str("systemVersionLocal", systemVersionLocal.String()). + Dur("duration", time.Since(t)). Msg("checkUpdateStatus: getLocalVersion") // fetch the remote metadata @@ -290,8 +338,9 @@ func (s *State) checkUpdateStatus( return err } - s.l.Trace(). + logger.Trace(). Interface("remoteMetadata", remoteMetadata). + Dur("duration", time.Since(t)). Msg("checkUpdateStatus: fetchUpdateMetadata") // parse the remote metadata to the componentUpdateStatuses @@ -314,10 +363,14 @@ func (s *State) checkUpdateStatus( } if s.l.GetLevel() <= zerolog.TraceLevel { - appUpdateStatus.getZerologLogger(s.l).Trace().Msg("checkUpdateStatus: remoteMetadataToComponentStatus [app]") - systemUpdateStatus.getZerologLogger(s.l).Trace().Msg("checkUpdateStatus: remoteMetadataToComponentStatus [system]") + appUpdateStatus.getZerologLogger(&logger).Trace().Msg("checkUpdateStatus: remoteMetadataToComponentStatus [app]") + systemUpdateStatus.getZerologLogger(&logger).Trace().Msg("checkUpdateStatus: remoteMetadataToComponentStatus [system]") } + logger.Trace(). + Dur("duration", time.Since(t)). + Msg("checkUpdateStatus: completed") + return nil } diff --git a/jsonrpc.go b/jsonrpc.go index be5125de..b401ac59 100644 --- a/jsonrpc.go +++ b/jsonrpc.go @@ -123,6 +123,7 @@ func onRPCMessage(message webrtc.DataChannelMessage, session *Session) { Interface("id", request.ID).Logger() scopedLogger.Trace().Msg("Received RPC request") + t := time.Now() handler, ok := rpcHandlers[request.Method] if !ok { @@ -154,7 +155,7 @@ func onRPCMessage(message webrtc.DataChannelMessage, session *Session) { return } - scopedLogger.Trace().Interface("result", result).Msg("RPC handler returned") + scopedLogger.Trace().Dur("duration", time.Since(t)).Interface("result", result).Msg("RPC handler returned") response := JSONRPCResponse{ JSONRPC: "2.0", diff --git a/ota.go b/ota.go index 595933aa..ef7f9c21 100644 --- a/ota.go +++ b/ota.go @@ -8,6 +8,7 @@ import ( "strings" "github.com/Masterminds/semver/v3" + "github.com/google/uuid" "github.com/jetkvm/kvm/internal/ota" ) @@ -82,6 +83,7 @@ func getUpdateStatus(includePreRelease bool) (*ota.UpdateStatus, error) { updateStatus, err := otaState.GetUpdateStatus(context.Background(), ota.UpdateParams{ DeviceID: GetDeviceID(), IncludePreRelease: includePreRelease, + RequestID: uuid.New().String(), }) // to ensure backwards compatibility, diff --git a/ui/src/utils/jsonrpc.ts b/ui/src/utils/jsonrpc.ts index 03f0af3f..716b8220 100644 --- a/ui/src/utils/jsonrpc.ts +++ b/ui/src/utils/jsonrpc.ts @@ -232,6 +232,7 @@ export async function getUpdateStatus() { // It can be called on page load right after a restart, so we need to give it time to // establish a connection to the api server. maxAttempts: 6, + attemptTimeoutMs: 10000, }); if (response.error) throw response.error; @@ -252,6 +253,7 @@ export interface updateParams { } export async function checkUpdateComponents(params: updateParams, includePreRelease: boolean) { + console.log("checkUpdateComponents", JSON.stringify(params, null, 2), includePreRelease); const response = await callJsonRpc({ method: "checkUpdateComponents", params: {