chore: add requestID to update status API calls and increase timeout to 10s

Author: ym

internal/ota/ota.go

@@ -6,6 +6,7 @@ import (
 	"errors"
 	"fmt"
 	"net/http"
+	"net/http/httptrace"
 	"net/url"
 	"time"
 
@@ -58,16 +59,47 @@ 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 +112,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 +129,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 +264,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 +316,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 +339,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 +364,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
 }
 

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",

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,

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<SystemVersionInfo>({
     method: "checkUpdateComponents",
     params: {