feat: enhance logging in service commands with consistent logger usage

- Add entry/exit logging to all ServiceCommand methods (start, stop, status, reload, restart, uninstall)
- Replace mainLog.Load() calls with consistent logger variable usage throughout
- Capitalize all logging messages for better readability
- Add error context logging for service manager initialization failures
- Add debug logging for key operations (restart sequence, cleanup, validation)
- Improve error handling with proper error context in all service commands
- Add completion logging to track command execution flow

This improves debugging capabilities and provides better operational visibility
for service management operations while maintaining clean user-facing messages.

cmd/cli/commands_service_reload.go

@@ -12,46 +12,56 @@ import (
 
 // Reload implements the logic from cmdReload.Run
 func (sc *ServiceCommand) Reload(cmd *cobra.Command, args []string) error {
+	logger := mainLog.Load()
+	logger.Debug().Msg("Service reload command started")
+
 	s, _, err := sc.initializeServiceManager()
 	if err != nil {
+		logger.Error().Err(err).Msg("Failed to initialize service manager")
 		return err
 	}
+
 	status, err := s.Status()
 	if errors.Is(err, service.ErrNotInstalled) {
-		mainLog.Load().Warn().Msg("service not installed")
+		logger.Warn().Msg("Service not installed")
 		return nil
 	}
 	if status == service.StatusStopped {
-		mainLog.Load().Warn().Msg("service is not running")
+		logger.Warn().Msg("Service is not running")
 		return nil
 	}
+
 	dir, err := socketDir()
 	if err != nil {
-		mainLog.Load().Fatal().Err(err).Msg("failed to find ctrld home dir")
+		logger.Fatal().Err(err).Msg("Failed to find ctrld home dir")
 	}
+
 	cc := newControlClient(filepath.Join(dir, ctrldControlUnixSock))
 	resp, err := cc.post(reloadPath, nil)
 	if err != nil {
-		mainLog.Load().Fatal().Err(err).Msg("failed to send reload signal to ctrld")
+		logger.Fatal().Err(err).Msg("Failed to send reload signal to ctrld")
 	}
 	defer resp.Body.Close()
+
 	switch resp.StatusCode {
 	case http.StatusOK:
-		mainLog.Load().Notice().Msg("Service reloaded")
+		logger.Notice().Msg("Service reloaded")
 	case http.StatusCreated:
-		mainLog.Load().Warn().Msg("Service was reloaded, but new config requires service restart.")
-		mainLog.Load().Warn().Msg("Restarting service")
+		logger.Warn().Msg("Service was reloaded, but new config requires service restart.")
+		logger.Warn().Msg("Restarting service")
 		if _, err := s.Status(); errors.Is(err, service.ErrNotInstalled) {
-			mainLog.Load().Warn().Msg("Service not installed")
+			logger.Warn().Msg("Service not installed")
 			return nil
 		}
 		return sc.Restart(cmd, args)
 	default:
 		buf, err := io.ReadAll(resp.Body)
 		if err != nil {
-			mainLog.Load().Fatal().Err(err).Msg("could not read response from control server")
+			logger.Fatal().Err(err).Msg("Could not read response from control server")
 		}
-		mainLog.Load().Error().Err(err).Msgf("failed to reload ctrld: %s", string(buf))
+		logger.Error().Err(err).Msgf("Failed to reload ctrld: %s", string(buf))
 	}
+
+	logger.Debug().Msg("Service reload command completed")
 	return nil
 }

cmd/cli/commands_service_restart.go

@@ -11,6 +11,9 @@ import (
 
 // Restart implements the logic from cmdRestart.Run
 func (sc *ServiceCommand) Restart(cmd *cobra.Command, args []string) error {
+	logger := mainLog.Load()
+	logger.Debug().Msg("Service restart command started")
+
 	readConfig(false)
 	v.Unmarshal(&cfg)
 	cdUID = curCdUID()
@@ -18,11 +21,12 @@ func (sc *ServiceCommand) Restart(cmd *cobra.Command, args []string) error {
 
 	s, p, err := sc.initializeServiceManager()
 	if err != nil {
+		logger.Error().Err(err).Msg("Failed to initialize service manager")
 		return err
 	}
 
 	if _, err := s.Status(); errors.Is(err, service.ErrNotInstalled) {
-		mainLog.Load().Warn().Msg("service not installed")
+		logger.Warn().Msg("Service not installed")
 		return nil
 	}
 
@@ -40,13 +44,20 @@ func (sc *ServiceCommand) Restart(cmd *cobra.Command, args []string) error {
 
 	var validateConfigErr error
 	if cdMode {
+		logger.Debug().Msg("Validating ControlD remote config")
 		validateConfigErr = doValidateCdRemoteConfig(cdUID, false)
+		if validateConfigErr != nil {
+			logger.Warn().Err(validateConfigErr).Msg("ControlD remote config validation failed")
+		}
 	}
 
 	if ir := runningIface(s); ir != nil {
 		iface = ir.Name
 	}
+
 	doRestart := func() bool {
+		logger.Debug().Msg("Starting service restart sequence")
+
 		tasks := []task{
 			{s.Stop, true, "Stop"},
 			{func() error {
@@ -60,12 +71,19 @@ func (sc *ServiceCommand) Restart(cmd *cobra.Command, args []string) error {
 			}, false, "Waiting for service to stop"},
 		}
 		if !doTasks(tasks) {
+			logger.Error().Msg("Service stop tasks failed")
 			return false
 		}
 		tasks = []task{
 			{s.Start, true, "Start"},
 		}
-		return doTasks(tasks)
+		success := doTasks(tasks)
+		if success {
+			logger.Debug().Msg("Service restart sequence completed successfully")
+		} else {
+			logger.Error().Msg("Service restart sequence failed")
+		}
+		return success
 	}
 
 	if doRestart() {
@@ -76,15 +94,18 @@ func (sc *ServiceCommand) Restart(cmd *cobra.Command, args []string) error {
 			}
 			if cc := newSocketControlClientWithTimeout(context.TODO(), s, dir, timeout); cc != nil {
 				_, _ = cc.post(ifacePath, nil)
+				logger.Debug().Msg("Control server ping successful")
 			} else {
-				mainLog.Load().Warn().Err(err).Msg("Service was restarted, but ctrld process may not be ready yet")
+				logger.Warn().Err(err).Msg("Service was restarted, but ctrld process may not be ready yet")
 			}
 		} else {
-			mainLog.Load().Warn().Err(err).Msg("Service was restarted, but could not ping the control server")
+			logger.Warn().Err(err).Msg("Service was restarted, but could not ping the control server")
 		}
-		mainLog.Load().Notice().Msg("Service restarted")
+		logger.Notice().Msg("Service restarted")
 	} else {
-		mainLog.Load().Error().Msg("Service restart failed")
+		logger.Error().Msg("Service restart failed")
 	}
+
+	logger.Debug().Msg("Service restart command completed")
 	return nil
 }

cmd/cli/commands_service_start.go

@@ -21,6 +21,9 @@ import (
 
 // Start implements the logic from cmdStart.Run
 func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
+	logger := mainLog.Load()
+	logger.Debug().Msg("Service start command started")
+
 	checkStrFlagEmpty(cmd, cdUidFlagName)
 	checkStrFlagEmpty(cmd, cdOrgFlagName)
 	validateCdAndNextDNSFlags()
@@ -37,6 +40,7 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 	// Initialize service manager with proper configuration
 	s, p, err := sc.initializeServiceManagerWithServiceConfig(svcConfig)
 	if err != nil {
+		logger.Error().Err(err).Msg("Failed to initialize service manager")
 		return err
 	}
 
@@ -53,10 +57,11 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 	// If pin code was set, do not allow running start command.
 	if isCtrldRunning {
 		if err := checkDeactivationPin(s, nil); isCheckDeactivationPinErr(err) {
+			logger.Error().Msg("Deactivation pin check failed")
 			os.Exit(deactivationPinInvalidExitCode)
 		}
 		currentIface = runningIface(s)
-		mainLog.Load().Debug().Msgf("current interface on start: %v", currentIface)
+		logger.Debug().Msgf("Current interface on start: %v", currentIface)
 	}
 
 	ctx, cancel := context.WithCancel(context.Background())
@@ -70,7 +75,7 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 				}
 				res := &ifaceResponse{}
 				if err := json.NewDecoder(resp.Body).Decode(res); err != nil {
-					mainLog.Load().Warn().Err(err).Msg("failed to get iface info")
+					logger.Warn().Err(err).Msg("Failed to get iface info")
 					return
 				}
 				if res.OK {
@@ -79,8 +84,8 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 						_, _ = patchNetIfaceName(iff)
 						name = iff.Name
 					}
-					logger := mainLog.Load().With().Str("iface", name)
-					logger.Debug().Msg("setting DNS successfully")
+					logger := logger.With().Str("iface", name)
+					logger.Debug().Msg("Setting DNS successfully")
 					if res.All {
 						// Log that DNS is set for other interfaces.
 						withEachPhysicalInterfaces(
@@ -105,7 +110,8 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 	ud, err := userHomeDir()
 	sockDir := ud
 	if err != nil {
-		mainLog.Load().Warn().Msg("log server did not start")
+		logger.Warn().Err(err).Msg("Failed to get user home directory")
+		logger.Warn().Msg("Log server did not start")
 		close(logServerStarted)
 	} else {
 		setWorkingDirectory(svcConfig, ud)
@@ -151,12 +157,12 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 	if startOnly && isCtrldInstalled {
 		tryReadingConfigWithNotice(false, true)
 		if err := v.Unmarshal(&cfg); err != nil {
-			mainLog.Load().Fatal().Msgf("failed to unmarshal config: %v", err)
+			logger.Fatal().Msgf("Failed to unmarshal config: %v", err)
 		}
 
 		// if already running, dont restart
 		if isCtrldRunning {
-			mainLog.Load().Notice().Msg("service is already running")
+			logger.Notice().Msg("Service is already running")
 			return nil
 		}
 
@@ -178,17 +184,17 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 			{s.Start, true, "Start"},
 			{noticeWritingControlDConfig, false, "Notice writing ControlD config"},
 		}
-		mainLog.Load().Notice().Msg("Starting existing ctrld service")
+		logger.Notice().Msg("Starting existing ctrld service")
 		if doTasks(tasks) {
-			mainLog.Load().Notice().Msg("Service started")
+			logger.Notice().Msg("Service started")
 			sockDir, err := socketDir()
 			if err != nil {
-				mainLog.Load().Warn().Err(err).Msg("Failed to get socket directory")
+				logger.Warn().Err(err).Msg("Failed to get socket directory")
 				os.Exit(1)
 			}
 			reportSetDnsOk(sockDir)
 		} else {
-			mainLog.Load().Error().Err(err).Msg("Failed to start existing ctrld service")
+			logger.Error().Err(err).Msg("Failed to start existing ctrld service")
 			os.Exit(1)
 		}
 		return nil
@@ -198,7 +204,7 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 		_ = doValidateCdRemoteConfig(cdUID, true)
 	} else if uid := cdUIDFromProvToken(); uid != "" {
 		cdUID = uid
-		mainLog.Load().Debug().Msg("using uid from provision token")
+		logger.Debug().Msg("Using uid from provision token")
 		removeOrgFlagsFromArgs(svcConfig)
 		// Pass --cd flag to "ctrld run" command, so the provision token takes no effect.
 		svcConfig.Arguments = append(svcConfig.Arguments, "--cd="+cdUID)
@@ -214,7 +220,7 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 	tryReadingConfigWithNotice(writeDefaultConfig, true)
 
 	if err := v.Unmarshal(&cfg); err != nil {
-		mainLog.Load().Fatal().Msgf("failed to unmarshal config: %v", err)
+		logger.Fatal().Msgf("Failed to unmarshal config: %v", err)
 	}
 
 	initInteractiveLogging()
@@ -254,7 +260,7 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 		// generated after s.Start, so we notice users here for consistent with nextdns mode.
 		{noticeWritingControlDConfig, false, "Notice writing ControlD config"},
 	}
-	mainLog.Load().Notice().Msg("Starting service")
+	logger.Notice().Msg("Starting service")
 	if doTasks(tasks) {
 		// add a small delay to ensure the service is started and did not crash
 		time.Sleep(1 * time.Second)
@@ -262,44 +268,45 @@ func (sc *ServiceCommand) Start(cmd *cobra.Command, args []string) error {
 		ok, status, err := selfCheckStatus(ctx, s, sockDir)
 		switch {
 		case ok && status == service.StatusRunning:
-			mainLog.Load().Notice().Msg("Service started")
+			logger.Notice().Msg("Service started")
 		default:
 			marker := bytes.Repeat([]byte("="), 32)
 			// If ctrld service is not running, emitting log obtained from ctrld process.
 			if status != service.StatusRunning || ctx.Err() != nil {
-				mainLog.Load().Error().Msg("ctrld service may not have started due to an error or misconfiguration, service log:")
-				_, _ = mainLog.Load().Write(marker)
+				logger.Error().Msg("Ctrld service may not have started due to an error or misconfiguration, service log:")
+				_, _ = logger.Write(marker)
 				haveLog := false
 				for msg := range runCmdLogCh {
-					_, _ = mainLog.Load().Write([]byte(strings.ReplaceAll(msg, msgExit, "")))
+					_, _ = logger.Write([]byte(strings.ReplaceAll(msg, msgExit, "")))
 					haveLog = true
 				}
 				// If we're unable to get log from "ctrld run", notice users about it.
 				if !haveLog {
-					mainLog.Load().Write([]byte(`<no log output is obtained from ctrld process>"`))
+					logger.Write([]byte(`<no log output is obtained from ctrld process>"`))
 				}
 			}
 			// Report any error if occurred.
 			if err != nil {
-				_, _ = mainLog.Load().Write(marker)
+				_, _ = logger.Write(marker)
 				msg := fmt.Sprintf("An error occurred while performing test query: %s", err)
-				mainLog.Load().Write([]byte(msg))
+				logger.Write([]byte(msg))
 			}
 			// If ctrld service is running but selfCheckStatus failed, it could be related
 			// to user's system firewall configuration, notice users about it.
 			if status == service.StatusRunning && err == nil {
-				_, _ = mainLog.Load().Write(marker)
-				mainLog.Load().Write([]byte(`ctrld service was running, but a DNS query could not be sent to its listener`))
-				mainLog.Load().Write([]byte(`Please check your system firewall if it is configured to block/intercept/redirect DNS queries`))
+				_, _ = logger.Write(marker)
+				logger.Write([]byte(`ctrld service was running, but a DNS query could not be sent to its listener`))
+				logger.Write([]byte(`Please check your system firewall if it is configured to block/intercept/redirect DNS queries`))
 			}
 
-			_, _ = mainLog.Load().Write(marker)
+			_, _ = logger.Write(marker)
 			uninstall(p, s)
 			os.Exit(1)
 		}
 		reportSetDnsOk(sockDir)
 	}
 
+	logger.Debug().Msg("Service start command completed")
 	return nil
 }
 

cmd/cli/commands_service_status.go

@@ -9,25 +9,33 @@ import (
 
 // Status implements the logic from cmdStatus.Run
 func (sc *ServiceCommand) Status(cmd *cobra.Command, args []string) error {
+	logger := mainLog.Load()
+	logger.Debug().Msg("Service status command started")
+
 	s, _, err := sc.initializeServiceManager()
 	if err != nil {
+		logger.Error().Err(err).Msg("Failed to initialize service manager")
 		return err
 	}
+
 	status, err := s.Status()
 	if err != nil {
-		mainLog.Load().Error().Msg(err.Error())
+		logger.Error().Msg(err.Error())
 		os.Exit(1)
 	}
+
 	switch status {
 	case service.StatusUnknown:
-		mainLog.Load().Notice().Msg("Unknown status")
+		logger.Notice().Msg("Unknown status")
 		os.Exit(2)
 	case service.StatusRunning:
-		mainLog.Load().Notice().Msg("Service is running")
+		logger.Notice().Msg("Service is running")
 		os.Exit(0)
 	case service.StatusStopped:
-		mainLog.Load().Notice().Msg("Service is stopped")
+		logger.Notice().Msg("Service is stopped")
 		os.Exit(1)
 	}
+
+	logger.Debug().Msg("Service status command completed")
 	return nil
 }

cmd/cli/commands_service_stop.go

@@ -10,15 +10,22 @@ import (
 
 // Stop implements the logic from cmdStop.Run
 func (sc *ServiceCommand) Stop(cmd *cobra.Command, args []string) error {
+	logger := mainLog.Load()
+	logger.Debug().Msg("Service stop command started")
+
 	readConfig(false)
 	v.Unmarshal(&cfg)
 
 	s, p, err := sc.initializeServiceManager()
 	if err != nil {
+		logger.Error().Err(err).Msg("Failed to initialize service manager")
 		return err
 	}
 
 	p.cfg = &cfg
+	if iface == "" {
+		iface = "auto"
+	}
 	p.preRun()
 	if ir := runningIface(s); ir != nil {
 		p.runningIface = ir.Name
@@ -29,19 +36,26 @@ func (sc *ServiceCommand) Stop(cmd *cobra.Command, args []string) error {
 
 	status, err := s.Status()
 	if errors.Is(err, service.ErrNotInstalled) {
-		mainLog.Load().Warn().Msg("service not installed")
+		logger.Warn().Msg("Service not installed")
 		return nil
 	}
 	if status == service.StatusStopped {
-		mainLog.Load().Warn().Msg("service is already stopped")
+		logger.Warn().Msg("Service is already stopped")
 		return nil
 	}
 
 	if err := checkDeactivationPin(s, nil); isCheckDeactivationPinErr(err) {
+		logger.Error().Msg("Deactivation pin check failed")
 		os.Exit(deactivationPinInvalidExitCode)
 	}
+
+	logger.Debug().Msg("Stopping service")
 	if doTasks([]task{{s.Stop, true, "Stop"}}) {
-		mainLog.Load().Notice().Msg("Service stopped")
+		logger.Notice().Msg("Service stopped")
+	} else {
+		logger.Error().Msg("Service stop failed")
 	}
+
+	logger.Debug().Msg("Service stop command completed")
 	return nil
 }

cmd/cli/commands_service_uninstall.go

@@ -12,11 +12,15 @@ import (
 
 // Uninstall implements the logic from cmdUninstall.Run
 func (sc *ServiceCommand) Uninstall(cmd *cobra.Command, args []string) error {
+	logger := mainLog.Load()
+	logger.Debug().Msg("Service uninstall command started")
+
 	readConfig(false)
 	v.Unmarshal(&cfg)
 
 	s, p, err := sc.initializeServiceManager()
 	if err != nil {
+		logger.Error().Err(err).Msg("Failed to initialize service manager")
 		return err
 	}
 
@@ -29,11 +33,17 @@ func (sc *ServiceCommand) Uninstall(cmd *cobra.Command, args []string) error {
 		p.runningIface = ir.Name
 		p.requiredMultiNICsConfig = ir.All
 	}
+
 	if err := checkDeactivationPin(s, nil); isCheckDeactivationPinErr(err) {
+		logger.Error().Msg("Deactivation pin check failed")
 		os.Exit(deactivationPinInvalidExitCode)
 	}
+
+	logger.Debug().Msg("Starting service uninstall")
 	uninstall(p, s)
+
 	if cleanup {
+		logger.Debug().Msg("Performing cleanup operations")
 		var files []string
 		// Config file.
 		files = append(files, v.ConfigFileUsed())
@@ -59,7 +69,7 @@ func (sc *ServiceCommand) Uninstall(cmd *cobra.Command, args []string) error {
 		})
 		bin, err := os.Executable()
 		if err != nil {
-			mainLog.Load().Warn().Err(err).Msg("failed to get executable path")
+			logger.Warn().Err(err).Msg("Failed to get executable path")
 		}
 		if bin != "" && supportedSelfDelete {
 			files = append(files, bin)
@@ -74,17 +84,23 @@ func (sc *ServiceCommand) Uninstall(cmd *cobra.Command, args []string) error {
 				continue
 			}
 			if err := os.Remove(file); err == nil {
-				mainLog.Load().Notice().Msgf("removed %s", file)
+				logger.Notice().Str("file", file).Msg("File removed during cleanup")
+			} else {
+				logger.Debug().Err(err).Str("file", file).Msg("Failed to remove file during cleanup")
 			}
 		}
 		// Self-delete the ctrld binary if supported
 		if err := selfDeleteExe(); err != nil {
-			mainLog.Load().Warn().Err(err).Msg("failed to delete ctrld binary")
+			logger.Warn().Err(err).Msg("Failed to delete ctrld binary")
 		} else {
 			if !supportedSelfDelete {
-				mainLog.Load().Debug().Msgf("file removed: %s", bin)
+				logger.Debug().Msgf("File removed: %s", bin)
 			}
 		}
+
+		logger.Debug().Msg("Cleanup operations completed")
 	}
+
+	logger.Debug().Msg("Service uninstall command completed")
 	return nil
 }

cmd/cli/prog.go

@@ -253,6 +253,7 @@ func (p *prog) runWait() {
 
 		select {
 		case p.reloadDoneCh <- struct{}{}:
+			p.Debug().Msg("reload done signal sent")
 		default:
 		}
 	}