diff --git a/cmd/main.go b/cmd/main.go index 8f3f155..7ac366f 100644 --- a/cmd/main.go +++ b/cmd/main.go @@ -1,6 +1,8 @@ package main import ( + "context" + "errors" "fmt" "github.com/richbl/go-ble-sync-cycle/internal/flags" @@ -29,14 +31,14 @@ func main() { // Check for application mode (CLI or GUI) if !flags.IsCLIMode() { - logger.Info(logger.BackgroundCtx, logger.APP, "now running in GUI mode...") + logger.Debug(logger.BackgroundCtx, logger.APP, "now running in GUI mode...") ui.StartGUI() return } // Continue running in CLI mode - logger.Info(logger.BackgroundCtx, logger.APP, "running in CLI mode") + logger.Debug(logger.BackgroundCtx, logger.APP, "running in CLI mode") // Create session manager sessionMgr := session.NewManager() @@ -48,7 +50,12 @@ func main() { // Start the session (initializes controllers, connects BLE, starts services) if err := sessionMgr.StartSession(); err != nil { - logger.Fatal(logger.BackgroundCtx, logger.APP, err) + + if errors.Is(err, context.Canceled) { + logger.Info(logger.BackgroundCtx, logger.APP, "application exiting due to user cancellation") + } else { + logger.Fatal(logger.BackgroundCtx, logger.APP, err) + } } // Wait patiently for shutdown (Ctrl+C or services error) diff --git a/internal/ble/sensor_controller.go b/internal/ble/sensor_controller.go index d6166c9..548fcab 100644 --- a/internal/ble/sensor_controller.go +++ b/internal/ble/sensor_controller.go @@ -4,7 +4,6 @@ import ( "context" "errors" "fmt" - "os" "sync" "sync/atomic" "time" @@ -80,7 +79,7 @@ const ( ) // NewBLEController creates a new BLE central controller for accessing a BLE peripheral -func NewBLEController(bleConfig config.BLEConfig, speedConfig config.SpeedConfig) (*Controller, error) { +func NewBLEController(ctx context.Context, bleConfig config.BLEConfig, speedConfig config.SpeedConfig) (*Controller, error) { AdapterMu.Lock() defer AdapterMu.Unlock() @@ -88,7 +87,7 @@ func NewBLEController(bleConfig config.BLEConfig, speedConfig config.SpeedConfig // Increment instance counter instanceID := bleInstanceCounter.Add(1) - logger.Debug(logger.BackgroundCtx, logger.BLE, fmt.Sprintf("creating BLE controller object (id:%04d)...", instanceID)) + logger.Debug(ctx, logger.BLE, fmt.Sprintf("creating BLE controller object (id:%04d)...", instanceID)) bleAdapter := bluetooth.DefaultAdapter @@ -96,7 +95,7 @@ func NewBLEController(bleConfig config.BLEConfig, speedConfig config.SpeedConfig return nil, fmt.Errorf(errFormat, "failed to enable BLE controller", err) } - logger.Info(logger.BackgroundCtx, logger.BLE, fmt.Sprintf("created BLE controller object (id:%04d)", instanceID)) + logger.Debug(ctx, logger.BLE, fmt.Sprintf("created BLE controller object (id:%04d)", instanceID)) return &Controller{ blePeripheralDetails: blePeripheralDetails{ @@ -161,23 +160,34 @@ func performBLEAction[T any](ctx context.Context, m *Controller, params actionPa scanCtx, cancel := context.WithTimeout(ctx, time.Duration(m.blePeripheralDetails.bleConfig.ScanTimeoutSecs)*time.Second) defer cancel() found := make(chan T, 1) + done := make(chan struct{}) errChan := make(chan error, 1) + // Start the BLE discovery action go func() { + defer close(done) logger.Debug(scanCtx, logger.BLE, params.logMessage) params.action(scanCtx, found, errChan) }() select { + case result := <-found: return result, nil + case err := <-errChan: var zero T return zero, err + case <-scanCtx.Done(): var zero T err := handleActionTimeout(scanCtx, m, params.stopAction) + logger.Debug(ctx, logger.BLE, "waiting for BLE peripheral disconnect...") + + <-done // Wait for the action to complete + + logger.Debug(ctx, logger.BLE, "BLE peripheral device disconnected") return zero, err } @@ -190,7 +200,6 @@ func handleActionTimeout(ctx context.Context, m *Controller, stopAction func() e if stopAction != nil { if err := stopAction(); err != nil { - fmt.Fprint(os.Stdout, "\r") // Clear the ^C character from the terminal line logger.Error(ctx, logger.BLE, fmt.Sprintf("failed to stop action: %v", err)) } @@ -201,8 +210,6 @@ func handleActionTimeout(ctx context.Context, m *Controller, stopAction func() e return fmt.Errorf("%w (%ds)", ErrScanTimeout, m.blePeripheralDetails.bleConfig.ScanTimeoutSecs) } - fmt.Fprint(os.Stdout, "\r") // Clear the ^C character from the terminal line - return fmt.Errorf(errFormat, "user interrupt detected", ctx.Err()) } @@ -217,7 +224,14 @@ func (m *Controller) scanAction(ctx context.Context, found chan<- bluetooth.Scan return } - found <- <-foundChan + // Wait for the scan to complete + select { + + case result := <-foundChan: + found <- result + + default: + } } @@ -235,37 +249,46 @@ func (m *Controller) connectAction(device bluetooth.ScanResult, found chan<- blu } -// startScanning starts the BLE peripheral scan +// startScanning starts the BLE peripheral scan and handles device discovery func (m *Controller) startScanning(ctx context.Context, found chan<- bluetooth.ScanResult) error { + // Check if already canceled before starting scanning operation + if err := ctx.Err(); err != nil { + return fmt.Errorf("session stop requested before BLE scan: %w", err) + } + AdapterMu.Lock() defer AdapterMu.Unlock() - err := m.blePeripheralDetails.bleAdapter.Scan(func(_ *bluetooth.Adapter, result bluetooth.ScanResult) { + // Use an atomic flag to ensure we only trigger the device discovery logic once + var foundOnce atomic.Bool + + err := m.blePeripheralDetails.bleAdapter.Scan(func(adapter *bluetooth.Adapter, result bluetooth.ScanResult) { - select { - case <-ctx.Done(): - logger.Debug(ctx, logger.BLE, "scan canceled via context") + // Check if context canceled before continuing scanning operation + if ctx.Err() != nil { + _ = adapter.StopScan() return - default: } + // Address comparison if result.Address.String() == m.blePeripheralDetails.bleConfig.SensorBDAddr { - if stopErr := m.blePeripheralDetails.bleAdapter.StopScan(); stopErr != nil { - logger.Error(ctx, logger.BLE, fmt.Sprintf("failed to stop scan: %v", stopErr)) - } + if foundOnce.CompareAndSwap(false, true) { + logger.Debug(ctx, logger.BLE, "BLE peripheral found; stopping scan...") + _ = adapter.StopScan() + + select { + case found <- result: + logger.Debug(ctx, logger.BLE, "scan result sent to controller") + default: + logger.Warn(ctx, logger.BLE, "controller object no longer listening; scan results ignored") + } - select { - case found <- result: - default: - logger.Warn(ctx, logger.BLE, "scan results channel full... try restarting the BLE device") } - return } - }) if err != nil { diff --git a/internal/ble/sensor_controller_test.go b/internal/ble/sensor_controller_test.go index 3baac0d..a8cc7a0 100644 --- a/internal/ble/sensor_controller_test.go +++ b/internal/ble/sensor_controller_test.go @@ -37,7 +37,7 @@ func createTestController(speedUnits string) (*Controller, error) { SpeedUnits: speedUnits, } - return NewBLEController(bleConfig, speedConfig) + return NewBLEController(logger.BackgroundCtx, bleConfig, speedConfig) } // waitForScanReset waits for the scan to reset diff --git a/internal/ble/sensor_services.go b/internal/ble/sensor_services.go index e30aea6..e4797c8 100644 --- a/internal/ble/sensor_services.go +++ b/internal/ble/sensor_services.go @@ -232,7 +232,7 @@ func (m *Controller) BatteryLevel(ctx context.Context, services []Characteristic } m.blePeripheralDetails.batteryLevel = batteryLevel - logger.Info(ctx, logger.BLE, "found battery characteristic UUID="+m.blePeripheralDetails.batteryCharacteristic.UUID().String()) + logger.Debug(ctx, logger.BLE, "found battery characteristic UUID="+m.blePeripheralDetails.batteryCharacteristic.UUID().String()) logger.Info(ctx, logger.BLE, fmt.Sprintf("BLE sensor battery level: %d%%", m.blePeripheralDetails.batteryLevel)) return nil @@ -253,7 +253,7 @@ func (m *Controller) CSCServices(ctx context.Context, device ServiceDiscoverer) return nil, fmt.Errorf(errFormat, ErrCSCServiceDiscovery, err) } - logger.Info(ctx, logger.BLE, "found CSC service UUID="+cscServiceConfig.serviceUUID.String()) + logger.Debug(ctx, logger.BLE, "found CSC service UUID="+cscServiceConfig.serviceUUID.String()) return result, nil } @@ -282,7 +282,7 @@ func (m *Controller) CSCCharacteristics(ctx context.Context, services []Characte return fmt.Errorf(errFormat, ErrCSCCharDiscovery, err) } - logger.Info(ctx, logger.BLE, "found CSC characteristic UUID="+cscServiceConfig.characteristicUUID.String()) + logger.Debug(ctx, logger.BLE, "found CSC characteristic UUID="+cscServiceConfig.characteristicUUID.String()) return nil } diff --git a/internal/ble/sensor_services_test.go b/internal/ble/sensor_services_test.go index 4e79e80..92607e6 100644 --- a/internal/ble/sensor_services_test.go +++ b/internal/ble/sensor_services_test.go @@ -125,7 +125,7 @@ func createTestBLEController(t *testing.T) *Controller { t.Helper() - controller, err := NewBLEController( + controller, err := NewBLEController(logger.BackgroundCtx, config.BLEConfig{ScanTimeoutSecs: 10}, config.SpeedConfig{}, ) diff --git a/internal/ble/sensor_updates.go b/internal/ble/sensor_updates.go index 8ee639c..0694aec 100644 --- a/internal/ble/sensor_updates.go +++ b/internal/ble/sensor_updates.go @@ -5,7 +5,6 @@ import ( "encoding/binary" "fmt" "math" - "os" "github.com/richbl/go-ble-sync-cycle/internal/config" "github.com/richbl/go-ble-sync-cycle/internal/logger" @@ -50,7 +49,7 @@ func initSpeedData(wheelCircumferenceMM int, speedUnitMultiplier float64) *speed // BLEUpdates starts the real-time monitoring of BLE sensor notifications func (m *Controller) BLEUpdates(ctx context.Context, speedController *speed.Controller) error { - logger.Info(ctx, logger.BLE, "starting the monitoring for BLE sensor notifications...") + logger.Debug(ctx, logger.BLE, "starting the monitoring for BLE sensor notifications...") errChan := make(chan error, 1) @@ -78,8 +77,8 @@ func (m *Controller) BLEUpdates(ctx context.Context, speedController *speed.Cont // Manage context cancellation go func() { <-ctx.Done() - fmt.Fprint(os.Stdout, "\r") // Clear the ^C character from the terminal line - logger.Info(ctx, logger.BLE, "interrupt detected, stopping the monitoring for BLE sensor notifications...") + + logger.Debug(ctx, logger.BLE, "interrupt detected, stopping the monitoring for BLE sensor notifications...") // Disable real-time notifications from BLE sensor if err := m.blePeripheralDetails.bleCharacteristic.EnableNotifications(nil); err != nil { diff --git a/internal/logger/logger.go b/internal/logger/logger.go index 827144b..f723180 100644 --- a/internal/logger/logger.go +++ b/internal/logger/logger.go @@ -98,13 +98,11 @@ func AddWriter(w io.Writer) { } // SetLogLevel dynamically updates the logging level of the running application -func SetLogLevel(levelStr string) { +func SetLogLevel(ctx context.Context, levelStr string) { newLevel := parseLogLevel(levelStr) logLevelVar.Set(newLevel) - Debug(BackgroundCtx, APP, "logging level changed to "+newLevel.String()) - } // LogLevel returns the current logging level @@ -368,9 +366,18 @@ func (h *CustomTextHandler) appendAttrs(buf *bytes.Buffer, attrs []slog.Attr) er return nil } -// UseGUIWriterOnly replaces all writers with only the GUI writer (used in GUI mode). +// UseGUIWriterOnly replaces all writers with only the GUI writer (used in GUI mode) func UseGUIWriterOnly(w io.Writer) { logOutput.mu.Lock() defer logOutput.mu.Unlock() logOutput.writers = []io.Writer{w} } + +// SetOutputToStdout resets the logger output to the standard output (terminal) +func SetOutputToStdout() { + + logOutput.mu.Lock() + defer logOutput.mu.Unlock() + logOutput.writers = []io.Writer{os.Stdout} + +} diff --git a/internal/services/shutdown_manager.go b/internal/services/shutdown_manager.go index 42ab606..b8f5346 100644 --- a/internal/services/shutdown_manager.go +++ b/internal/services/shutdown_manager.go @@ -39,12 +39,10 @@ var shutdownInstanceCounter atomic.Int64 func NewShutdownManager(timeout time.Duration) *ShutdownManager { instanceID := shutdownInstanceCounter.Add(1) - logger.Debug(logger.BackgroundCtx, logger.APP, fmt.Sprintf("creating shutdown manager object (id:%04d)...", instanceID)) // Create a context with a timeout ctx, cancel := context.WithCancel(logger.BackgroundCtx) - logger.Debug(logger.BackgroundCtx, logger.APP, fmt.Sprintf("created shutdown manager object (id:%04d)", instanceID)) return &ShutdownManager{ @@ -90,8 +88,11 @@ func (sm *ShutdownManager) Start() { sigChan := make(chan os.Signal, 1) signal.Notify(sigChan, os.Interrupt, syscall.SIGTERM) + // Wait for a shutdown signal go func() { <-sigChan + logger.ClearCLILine() + logger.Info(logger.BackgroundCtx, logger.APP, "shutdown request detected, shutting down now...") sm.Shutdown() }() @@ -111,6 +112,7 @@ func (sm *ShutdownManager) Shutdown() { }() select { + case <-done: logger.Debug(logger.BackgroundCtx, logger.APP, fmt.Sprintf("shutdown manager (id:%04d) services stopped", sm.InstanceID)) @@ -137,8 +139,10 @@ func (sm *ShutdownManager) Context() *context.Context { func (sm *ShutdownManager) Wait() { select { + case <-sm.context.ctx.Done(): sm.Shutdown() + case err := <-sm.errChan: if err != nil { logger.Error(sm.context.ctx, logger.APP, fmt.Sprintf("service error: %v", err)) @@ -157,8 +161,14 @@ func WaveHello(ctx context.Context) { // WaveGoodbye outputs a goodbye message and exits the program func WaveGoodbye(ctx context.Context) { + // Redirect logging to the console, clear the CLI line, and set the log level so this final + // shutdown message is visible regardless of application mode (CLI or GUI) + logger.SetOutputToStdout() logger.ClearCLILine() + logger.SetLogLevel(ctx, "debug") + logger.Info(ctx, logger.APP, config.GetFullVersion()+" shutdown complete. Goodbye") + os.Exit(0) } diff --git a/internal/session/controllers.go b/internal/session/controllers.go index 70b67c1..641794b 100644 --- a/internal/session/controllers.go +++ b/internal/session/controllers.go @@ -4,7 +4,6 @@ import ( "context" "errors" "fmt" - "os" "time" "github.com/richbl/go-ble-sync-cycle/internal/ble" @@ -17,8 +16,10 @@ import ( // Error definitions var ( - errNoActiveConfig = errors.New("cannot initialize controllers: no active configuration") - errNoActiveSession = errors.New("no active session to stop") + errNoActiveConfig = errors.New("cannot initialize controllers: no active configuration") + errNoActiveSession = errors.New("no active session to stop") + errInitializeControllers = errors.New("failed to initialize controllers") + errBLEConnectionFailed = errors.New("failed to connect to BLE device") ) // controllers holds the application component controllers @@ -32,59 +33,91 @@ type controllers struct { // StartSession initializes controllers and starts BLE and video services func (m *StateManager) StartSession() error { - // Validate preconditions and flip PendingStart/state to Connecting atomically + // Confirm start state, otherwise... why are we here? if err := m.prepareStart(); err != nil { return err } - logger.Debug(logger.BackgroundCtx, logger.APP, "creating ShutdownManager") + logger.Debug(logger.BackgroundCtx, logger.APP, "session startup sequence starting...") shutdownMgr := services.NewShutdownManager(30 * time.Second) shutdownMgr.Start() - - // store the shutdown manager reference m.storeShutdownMgr(shutdownMgr) - // store the context for the now-sentient shutdown manager - ctx := *shutdownMgr.Context() + setupDone := make(chan error, 1) + + // Wrap connection phase in a managed WaitGroup to ensure clean shutdown + shutdownMgr.Run(func(ctx context.Context) error { + + err := m.performSessionStartup(ctx, shutdownMgr) + setupDone <- err + + return err + }) + + // Wait for connection success, internal failure, or user cancellation + select { + + case err := <-setupDone: + + if err != nil { + m.cleanupStartFailure(shutdownMgr) + + return err + } + + logger.Debug(logger.BackgroundCtx, logger.APP, "session startup sequence completed") + + return nil + + case <-(*shutdownMgr.Context()).Done(): + m.cleanupStartFailure(shutdownMgr) + + return context.Canceled + } + +} + +// performSessionStartup handles the initialization and connection logic for a session +func (m *StateManager) performSessionStartup(ctx context.Context, shutdownMgr *services.ShutdownManager) error { logger.Debug(ctx, logger.APP, "initializing controllers...") - controllers, err := m.initializeControllers() + controllers, err := m.initializeControllers(ctx) if err != nil { logger.Error(ctx, logger.APP, fmt.Sprintf("controllers init failed: %v", err)) - m.cleanupStartFailure(shutdownMgr) - return fmt.Errorf("failed to initialize controllers: %w", err) + return fmt.Errorf(errFormat, errInitializeControllers, err) + } + + // Check if user clicked 'Stop' during init + if err := ctx.Err(); err != nil { + return fmt.Errorf(errFormat, errInitializeControllers, err) } logger.Debug(ctx, logger.APP, "controllers initialized OK") logger.Debug(ctx, logger.APP, "connecting BLE...") - bleDevice, err := m.connectBLE(controllers, shutdownMgr) + // Connect to the BLE peripheral + device, err := m.connectBLE(ctx, controllers) if err != nil { logger.Error(ctx, logger.APP, fmt.Sprintf("BLE connect failed: %v", err)) - m.cleanupStartFailure(shutdownMgr) - return fmt.Errorf("BLE connection failed: %w", err) + return fmt.Errorf(errFormat, errBLEConnectionFailed, err) } - controllers.bleDevice = bleDevice + controllers.bleDevice = device logger.Debug(ctx, logger.APP, "BLE connected OK") - // Finalize successful start m.mu.Lock() m.controllers = controllers - m.PendingStart = false m.state = StateRunning - logger.Debug(ctx, logger.APP, "set state=Running, PendingStart=false") + m.PendingStart = false m.mu.Unlock() logger.Debug(ctx, logger.APP, "starting services...") - - m.startServices(controllers, shutdownMgr) - + m.startServices(ctx, controllers, shutdownMgr) logger.Debug(ctx, logger.APP, "services started") return nil @@ -95,45 +128,53 @@ func (m *StateManager) StopSession() error { m.mu.Lock() - shutdownMgr := m.shutdownMgr + // Capture the manager instance we are about to stop + targetMgr := m.shutdownMgr wasPending := m.PendingStart - // Log what we're destroying - m.logControllersRelease(shutdownMgr) + // Log the release of specific controller IDs before we destroy the manager object + m.logControllersRelease(targetMgr) + // Reset state m.state = StateLoaded m.PendingStart = false + + // Null the StateManager fields only if they still point to the manager we are stopping + if m.shutdownMgr == targetMgr { + m.controllers = nil + m.shutdownMgr = nil + m.activeConfig = nil + } + m.mu.Unlock() - if shutdownMgr == nil && !wasPending { + // If there's nothing to stop, return + if targetMgr == nil && !wasPending { return errNoActiveSession } + // Determine the log context (use the target manager's context if available) ctx := logger.BackgroundCtx - if shutdownMgr != nil { - ctx = *shutdownMgr.Context() + + if targetMgr != nil { + ctx = *targetMgr.Context() } if wasPending { - logger.Info(ctx, logger.APP, "stop requested, canceling pending session setup...") + logger.Debug(ctx, logger.APP, "stop requested, canceling pending session setup...") } else { - logger.Info(ctx, logger.APP, "stop requested, canceling active session...") + logger.Debug(ctx, logger.APP, "stop requested, canceling active session...") } - fmt.Fprint(os.Stdout, "\r") // Clear the ^C character from the terminal line - - // Stop the shutdown manager - if shutdownMgr != nil { - shutdownMgr.Shutdown() + // Finally, we can now stop the session object + if targetMgr != nil { + targetMgr.Shutdown() } - m.clearResources() - m.stopBLEScan(ctx) - if wasPending { - logger.Info(ctx, logger.APP, "stopped pending session startup") + logger.Debug(ctx, logger.APP, "stopped pending session startup") } else { - logger.Info(ctx, logger.APP, "session stopped") + logger.Debug(ctx, logger.APP, "session stopped") } return nil @@ -149,42 +190,13 @@ func (m *StateManager) logControllersRelease(shutdownMgr *services.ShutdownManag ctx := *shutdownMgr.Context() if m.controllers.bleController != nil { - logger.Info(ctx, logger.BLE, fmt.Sprintf("releasing BLE controller object (id:%04d)", m.controllers.bleController.InstanceID)) + logger.Debug(ctx, logger.BLE, fmt.Sprintf("releasing BLE controller object (id:%04d)", m.controllers.bleController.InstanceID)) } if m.controllers.speedController != nil { - logger.Info(ctx, logger.SPEED, fmt.Sprintf("releasing speed controller object (id:%04d)", m.controllers.speedController.InstanceID)) + logger.Debug(ctx, logger.SPEED, fmt.Sprintf("releasing speed controller object (id:%04d)", m.controllers.speedController.InstanceID)) } if m.controllers.videoPlayer != nil { - logger.Info(ctx, logger.VIDEO, fmt.Sprintf("releasing video controller object (id:%04d)", m.controllers.videoPlayer.InstanceID)) - } - -} - -// clearResources clears the session resources -func (m *StateManager) clearResources() { - - m.mu.Lock() - defer m.mu.Unlock() - - m.controllers = nil - m.shutdownMgr = nil - m.activeConfig = nil - - logger.Debug(logger.BackgroundCtx, logger.APP, "controllers and shutdown manager objects released") - -} - -// stopBLEScan stops the BLE scan -func (m *StateManager) stopBLEScan(ctx context.Context) { - - // Stop any ongoing scan under mutex - ble.AdapterMu.Lock() - defer ble.AdapterMu.Unlock() - - if err := bluetooth.DefaultAdapter.StopScan(); err != nil { - logger.Warn(ctx, logger.BLE, fmt.Sprintf("failed to stop current BLE scan: %v", err)) - } else { - logger.Info(ctx, logger.BLE, "BLE scan stopped") + logger.Debug(ctx, logger.VIDEO, fmt.Sprintf("releasing video controller object (id:%04d)", m.controllers.videoPlayer.InstanceID)) } } @@ -252,37 +264,34 @@ func (m *StateManager) VideoPlaybackRate() float64 { } // initializeControllers creates the speed, video, and BLE controllers -func (m *StateManager) initializeControllers() (*controllers, error) { +func (m *StateManager) initializeControllers(ctx context.Context) (*controllers, error) { m.mu.RLock() cfg := m.activeConfig m.mu.RUnlock() - logger.Debug(logger.BackgroundCtx, logger.APP, "creating and initializing controllers...") + logger.Debug(ctx, logger.APP, "creating and initializing controllers...") if cfg == nil { return nil, errNoActiveConfig } - logger.Debug(logger.BackgroundCtx, logger.APP, "creating new speed controller...") - - speedController := speed.NewSpeedController(cfg.Speed.SmoothingWindow) - - logger.Debug(logger.BackgroundCtx, logger.APP, "creating new video controller...") + logger.Debug(ctx, logger.APP, "creating new speed controller...") + speedController := speed.NewSpeedController(ctx, cfg.Speed.SmoothingWindow) + logger.Debug(ctx, logger.APP, "creating new video controller...") - videoPlayer, err := video.NewPlaybackController(cfg.Video, cfg.Speed) + videoPlayer, err := video.NewPlaybackController(ctx, cfg.Video, cfg.Speed) if err != nil { return nil, fmt.Errorf("failed to create video controller: %w", err) } - logger.Debug(logger.BackgroundCtx, logger.APP, "creating new BLE controller...") - - bleController, err := ble.NewBLEController(cfg.BLE, cfg.Speed) + logger.Debug(ctx, logger.APP, "creating new BLE controller...") + bleController, err := ble.NewBLEController(ctx, cfg.BLE, cfg.Speed) if err != nil { return nil, fmt.Errorf("failed to create BLE controller: %w", err) } - logger.Debug(logger.BackgroundCtx, logger.APP, "all controllers created and initialized") + logger.Debug(ctx, logger.APP, "all controllers created and initialized") return &controllers{ speedController: speedController, @@ -292,9 +301,7 @@ func (m *StateManager) initializeControllers() (*controllers, error) { } // connectBLE handles BLE scanning, connection, and service discovery -func (m *StateManager) connectBLE(ctrl *controllers, shutdownMgr *services.ShutdownManager) (bluetooth.Device, error) { - - ctx := *shutdownMgr.Context() +func (m *StateManager) connectBLE(ctx context.Context, ctrl *controllers) (bluetooth.Device, error) { // Scan for BLE peripheral scanResult, err := ctrl.bleController.ScanForBLEPeripheral(ctx) @@ -342,64 +349,80 @@ func (m *StateManager) connectBLE(ctrl *controllers, shutdownMgr *services.Shutd } // startServices launches BLE and video services in background goroutines -func (m *StateManager) startServices(ctrl *controllers, shutdownMgr *services.ShutdownManager) { +func (m *StateManager) startServices(ctx context.Context, ctrl *controllers, shutdownMgr *services.ShutdownManager) { - m.runService(shutdownMgr, "BLE", func(ctx context.Context) error { + m.runService(ctx, shutdownMgr, "BLE", func(ctx context.Context) error { return ctrl.bleController.BLEUpdates(ctx, ctrl.speedController) }) - m.runService(shutdownMgr, "video", func(ctx context.Context) error { + m.runService(ctx, shutdownMgr, "video", func(ctx context.Context) error { return ctrl.videoPlayer.StartPlayback(ctx, ctrl.speedController) }) - logger.Debug(*shutdownMgr.Context(), logger.APP, "BLE and video services started") + logger.Debug(ctx, logger.APP, "BLE and video services started") } // cleanupStartFailure handles cleaning manager state when session startup fails func (m *StateManager) cleanupStartFailure(shutdownMgr *services.ShutdownManager) { - logger.Debug(logger.BackgroundCtx, logger.APP, "resetting controllers and session state...") - m.mu.Lock() - m.PendingStart = false - m.state = StateLoaded - m.controllers = nil - m.shutdownMgr = nil - m.activeConfig = nil + // Confirm that the shutdown manager being cleaned up is the one we currently hold + isCurrent := (m.shutdownMgr == shutdownMgr) + + if isCurrent { + logger.Debug(logger.BackgroundCtx, logger.APP, fmt.Sprintf("resetting state for current shutdown manager (id:%04d)", shutdownMgr.InstanceID)) + m.PendingStart = false + m.state = StateLoaded + m.controllers = nil + m.shutdownMgr = nil + m.activeConfig = nil + } m.mu.Unlock() - // ensure the shutdown manager... uh... shuts down - if shutdownMgr != nil { + // If no shutdown manager to clean up, go home + if shutdownMgr == nil { + return + } + + if (*shutdownMgr.Context()).Err() == nil { + logger.Debug(logger.BackgroundCtx, logger.APP, fmt.Sprintf("shutting down shutdown manager (id:%04d)", shutdownMgr.InstanceID)) shutdownMgr.Shutdown() } - logger.Debug(logger.BackgroundCtx, logger.APP, "controllers and session state reset complete") + if isCurrent { + logger.Debug(logger.BackgroundCtx, logger.APP, "controllers and session state reset complete") + } } // runService helper to launch a service with standard error handling and logging -func (m *StateManager) runService(shutdownMgr *services.ShutdownManager, service string, action func(context.Context) error) { +func (m *StateManager) runService(ctx context.Context, shutdownMgr *services.ShutdownManager, service string, action func(context.Context) error) { - logger.Debug(*shutdownMgr.Context(), logger.APP, fmt.Sprintf("starting %s service goroutine", service)) + logger.Debug(ctx, logger.APP, fmt.Sprintf("starting %s service goroutine", service)) shutdownMgr.Run(func(ctx context.Context) error { + logger.Debug(ctx, logger.APP, service+" service starting") err := action(ctx) - // If this goroutine fails, we must reset the state and clean up resources + // If this goroutine fails, we reset the state and clean up resources if err != nil && !errors.Is(err, context.Canceled) { + m.mu.Lock() - // Only update if we were previously running (avoids clobbering other states if raced) + + // Only update if we were previously running if m.state == StateRunning { m.state = StateError m.errorMsg = fmt.Sprintf("%s service failed: %v", service, err) } + // Rest resources state m.controllers = nil m.activeConfig = nil + m.mu.Unlock() } diff --git a/internal/session/session.go b/internal/session/session.go index 9dcc246..e2075be 100644 --- a/internal/session/session.go +++ b/internal/session/session.go @@ -51,12 +51,12 @@ func (s State) String() string { // StateManager coordinates session lifecycle and state type StateManager struct { - activeConfig *config.Config // The "currently running" config (immutable) + activeConfig *config.Config // The "currently running" config - loadedConfig *config.Config // The "loaded" config + loadedConfig *config.Config // The "loaded" (but not running) config loadedConfigPath string - editConfig *config.Config // The "editing" config + editConfig *config.Config // The "getting edited" config editConfigPath string controllers *controllers @@ -74,7 +74,7 @@ func NewManager() *StateManager { } } -// LoadTargetSession loads (or reloads) a session configuration for execution (loadedConfig) +// LoadTargetSession loads (or reloads) a session configuration for execution func (m *StateManager) LoadTargetSession(configPath string) error { defer m.writeLock()() @@ -104,13 +104,13 @@ func (m *StateManager) LoadTargetSession(configPath string) error { } if cfg.App.LogLevel != "" { - logger.SetLogLevel(cfg.App.LogLevel) + logger.SetLogLevel(logger.BackgroundCtx, cfg.App.LogLevel) } return nil } -// LoadEditSession loads a session configuration specifically for editing (editConfig only) +// LoadEditSession loads a session configuration specifically for editing func (m *StateManager) LoadEditSession(configPath string) error { defer m.writeLock()() @@ -154,7 +154,7 @@ func (m *StateManager) UpdateLoadedSession(cfg *config.Config, path string) erro return nil } -// SessionState returns the current session state (thread-safe) +// SessionState returns the current session state func (m *StateManager) SessionState() State { defer m.readLock()() @@ -162,7 +162,7 @@ func (m *StateManager) SessionState() State { return m.state } -// Config returns a copy of the current editing configuration (thread-safe) +// Config returns a copy of the current editing configuration func (m *StateManager) Config() *config.Config { defer m.readLock()() @@ -302,7 +302,7 @@ func (m *StateManager) prepareStart() error { return errNoSessionLoaded } - // Create a snapshot of the config (activeConfig is immutable) + // Create a snapshot of the config switch { case m.loadedConfig != nil: m.activeConfig = m.loadedConfig diff --git a/internal/speed/speed_controller.go b/internal/speed/speed_controller.go index 1ef1556..89d1b72 100644 --- a/internal/speed/speed_controller.go +++ b/internal/speed/speed_controller.go @@ -43,12 +43,11 @@ const ( // NewSpeedController creates a new speed controller with a specified window size, which // determines the number of speed measurements used for smoothing -func NewSpeedController(window int) *Controller { +func NewSpeedController(ctx context.Context, window int) *Controller { // Increment instance counter instanceID := speedInstanceCounter.Add(1) - - logger.Debug(logger.BackgroundCtx, logger.SPEED, fmt.Sprintf("creating speed controller object (id:%04d)...", instanceID)) + logger.Debug(ctx, logger.SPEED, fmt.Sprintf("creating speed controller object (id:%04d)...", instanceID)) r := ring.New(window) @@ -57,7 +56,7 @@ func NewSpeedController(window int) *Controller { r = r.Next() } - logger.Debug(logger.BackgroundCtx, logger.SPEED, fmt.Sprintf("created speed controller object (id:%04d)", instanceID)) + logger.Debug(ctx, logger.SPEED, fmt.Sprintf("created speed controller object (id:%04d)", instanceID)) return &Controller{ speeds: r, @@ -69,7 +68,6 @@ func NewSpeedController(window int) *Controller { // UpdateSpeed updates the current speed measurement and calculates a smoothed average func (sc *Controller) UpdateSpeed(ctx context.Context, speed float64) { - // Lock the mutex to protect the fields sc.mu.Lock() defer sc.mu.Unlock() @@ -88,6 +86,7 @@ func (sc *Controller) UpdateSpeed(ctx context.Context, speed float64) { } sum += value + }) // Ahh... smoothness diff --git a/internal/speed/speed_controller_test.go b/internal/speed/speed_controller_test.go index 601f45e..a5206e9 100644 --- a/internal/speed/speed_controller_test.go +++ b/internal/speed/speed_controller_test.go @@ -45,7 +45,7 @@ func TestNewSpeedController(t *testing.T) { logger.Initialize("debug") - controller := NewSpeedController(td.window) + controller := NewSpeedController(logger.BackgroundCtx, td.window) // Verify initialization if got := controller.window; got != td.window { @@ -67,7 +67,7 @@ func TestNewSpeedController(t *testing.T) { // TestUpdateSpeed tests the UpdateSpeed method of Controller func TestUpdateSpeed(t *testing.T) { - controller := NewSpeedController(td.window) + controller := NewSpeedController(logger.BackgroundCtx, td.window) // Update with test speeds for _, speed := range td.speeds { @@ -99,7 +99,7 @@ func TestSmoothedSpeed(t *testing.T) { // Run tests for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - controller := NewSpeedController(td.window) + controller := NewSpeedController(logger.BackgroundCtx, td.window) for _, speed := range tt.updates { controller.UpdateSpeed(logger.BackgroundCtx, speed) @@ -118,7 +118,7 @@ func TestSmoothedSpeed(t *testing.T) { func TestSpeedBuffer(t *testing.T) { // Define test cases - controller := NewSpeedController(td.window) + controller := NewSpeedController(logger.BackgroundCtx, td.window) speeds := []float64{3.5, 2.5, 1.5, 0.0, 0.0} want := []string{"3.50", "2.50", "1.50", "0.00", "0.00"} @@ -144,7 +144,7 @@ func TestSpeedBuffer(t *testing.T) { func TestConcurrency(t *testing.T) { // Create Controller - controller := NewSpeedController(td.window) + controller := NewSpeedController(logger.BackgroundCtx, td.window) var wg sync.WaitGroup // Run concurrent updates diff --git a/internal/video/media_player.go b/internal/video/media_player.go index c8b6469..1433f2a 100644 --- a/internal/video/media_player.go +++ b/internal/video/media_player.go @@ -1,6 +1,7 @@ package video import ( + "context" "errors" "fmt" "sync" @@ -96,11 +97,11 @@ func wrapError(context string, err error) error { // screenResolution returns the screen resolution of the primary monitor (needed by VLC for video // playback scaling) -func screenResolution() (int, int, error) { +func screenResolution(ctx context.Context) (int, int, error) { // Initialize framework if err := glfw.Init(); err != nil { - logger.Warn(logger.BackgroundCtx, logger.VIDEO, fmt.Sprintf("%v: %v", errFailedToInitializeGLFW, err)) + logger.Warn(ctx, logger.VIDEO, fmt.Sprintf("%v: %v", errFailedToInitializeGLFW, err)) return 0, 0, errFailedToInitializeGLFW } @@ -110,7 +111,7 @@ func screenResolution() (int, int, error) { // Get the primary monitor monitor := glfw.GetPrimaryMonitor() if monitor == nil { - logger.Warn(logger.BackgroundCtx, logger.VIDEO, errFailedToAcquireMonitor) + logger.Warn(ctx, logger.VIDEO, errFailedToAcquireMonitor) return 0, 0, errFailedToAcquireMonitor } @@ -118,7 +119,7 @@ func screenResolution() (int, int, error) { // Get the current video dimensions (width, height) mode := monitor.GetVideoMode() if mode == nil { - logger.Warn(logger.BackgroundCtx, logger.VIDEO, errFailedToGetVideoMode) + logger.Warn(ctx, logger.VIDEO, errFailedToGetVideoMode) return 0, 0, errFailedToGetVideoMode } @@ -140,8 +141,7 @@ func execGuarded(mu *sync.RWMutex, isNil func() bool, action func() error) error return action() } -// queryGuarded follows a lifecycle guard pattern to allow concurrent commands while the player is alive, -// returning a value and an error +// queryGuarded permits concurrent commands while the player is alive // //nolint:ireturn // Legitimate use of generics for internal player abstraction func queryGuarded[T any](mu *sync.RWMutex, isNil func() bool, action func() (T, error)) (T, error) { diff --git a/internal/video/mpv_player.go b/internal/video/mpv_player.go index bf7d79e..e1fbbda 100644 --- a/internal/video/mpv_player.go +++ b/internal/video/mpv_player.go @@ -13,6 +13,7 @@ static void set_c_locale_numeric() { import "C" import ( + "context" "fmt" "sync" "time" @@ -28,7 +29,7 @@ type mpvPlayer struct { } // newMpvPlayer creates a new mpvPlayer instance -func newMpvPlayer() (*mpvPlayer, error) { +func newMpvPlayer(ctx context.Context) (*mpvPlayer, error) { // Ensure C locale is set to "C" for numeric formats C.set_c_locale_numeric() @@ -41,6 +42,8 @@ func newMpvPlayer() (*mpvPlayer, error) { return nil, fmt.Errorf(errFormat, "failed to initialize mpv player", err) } + logger.Info(ctx, logger.VIDEO, "mpv player object created") + return m, nil } @@ -67,7 +70,7 @@ func (m *mpvPlayer) loadFile(path string) error { return err } - logger.Debug(logger.BackgroundCtx, logger.VIDEO, "video file validation succeeded") + logger.Info(logger.BackgroundCtx, logger.VIDEO, "video file validation succeeded") return nil }) @@ -136,9 +139,7 @@ func (m *mpvPlayer) validateLoadedFile() error { func (m *mpvPlayer) handleEndFile(event *mpv.Event) error { logger.Debug(logger.BackgroundCtx, logger.VIDEO, "EventEnd received during loading") - endFile := event.EndFile() - logger.Debug(logger.BackgroundCtx, logger.VIDEO, fmt.Sprintf("EndFile reason: %s, error: %v", endFile.Reason.String(), endFile.Error)) var validationErr error @@ -160,7 +161,6 @@ func (m *mpvPlayer) handleEndFile(event *mpv.Event) error { } logger.Debug(logger.BackgroundCtx, logger.VIDEO, "draining remaining events after error") - m.drainEvents() return validationErr @@ -312,7 +312,7 @@ func (m *mpvPlayer) setupEvents() error { // waitEvent waits for an mpv event and translates it to a generic playerEvent func (m *mpvPlayer) waitEvent(timeout float64) *playerEvent { - res, _ := queryGuarded[*playerEvent](&m.mu, func() bool { return m.player == nil }, func() (*playerEvent, error) { + res, _ := queryGuarded(&m.mu, func() bool { return m.player == nil }, func() (*playerEvent, error) { e := m.player.WaitEvent(timeout) if e == nil || e.EventID == mpv.EventNone { diff --git a/internal/video/mpv_player_test.go b/internal/video/mpv_player_test.go index ce7acf7..d7dc00c 100644 --- a/internal/video/mpv_player_test.go +++ b/internal/video/mpv_player_test.go @@ -2,11 +2,13 @@ package video import ( "testing" + + "github.com/richbl/go-ble-sync-cycle/internal/logger" ) // mpvPlayerFactory creates a new mpvPlayer instance for testing func mpvPlayerFactory() (*mpvPlayer, error) { - return newMpvPlayer() + return newMpvPlayer(logger.BackgroundCtx) } func TestMpvPlayerLifecycle(t *testing.T) { diff --git a/internal/video/video_controller.go b/internal/video/video_controller.go index 79aa2e8..0352047 100644 --- a/internal/video/video_controller.go +++ b/internal/video/video_controller.go @@ -4,7 +4,6 @@ import ( "context" "fmt" "math" - "os" "strings" "sync/atomic" "time" @@ -51,23 +50,22 @@ var speedUnitConversion = map[string]float64{ } // NewPlaybackController creates a new video player instance with the given config -func NewPlaybackController(videoConfig config.VideoConfig, speedConfig config.SpeedConfig) (*PlaybackController, error) { +func NewPlaybackController(ctx context.Context, videoConfig config.VideoConfig, speedConfig config.SpeedConfig) (*PlaybackController, error) { var player mediaPlayer var err error // Increment instance counter instanceID := videoInstanceCounter.Add(1) - - logger.Debug(logger.BackgroundCtx, logger.VIDEO, fmt.Sprintf("creating video controller object (id:%04d)...", instanceID)) + logger.Debug(ctx, logger.VIDEO, fmt.Sprintf("creating video controller object (id:%04d)...", instanceID)) switch videoConfig.MediaPlayer { case config.MediaPlayerMPV: - player, err = newMpvPlayer() + player, err = newMpvPlayer(ctx) case config.MediaPlayerVLC: - player, err = newVLCPlayer() + player, err = newVLCPlayer(ctx) default: return nil, errUnsupportedVideoPlayer @@ -77,7 +75,7 @@ func NewPlaybackController(videoConfig config.VideoConfig, speedConfig config.Sp return nil, fmt.Errorf("failed to create %s player: %w", videoConfig.MediaPlayer, err) } - logger.Debug(logger.BackgroundCtx, logger.VIDEO, fmt.Sprintf("created video controller object (id:%04d)", instanceID)) + logger.Debug(ctx, logger.VIDEO, fmt.Sprintf("created video controller object (id:%04d)", instanceID)) return &PlaybackController{ videoConfig: videoConfig, @@ -110,9 +108,7 @@ func (p *PlaybackController) StartPlayback(ctx context.Context, speedController defer func() { logger.Debug(ctx, logger.VIDEO, fmt.Sprintf("terminating video controller object (id:%04d)...", p.InstanceID)) - p.player.terminatePlayer() - logger.Debug(ctx, logger.VIDEO, fmt.Sprintf("destroyed video controller object (id:%04d)", p.InstanceID)) }() @@ -217,17 +213,19 @@ func (p *PlaybackController) setPlaybackOptions() error { func (p *PlaybackController) eventLoop(ctx context.Context, speedController *speed.Controller) error { // Start a ticker to check updates from SpeedController - ticker := time.NewTicker(time.Duration(p.videoConfig.UpdateIntervalSec * float64(time.Second))) + defer ticker.Stop() for { + // Check player events (give priority to video completion) if err := p.handlePlayerEvents(); err != nil { return err } select { + case <-ticker.C: if err := p.updateSpeedFromController(ctx, speedController); err != nil { @@ -235,9 +233,7 @@ func (p *PlaybackController) eventLoop(ctx context.Context, speedController *spe } case <-ctx.Done(): - - fmt.Fprint(os.Stdout, "\r") // Clear the ^C character from the terminal line - logger.Info(ctx, logger.VIDEO, fmt.Sprintf("interrupt detected, stopping %s video playback...", p.videoConfig.MediaPlayer)) + logger.Debug(ctx, logger.VIDEO, fmt.Sprintf("interrupt detected, stopping %s video playback...", p.videoConfig.MediaPlayer)) return nil // No need to show this context cancellation error } @@ -299,7 +295,6 @@ func (p *PlaybackController) updateSpeed(ctx context.Context) error { // Update the playback speed based on current speed and unit multiplier playbackSpeed := p.PlaybackSpeed() - logger.Debug(ctx, logger.VIDEO, fmt.Sprintf(logger.Cyan+"updating video playback speed to %.2fx...", playbackSpeed)) if err := p.player.setSpeed(playbackSpeed); err != nil { diff --git a/internal/video/video_controller_test.go b/internal/video/video_controller_test.go index 120f89a..f440e5c 100644 --- a/internal/video/video_controller_test.go +++ b/internal/video/video_controller_test.go @@ -226,7 +226,7 @@ func TestNewPlaybackController(t *testing.T) { vc, sc := createTestConfig() t.Run("successful creation", func(t *testing.T) { - controller, err := NewPlaybackController(vc, sc) + controller, err := NewPlaybackController(logger.BackgroundCtx, vc, sc) if err != nil { t.Skip("Skipping test: cannot create real player in unit test environment.") } @@ -240,7 +240,7 @@ func TestNewPlaybackController(t *testing.T) { t.Run("unsupported media player", func(t *testing.T) { vcInvalid := vc vcInvalid.MediaPlayer = "invalid-player" - controller, err := NewPlaybackController(vcInvalid, sc) + controller, err := NewPlaybackController(logger.BackgroundCtx, vcInvalid, sc) if err == nil { t.Error("expected an error for unsupported media player, but got nil") } @@ -260,7 +260,7 @@ func setupTestController(t *testing.T) (*PlaybackController, *mockMediaPlayer, * vc, sc := createTestConfig() mockPlayer := newMockMediaPlayer() - speedCtrl := speed.NewSpeedController(5) + speedCtrl := speed.NewSpeedController(logger.BackgroundCtx, 5) controller := &PlaybackController{ videoConfig: vc, speedConfig: sc, @@ -366,7 +366,7 @@ func runSingleUpdateSpeedTest(t *testing.T, vc config.VideoConfig, sc config.Spe controller.speedUnitMultiplier = 0.1 // For simplicity // Create a fresh speed controller per test to avoid cross-test state - speedCtrl := speed.NewSpeedController(5) + speedCtrl := speed.NewSpeedController(logger.BackgroundCtx, 5) // Fill the speed controller's buffer to get a predictable smoothed speed for range 5 { diff --git a/internal/video/vlc_player.go b/internal/video/vlc_player.go index a027e9e..0b331ff 100644 --- a/internal/video/vlc_player.go +++ b/internal/video/vlc_player.go @@ -1,6 +1,7 @@ package video import ( + "context" "errors" "fmt" "math" @@ -31,7 +32,7 @@ type vlcPlayer struct { } // newVLCPlayer creates a new vlcPlayer instance -func newVLCPlayer() (*vlcPlayer, error) { +func newVLCPlayer(ctx context.Context) (*vlcPlayer, error) { // Initialize VLC library if err := vlc.Init("--no-video-title-show", "--quiet"); err != nil { @@ -43,7 +44,7 @@ func newVLCPlayer() (*vlcPlayer, error) { if err != nil { if releaseErr := vlc.Release(); releaseErr != nil { - logger.Error(logger.BackgroundCtx, logger.VIDEO, fmt.Sprintf("failed to release VLC library: %v", releaseErr)) + logger.Error(ctx, logger.VIDEO, fmt.Sprintf("failed to release VLC library: %v", releaseErr)) } return nil, fmt.Errorf(errFormat, "failed to create VLC player", err) @@ -53,10 +54,12 @@ func newVLCPlayer() (*vlcPlayer, error) { var displayWidth int var displayHeight int - if displayWidth, displayHeight, err = screenResolution(); err != nil { - logger.Warn(logger.BackgroundCtx, logger.VIDEO, fmt.Sprintf("failed to get screen resolution: %v", err)) + if displayWidth, displayHeight, err = screenResolution(ctx); err != nil { + logger.Warn(ctx, logger.VIDEO, fmt.Sprintf("failed to get screen resolution: %v", err)) } + logger.Info(ctx, logger.VIDEO, "VLC player object created") + return &vlcPlayer{ player: player, marquee: player.Marquee(), @@ -195,7 +198,7 @@ func (v *vlcPlayer) setPause(paused bool) error { // timeRemaining gets the remaining time of the video func (v *vlcPlayer) timeRemaining() (int64, error) { - return queryGuarded[int64](&v.mu, func() bool { return v.player == nil }, func() (int64, error) { + return queryGuarded(&v.mu, func() bool { return v.player == nil }, func() (int64, error) { length, err := v.player.MediaLength() if err != nil { @@ -404,7 +407,7 @@ func (v *vlcPlayer) terminatePlayer() { v.player = nil v.marquee = nil - logger.Debug(logger.BackgroundCtx, logger.VIDEO, "destroyed VLC handle: C resources released") + logger.Debug(logger.BackgroundCtx, logger.VIDEO, "VLC player stopped and instance released") } if err := vlc.Release(); err != nil { diff --git a/internal/video/vlc_player_test.go b/internal/video/vlc_player_test.go index 62dc5fa..b875e78 100644 --- a/internal/video/vlc_player_test.go +++ b/internal/video/vlc_player_test.go @@ -2,11 +2,13 @@ package video import ( "testing" + + "github.com/richbl/go-ble-sync-cycle/internal/logger" ) // vlcPlayerFactory creates a new vlcPlayer instance for testing func vlcPlayerFactory() (*vlcPlayer, error) { - return newVLCPlayer() + return newVLCPlayer(logger.BackgroundCtx) } // TestVLCPlayerLifecycle tests the lifecycle of the vlcPlayer diff --git a/ui/ui.go b/ui/ui.go index 32c92f2..374c277 100644 --- a/ui/ui.go +++ b/ui/ui.go @@ -3,7 +3,6 @@ package ui import ( _ "embed" // required for go:embed "fmt" - "os" "time" "github.com/diamondburned/gotk4-adwaita/pkg/adw" @@ -220,10 +219,10 @@ func hydrateSessionLog(builder *gtk.Builder) *PageSessionLog { // Enable logging to the console in GUI mode if requested if flags.IsGUIConsoleLogging() { logger.AddWriter(sessionLog.LogWriter) - logger.Info(logger.BackgroundCtx, logger.GUI, "logging via Session Log started with added console/CLI output") + logger.Debug(logger.BackgroundCtx, logger.GUI, "logging via Session Log started with added console/CLI output") } else { logger.UseGUIWriterOnly(sessionLog.LogWriter) - logger.Info(logger.BackgroundCtx, logger.GUI, "logging via Session Log started") + logger.Debug(logger.BackgroundCtx, logger.GUI, "logging via Session Log started") } return sessionLog @@ -333,28 +332,27 @@ func StartGUI() { }) // Set up signal handling for CTRL+C that integrates with GTK event loop - logger.Debug(logger.BackgroundCtx, logger.GUI, "starting ShutdownManager signal handler") + logger.Debug(logger.BackgroundCtx, logger.GUI, "starting ShutdownManager signal handler...") shutdownMgr.Start() + logger.Debug(logger.BackgroundCtx, logger.GUI, "ShutdownManager signal handler started") // Monitor shutdown signal in a goroutine and trigger GTK quit when signaled go func() { ctx := *shutdownMgr.Context() <-ctx.Done() - fmt.Fprint(os.Stdout, "\r") // Clear the ^C character from the terminal line logger.Info(logger.BackgroundCtx, logger.GUI, "shutdown signal received, triggering GTK application quit") safeUpdateUI(func() { app.Quit() }) + }() // Run the GUI application... fly and be free! - logger.Debug(logger.BackgroundCtx, logger.GUI, "starting GTK event loop") + logger.Debug(logger.BackgroundCtx, logger.GUI, "GTK event loop started") app.Run(nil) - // Application has exited, perform cleanup - logger.Debug(logger.BackgroundCtx, logger.GUI, "GTK event loop exited, performing cleanup") - shutdownMgr.Shutdown() + // Application has exited, so say goodbye services.WaveGoodbye(logger.BackgroundCtx) } diff --git a/ui/ui_session_edit.go b/ui/ui_session_edit.go index 1b565b1..5535de8 100644 --- a/ui/ui_session_edit.go +++ b/ui/ui_session_edit.go @@ -340,7 +340,7 @@ func (sc *SessionController) performSessionSave(path string, cfg *config.Config) displayAlertDialog(sc.UI.Window, "BSC Session Saved", "") }) - logger.Info(logger.BackgroundCtx, logger.GUI, fmt.Sprintf("session file '%s' saved to: %s", cfg.App.SessionTitle, path)) + logger.Debug(logger.BackgroundCtx, logger.GUI, fmt.Sprintf("session file '%s' saved to: %s", cfg.App.SessionTitle, path)) // Check if we are modifying the currently loaded session loadedPath := sc.SessionManager.LoadedConfigPath() diff --git a/ui/ui_session_select.go b/ui/ui_session_select.go index 16097f8..e63cf06 100644 --- a/ui/ui_session_select.go +++ b/ui/ui_session_select.go @@ -134,7 +134,7 @@ func (sc *SessionController) scanForSessions() { // Check if any files were actually found if len(sc.Sessions) == 0 { - logger.Info(logger.BackgroundCtx, logger.GUI, "no session configuration files found") + logger.Debug(logger.BackgroundCtx, logger.GUI, "no session configuration files found") safeUpdateUI(func() { displayConfirmationDialog( @@ -154,7 +154,7 @@ func (sc *SessionController) scanForSessions() { // createNewDefaultSession creates a default configuration file, a placeholder video, and refreshes the list func (sc *SessionController) createNewDefaultSession() { - logger.Info(logger.BackgroundCtx, logger.GUI, "creating new default session configuration...") + logger.Debug(logger.BackgroundCtx, logger.GUI, "creating new default session configuration...") // Determine configuration directory configDir, err := getSessionConfigDir() @@ -194,7 +194,7 @@ func (sc *SessionController) createNewDefaultSession() { return } - logger.Info(logger.BackgroundCtx, logger.GUI, "successfully created new session file at "+filePath) + logger.Debug(logger.BackgroundCtx, logger.GUI, "successfully created new session file at "+filePath) // Refresh the GUI list sc.scanForSessions() diff --git a/ui/ui_session_status.go b/ui/ui_session_status.go index 86a57a8..2370c39 100644 --- a/ui/ui_session_status.go +++ b/ui/ui_session_status.go @@ -39,8 +39,16 @@ func (sc *SessionController) setupSessionControlSignals() { // handleSessionControl processes clicks on the session control button func (sc *SessionController) handleSessionControl() error { - currentState := sc.SessionManager.SessionState() + // Debounce session control button + safeUpdateUI(func() { + sc.UI.Page2.SessionControlBtn.SetSensitive(false) + }) + safeUpdateUI(func() { + sc.UI.Page2.SessionControlBtn.SetSensitive(true) + }) + + currentState := sc.SessionManager.SessionState() logger.Debug(logger.BackgroundCtx, logger.GUI, fmt.Sprintf("button clicked: State=%s", currentState)) if currentState >= session.StateConnecting || sc.starting.Load() { @@ -63,38 +71,34 @@ func (sc *SessionController) handleStart() { logger.Info(logger.BackgroundCtx, logger.GUI, "starting BSC Session...") - if sc.starting.Load() { - logger.Warn(logger.BackgroundCtx, logger.GUI, "start ignored: already pending") - - return - } - if !sc.starting.CompareAndSwap(false, true) { - logger.Warn(logger.BackgroundCtx, logger.GUI, "start ignored: race on pending") + logger.Warn(logger.BackgroundCtx, logger.GUI, "start request ignored: already pending") return } - // Ensure starting flag is cleared when method exits - defer sc.starting.Store(false) - // Update UI to show connecting state + logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI for start") + safeUpdateUI(func() { - logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI for start") sc.updateSessionControlButton(true) sc.updatePage2Status(StatusConnecting, StatusNotConnected, StatusUnknown) }) // Launch goroutine to start session - go sc.startSessionGUI() + go func() { + defer sc.starting.Store(false) + sc.startSessionGUI() + }() } // handleStartError processes errors from StartSession func (sc *SessionController) handleStartError(err error) { + logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI for error") + safeUpdateUI(func() { - logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI for error") sc.updateSessionControlButton(false) if errors.Is(err, context.Canceled) { @@ -130,9 +134,9 @@ func (sc *SessionController) handleStop() error { } logger.Debug(logger.BackgroundCtx, logger.GUI, "stop session returned") + logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI for stop") safeUpdateUI(func() { - logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI for stop") sc.updateSessionControlButton(false) sc.updatePage2Status(StatusStopped, StatusNotConnected, StatusUnknown) sc.resetMetrics() @@ -156,21 +160,20 @@ func (sc *SessionController) startSessionGUI() { defer func() { logger.Debug(logger.BackgroundCtx, logger.GUI, "start goroutine exiting") + logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI post-start") safeUpdateUI(func() { - logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI post-start") - // Re-toggle to Start if success/error, but only if stopped if sc.SessionManager.SessionState() == session.StateLoaded { sc.updateSessionControlButton(false) } }) + }() // Start the session logger.Debug(logger.BackgroundCtx, logger.GUI, "calling StartSession()") - err := sc.SessionManager.StartSession() if err != nil { sc.handleStartError(err) @@ -180,9 +183,9 @@ func (sc *SessionController) startSessionGUI() { // Update UI to show success state logger.Debug(logger.BackgroundCtx, logger.GUI, "StartSession() successful") + logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI for successful start") safeUpdateUI(func() { - logger.Debug(logger.BackgroundCtx, logger.GUI, "updating UI for successful start") battery := fmt.Sprintf("%d%%", sc.SessionManager.BatteryLevel()) sc.updatePage2Status(StatusConnected, StatusConnected, battery) sc.startMetricsLoop() diff --git a/ui/ui_setup.go b/ui/ui_setup.go index 2cb23e0..f0b1b15 100644 --- a/ui/ui_setup.go +++ b/ui/ui_setup.go @@ -43,7 +43,7 @@ func setupGUIApplication(app *gtk.Application, shutdownMgr *services.ShutdownMan // Create the "Exit" menu item action handler exitAction := gio.NewSimpleAction("exit", nil) exitAction.ConnectActivate(func(_ *glib.Variant) { - logger.Info(logger.BackgroundCtx, logger.GUI, "Exit action triggered from app menu item") + logger.Debug(logger.BackgroundCtx, logger.GUI, "Exit action triggered from app menu item") ui.createExitDialog() })