diff --git a/internal/ota/app.go b/internal/ota/app.go index 3ae206f9..55caa8e8 100644 --- a/internal/ota/app.go +++ b/internal/ota/app.go @@ -2,25 +2,15 @@ package ota import ( "context" - "fmt" "time" - - "github.com/rs/zerolog" ) const ( appUpdatePath = "/userdata/jetkvm/jetkvm_app.update" ) -func (s *State) componentUpdateError(prefix string, err error, l *zerolog.Logger) error { - if l == nil { - l = s.l - } - l.Error().Err(err).Msg(prefix) - s.error = fmt.Sprintf("%s: %v", prefix, err) - return err -} - +// DO NOT call it directly, it's not thread safe +// Mutex is currently held by the caller, e.g. doUpdate func (s *State) updateApp(ctx context.Context, appUpdate *componentUpdateStatus) error { l := s.l.With().Str("path", appUpdatePath).Logger() diff --git a/internal/ota/errors.go b/internal/ota/errors.go index 49804282..45f22890 100644 --- a/internal/ota/errors.go +++ b/internal/ota/errors.go @@ -1,8 +1,22 @@ package ota -import "errors" +import ( + "errors" + "fmt" + + "github.com/rs/zerolog" +) var ( // ErrVersionNotFound is returned when the specified version is not found ErrVersionNotFound = errors.New("specified version not found") ) + +func (s *State) componentUpdateError(prefix string, err error, l *zerolog.Logger) error { + if l == nil { + l = s.l + } + l.Error().Err(err).Msg(prefix) + s.error = fmt.Sprintf("%s: %v", prefix, err) + return err +} diff --git a/internal/ota/ota.go b/internal/ota/ota.go index 6802e316..bdf28f17 100644 --- a/internal/ota/ota.go +++ b/internal/ota/ota.go @@ -171,6 +171,8 @@ func (s *State) doUpdate(ctx context.Context, params UpdateParams) error { s.triggerComponentUpdateState("system", systemUpdate) } + scopedLogger.Trace().Bool("pending", appUpdate.pending).Msg("Checking for app update") + if appUpdate.pending { scopedLogger.Info(). Str("url", appUpdate.url). @@ -184,6 +186,8 @@ func (s *State) doUpdate(ctx context.Context, params UpdateParams) error { scopedLogger.Info().Msg("App is up to date") } + scopedLogger.Trace().Bool("pending", systemUpdate.pending).Msg("Checking for system update") + if systemUpdate.pending { if err := s.updateSystem(ctx, systemUpdate); err != nil { return s.componentUpdateError("Error updating system", err, &scopedLogger) diff --git a/internal/ota/sys.go b/internal/ota/sys.go index 465b9a4d..6a5002f6 100644 --- a/internal/ota/sys.go +++ b/internal/ota/sys.go @@ -11,10 +11,9 @@ const ( systemUpdatePath = "/userdata/jetkvm/update_system.tar" ) +// DO NOT call it directly, it's not thread safe +// Mutex is currently held by the caller, e.g. doUpdate func (s *State) updateSystem(ctx context.Context, systemUpdate *componentUpdateStatus) error { - s.mu.Lock() - defer s.mu.Unlock() - l := s.l.With().Str("path", systemUpdatePath).Logger() if err := s.downloadFile(ctx, systemUpdatePath, systemUpdate.url, "system"); err != nil { diff --git a/internal/ota/utils.go b/internal/ota/utils.go index 6da310ef..45d6c92c 100644 --- a/internal/ota/utils.go +++ b/internal/ota/utils.go @@ -26,6 +26,10 @@ 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") + componentUpdate, ok := s.componentUpdateStatuses[component] if !ok { return fmt.Errorf("component %s not found", component) @@ -34,6 +38,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") if err := os.Remove(path); err != nil { return fmt.Errorf("error removing existing file: %w", err) } @@ -41,23 +46,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") if err := os.Remove(unverifiedPath); err != nil { return fmt.Errorf("error removing existing unverified file: %w", err) } } + logger.Trace().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) if err != nil { return fmt.Errorf("error creating request: %w", err) } client := s.client() + logger.Trace().Msg("starting download") resp, err := client.Do(req) if err != nil { return fmt.Errorf("error downloading file: %w", err) @@ -100,15 +109,16 @@ func (s *State) downloadFile(ctx context.Context, path string, url string, compo } } + logger.Trace().Msg("download finished") file.Close() + logger.Trace().Msg("syncing filesystem") if err := syncFilesystem(); err != nil { return fmt.Errorf("error syncing filesystem: %w", err) } return nil } - func (s *State) verifyFile(path string, expectedHash string, verifyProgress *float32) error { l := s.l.With().Str("path", path).Logger()