From 5d87bd07ca143212eb0e59989de7ab562626b294 Mon Sep 17 00:00:00 2001 From: Cuong Manh Le Date: Wed, 3 Sep 2025 18:43:23 +0700 Subject: [PATCH] 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 | 30 +++++++++----- cmd/cli/commands_service_restart.go | 33 +++++++++++++--- cmd/cli/commands_service_start.go | 57 +++++++++++++++------------ cmd/cli/commands_service_status.go | 16 ++++++-- cmd/cli/commands_service_stop.go | 20 ++++++++-- cmd/cli/commands_service_uninstall.go | 24 +++++++++-- cmd/cli/prog.go | 1 + 7 files changed, 129 insertions(+), 52 deletions(-) diff --git a/cmd/cli/commands_service_reload.go b/cmd/cli/commands_service_reload.go index 74a80ac..5ddf4ff 100644 --- a/cmd/cli/commands_service_reload.go +++ b/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 } diff --git a/cmd/cli/commands_service_restart.go b/cmd/cli/commands_service_restart.go index 8764046..02e5a69 100644 --- a/cmd/cli/commands_service_restart.go +++ b/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 } diff --git a/cmd/cli/commands_service_start.go b/cmd/cli/commands_service_start.go index ea349ba..e206e0b 100644 --- a/cmd/cli/commands_service_start.go +++ b/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(`"`)) + logger.Write([]byte(`"`)) } } // 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 } diff --git a/cmd/cli/commands_service_status.go b/cmd/cli/commands_service_status.go index 13b1628..270e0e0 100644 --- a/cmd/cli/commands_service_status.go +++ b/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 } diff --git a/cmd/cli/commands_service_stop.go b/cmd/cli/commands_service_stop.go index 5c71842..0f47e46 100644 --- a/cmd/cli/commands_service_stop.go +++ b/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 } diff --git a/cmd/cli/commands_service_uninstall.go b/cmd/cli/commands_service_uninstall.go index 0f3032a..78a3d5e 100644 --- a/cmd/cli/commands_service_uninstall.go +++ b/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 } diff --git a/cmd/cli/prog.go b/cmd/cli/prog.go index 2b41bc0..c2d896f 100644 --- a/cmd/cli/prog.go +++ b/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: } }