From e79f03d0db97a7cfc227d764aa767736f29386b7 Mon Sep 17 00:00:00 2001 From: Siyuan Date: Tue, 18 Nov 2025 14:07:42 +0000 Subject: [PATCH] feat: add trace logging to OTA download --- internal/ota/ota.go | 48 +++++++++++++++++++++++++------------------ internal/ota/utils.go | 26 ++++++++++++++--------- 2 files changed, 44 insertions(+), 30 deletions(-) diff --git a/internal/ota/ota.go b/internal/ota/ota.go index 5486177a..1b8f9c74 100644 --- a/internal/ota/ota.go +++ b/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 - 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) + req, err := s.newHTTPRequestWithTrace(ctx, "GET", url, nil, traceLogger) if err != nil { return nil, fmt.Errorf("error creating request: %w", err) } diff --git a/internal/ota/utils.go b/internal/ota/utils.go index 45d6c92c..25d27cdb 100644 --- a/internal/ota/utils.go +++ b/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() - - logger.Trace().Msg("downloading file") + t := time.Now() + 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") - req, err := http.NewRequestWithContext(ctx, "GET", url, nil) + traceLogger().Msg("creating request") + 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) }