fix: remove mutex from updateApp & updateSystem

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 {
+// DO NOT call it directly, it's not thread safe
-	if l == nil {
+// Mutex is currently held by the caller, e.g. doUpdate
-		l = s.l
-	}
-	l.Error().Err(err).Msg(prefix)
-	s.error = fmt.Sprintf("%s: %v", prefix, err)
-	return err
-}
-
 func (s *State) updateApp(ctx context.Context, appUpdate *componentUpdateStatus) error {
 	l := s.l.With().Str("path", appUpdatePath).Logger()
 

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
+}

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)

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 {

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()