feat: add trace logging to OTA download

internal/ota/ota.go

@@ -5,6 +5,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"io"
 	"net/http"
 	"net/http/httptrace"
 	"net/url"
@@ -56,6 +57,32 @@ func (s *State) getUpdateURL(params UpdateParams) (string, error, bool) {
 	return updateURL.String(), nil, isCustomVersion
 }
 
+// newHTTPRequestWithTrace creates a new HTTP request with a trace logger
+func (s *State) newHTTPRequestWithTrace(ctx context.Context, method, url string, body io.Reader, logger func() *zerolog.Event) (*http.Request, error) {
+	localCtx := ctx
+	if s.l.GetLevel() <= zerolog.TraceLevel {
+		if logger == nil {
+			logger = func() *zerolog.Event { return s.l.Trace() }
+		}
+
+		l := func() *zerolog.Event { return logger().Str("url", url).Str("method", method) }
+		localCtx = httptrace.WithClientTrace(localCtx, &httptrace.ClientTrace{
+			GetConn:  func(hostPort string) { l().Str("hostPort", hostPort).Msg("starting to create conn") },
+			DNSStart: func(info httptrace.DNSStartInfo) { l().Interface("info", info).Msg("starting to look up dns") },
+			DNSDone:  func(info httptrace.DNSDoneInfo) { l().Interface("info", info).Msg("done looking up dns") },
+			ConnectStart: func(network, addr string) {
+				l().Str("network", network).Str("addr", addr).Msg("starting tcp connection")
+			},
+			ConnectDone: func(network, addr string, err error) {
+				l().Str("network", network).Str("addr", addr).Err(err).Msg("tcp connection created")
+			},
+			GotConn: func(info httptrace.GotConnInfo) { l().Interface("info", info).Msg("connection established") },
+		})
+	}
+
+	return http.NewRequestWithContext(localCtx, method, url, body)
+}
+
 func (s *State) fetchUpdateMetadata(ctx context.Context, params UpdateParams) (*UpdateMetadata, error) {
 	metadata := &UpdateMetadata{}
 
@@ -79,26 +106,7 @@ func (s *State) fetchUpdateMetadata(ctx context.Context, params UpdateParams) (*
 		Str("url", url).
 		Msg("fetching update metadata")
 
-	localCtx := ctx
+	req, err := s.newHTTPRequestWithTrace(ctx, "GET", url, nil, traceLogger)
-	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)
 	}

internal/ota/utils.go

@@ -9,6 +9,9 @@ import (
 	"net/http"
 	"os"
 	"os/exec"
+	"time"
+
+	"github.com/rs/zerolog"
 )
 
 func syncFilesystem() error {
@@ -27,8 +30,11 @@ func syncFilesystem() error {
 
 func (s *State) downloadFile(ctx context.Context, path string, url string, component string) error {
 	logger := s.l.With().Str("path", path).Str("url", url).Str("component", component).Logger()
-
+	t := time.Now()
-	logger.Trace().Msg("downloading file")
+	traceLogger := func() *zerolog.Event {
+		return logger.Trace().Dur("duration", time.Since(t))
+	}
+	traceLogger().Msg("downloading file")
 
 	componentUpdate, ok := s.componentUpdateStatuses[component]
 	if !ok {
@@ -38,7 +44,7 @@ func (s *State) downloadFile(ctx context.Context, path string, url string, compo
 	downloadProgress := componentUpdate.downloadProgress
 
 	if _, err := os.Stat(path); err == nil {
-		logger.Trace().Msg("removing existing file")
+		traceLogger().Msg("removing existing file")
 		if err := os.Remove(path); err != nil {
 			return fmt.Errorf("error removing existing file: %w", err)
 		}
@@ -46,27 +52,27 @@ func (s *State) downloadFile(ctx context.Context, path string, url string, compo
 
 	unverifiedPath := path + ".unverified"
 	if _, err := os.Stat(unverifiedPath); err == nil {
-		logger.Trace().Msg("removing existing unverified file")
+		traceLogger().Msg("removing existing unverified file")
 		if err := os.Remove(unverifiedPath); err != nil {
 			return fmt.Errorf("error removing existing unverified file: %w", err)
 		}
 	}
 
-	logger.Trace().Msg("creating unverified file")
+	traceLogger().Msg("creating unverified file")
 	file, err := os.Create(unverifiedPath)
 	if err != nil {
 		return fmt.Errorf("error creating file: %w", err)
 	}
 	defer file.Close()
 
-	logger.Trace().Msg("creating request")
+	traceLogger().Msg("creating request")
-	req, err := http.NewRequestWithContext(ctx, "GET", url, nil)
+	req, err := s.newHTTPRequestWithTrace(ctx, "GET", url, nil, traceLogger)
 	if err != nil {
 		return fmt.Errorf("error creating request: %w", err)
 	}
 
 	client := s.client()
-	logger.Trace().Msg("starting download")
+	traceLogger().Msg("starting download")
 	resp, err := client.Do(req)
 	if err != nil {
 		return fmt.Errorf("error downloading file: %w", err)
@@ -109,10 +115,10 @@ func (s *State) downloadFile(ctx context.Context, path string, url string, compo
 		}
 	}
 
-	logger.Trace().Msg("download finished")
+	traceLogger().Msg("download finished")
 	file.Close()
 
-	logger.Trace().Msg("syncing filesystem")
+	traceLogger().Msg("syncing filesystem")
 	if err := syncFilesystem(); err != nil {
 		return fmt.Errorf("error syncing filesystem: %w", err)
 	}