From 5368d8de50d266b438a4909d81b5fec76b5ca65c Mon Sep 17 00:00:00 2001 From: Stanislav Chzhen Date: Tue, 3 Dec 2024 17:25:37 +0300 Subject: [PATCH] home: imp code --- internal/home/controlinstall.go | 51 ++++++++++++++++++++++----------- internal/home/controlupdate.go | 25 ++++++++++------ internal/home/home.go | 2 +- internal/home/web.go | 26 +++++++++++------ 4 files changed, 69 insertions(+), 35 deletions(-) diff --git a/internal/home/controlinstall.go b/internal/home/controlinstall.go index bad59c59..42ea33c6 100644 --- a/internal/home/controlinstall.go +++ b/internal/home/controlinstall.go @@ -5,6 +5,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "net/http" "net/netip" "os" @@ -125,6 +126,8 @@ func (req *checkConfReq) validateWeb(tcpPorts aghalg.UniqChecker[tcpPort]) (err // be set. canAutofix is true if the port can be unbound by AdGuard Home // automatically. func (req *checkConfReq) validateDNS( + ctx context.Context, + l *slog.Logger, tcpPorts aghalg.UniqChecker[tcpPort], ) (canAutofix bool, err error) { defer func() { err = errors.Annotate(err, "validating ports: %w") }() @@ -155,10 +158,10 @@ func (req *checkConfReq) validateDNS( } // Try to fix automatically. - canAutofix = checkDNSStubListener() + canAutofix = checkDNSStubListener(ctx, l) if canAutofix && req.DNS.Autofix { - if derr := disableDNSStubListener(); derr != nil { - log.Error("disabling DNSStubListener: %s", err) + if derr := disableDNSStubListener(ctx, l); derr != nil { + l.ErrorContext(ctx, "disabling DNSStubListener", slogutil.KeyError, err) } err = aghnet.CheckPort("udp", netip.AddrPortFrom(req.DNS.IP, port)) @@ -185,7 +188,7 @@ func (web *webAPI) handleInstallCheckConfig(w http.ResponseWriter, r *http.Reque resp.Web.Status = err.Error() } - if resp.DNS.CanAutofix, err = req.validateDNS(tcpPorts); err != nil { + if resp.DNS.CanAutofix, err = req.validateDNS(r.Context(), web.logger, tcpPorts); err != nil { resp.DNS.Status = err.Error() } else if !req.DNS.IP.IsUnspecified() { resp.StaticIP = handleStaticIP(req.DNS.IP, req.SetStaticIP) @@ -234,27 +237,40 @@ func handleStaticIP(ip netip.Addr, set bool) staticIPJSON { return resp } -// Check if DNSStubListener is active -func checkDNSStubListener() bool { +// checkDNSStubListener returns true if DNSStubListener is active. +func checkDNSStubListener(ctx context.Context, l *slog.Logger) (ok bool) { if runtime.GOOS != "linux" { return false } - cmd := exec.Command("systemctl", "is-enabled", "systemd-resolved") - log.Tracef("executing %s %v", cmd.Path, cmd.Args) - _, err := cmd.Output() + var cmd *exec.Cmd + var err error + + defer func() { + if ok { + return + } + + l.ErrorContext( + ctx, + "execution failed", + "cmd", cmd.Path, + "code", cmd.ProcessState.ExitCode(), + slogutil.KeyError, err, + ) + }() + + cmd = exec.Command("systemctl", "is-enabled", "systemd-resolved") + l.DebugContext(ctx, "executing", "cmd", cmd.Path, "args", cmd.Args) + _, err = cmd.Output() if err != nil || cmd.ProcessState.ExitCode() != 0 { - log.Info("command %s has failed: %v code:%d", - cmd.Path, err, cmd.ProcessState.ExitCode()) return false } cmd = exec.Command("grep", "-E", "#?DNSStubListener=yes", "/etc/systemd/resolved.conf") - log.Tracef("executing %s %v", cmd.Path, cmd.Args) + l.DebugContext(ctx, "executing", "cmd", cmd.Path, "args", cmd.Args) _, err = cmd.Output() if err != nil || cmd.ProcessState.ExitCode() != 0 { - log.Info("command %s has failed: %v code:%d", - cmd.Path, err, cmd.ProcessState.ExitCode()) return false } @@ -270,8 +286,9 @@ DNSStubListener=no ) const resolvConfPath = "/etc/resolv.conf" -// Deactivate DNSStubListener -func disableDNSStubListener() (err error) { +// disableDNSStubListener deactivates DNSStubListerner and returns an error, if +// any. +func disableDNSStubListener(ctx context.Context, l *slog.Logger) (err error) { dir := filepath.Dir(resolvedConfPath) err = os.MkdirAll(dir, 0o755) if err != nil { @@ -291,7 +308,7 @@ func disableDNSStubListener() (err error) { } cmd := exec.Command("systemctl", "reload-or-restart", "systemd-resolved") - log.Tracef("executing %s %v", cmd.Path, cmd.Args) + l.DebugContext(ctx, "executing", "cmd", cmd.Path, "args", cmd.Args) _, err = cmd.Output() if err != nil { return err diff --git a/internal/home/controlupdate.go b/internal/home/controlupdate.go index 0febddb4..2c6f1e60 100644 --- a/internal/home/controlupdate.go +++ b/internal/home/controlupdate.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "fmt" + "log/slog" "net/http" "os" "os/exec" @@ -16,7 +17,6 @@ import ( "github.com/AdguardTeam/AdGuardHome/internal/aghnet" "github.com/AdguardTeam/AdGuardHome/internal/updater" "github.com/AdguardTeam/golibs/errors" - "github.com/AdguardTeam/golibs/log" "github.com/AdguardTeam/golibs/logutil/slogutil" ) @@ -147,7 +147,7 @@ func (web *webAPI) handleUpdate(w http.ResponseWriter, r *http.Request) { // The background context is used because the underlying functions wrap it // with timeout and shut down the server, which handles current request. It // also should be done in a separate goroutine for the same reason. - go finishUpdate(context.Background(), execPath, web.conf.runningAsService) + go finishUpdate(context.Background(), web.logger, execPath, web.conf.runningAsService) } // versionResponse is the response for /control/version.json endpoint. @@ -188,10 +188,17 @@ func tlsConfUsesPrivilegedPorts(c *tlsConfigSettings) (ok bool) { } // finishUpdate completes an update procedure. -func finishUpdate(ctx context.Context, execPath string, runningAsService bool) { +func finishUpdate(ctx context.Context, l *slog.Logger, execPath string, runningAsService bool) { var err error + defer func() { + if err != nil { + l.ErrorContext(ctx, "restarting", slogutil.KeyError, err) - log.Info("stopping all tasks") + os.Exit(1) + } + }() + + l.InfoContext(ctx, "stopping all tasks") cleanup(ctx) cleanupAlways() @@ -206,28 +213,28 @@ func finishUpdate(ctx context.Context, execPath string, runningAsService bool) { cmd := exec.Command("cmd", "/c", "net stop AdGuardHome & net start AdGuardHome") err = cmd.Start() if err != nil { - log.Fatalf("restarting: stopping: %s", err) + return } os.Exit(0) } cmd := exec.Command(execPath, os.Args[1:]...) - log.Info("restarting: %q %q", execPath, os.Args[1:]) + l.InfoContext(ctx, "restarting", "exec_path", execPath, "args", os.Args[1:]) cmd.Stdin = os.Stdin cmd.Stdout = os.Stdout cmd.Stderr = os.Stderr err = cmd.Start() if err != nil { - log.Fatalf("restarting:: %s", err) + return } os.Exit(0) } - log.Info("restarting: %q %q", execPath, os.Args[1:]) + l.InfoContext(ctx, "restarting", "exec_path", execPath, "args", os.Args[1:]) err = syscall.Exec(execPath, os.Args, os.Environ()) if err != nil { - log.Fatalf("restarting: %s", err) + return } } diff --git a/internal/home/home.go b/internal/home/home.go index 40ef7c6c..2827dce2 100644 --- a/internal/home/home.go +++ b/internal/home/home.go @@ -640,7 +640,7 @@ func run(opts options, clientBuildFS fs.FS, done chan struct{}) { fatalOnError(err) if config.HTTPConfig.Pprof.Enabled { - startPprof(config.HTTPConfig.Pprof.Port) + startPprof(slogLogger, config.HTTPConfig.Pprof.Port) } } diff --git a/internal/home/web.go b/internal/home/web.go index 21110948..a88e672d 100644 --- a/internal/home/web.go +++ b/internal/home/web.go @@ -199,6 +199,9 @@ func (web *webAPI) tlsConfigChanged(ctx context.Context, tlsConf tlsConfigSettin web.httpsServer.cond.L.Unlock() } +// loggerKeyServer is the key used by [webAPI] to identify servers. +const loggerKeyServer = "server" + // start - start serving HTTP requests func (web *webAPI) start(ctx context.Context) { web.logger.InfoContext(ctx, "AdGuard Home is available at the following addresses:") @@ -216,14 +219,16 @@ func (web *webAPI) start(ctx context.Context) { // Use an h2c handler to support unencrypted HTTP/2, e.g. for proxies. hdlr := h2c.NewHandler(withMiddlewares(Context.mux, limitRequestBody), &http2.Server{}) + logger := web.baseLogger.With(loggerKeyServer, "plain") + // Create a new instance, because the Web is not usable after Shutdown. web.httpServer = &http.Server{ - ErrorLog: log.StdLog("web: plain", log.DEBUG), Addr: web.conf.BindAddr.String(), Handler: hdlr, ReadTimeout: web.conf.ReadTimeout, ReadHeaderTimeout: web.conf.ReadHeaderTimeout, WriteTimeout: web.conf.WriteTimeout, + ErrorLog: slog.NewLogLogger(logger.Handler(), slog.LevelError), } go func() { errs <- web.httpServer.ListenAndServe() @@ -289,19 +294,21 @@ func (web *webAPI) tlsServerLoop(ctx context.Context) { }() addr := netip.AddrPortFrom(web.conf.BindAddr.Addr(), portHTTPS).String() + logger := web.baseLogger.With(loggerKeyServer, "https") + web.httpsServer.server = &http.Server{ - ErrorLog: log.StdLog("web: https", log.DEBUG), - Addr: addr, + Addr: addr, + Handler: withMiddlewares(Context.mux, limitRequestBody), TLSConfig: &tls.Config{ Certificates: []tls.Certificate{web.httpsServer.cert}, RootCAs: Context.tlsRoots, CipherSuites: Context.tlsCipherIDs, MinVersion: tls.VersionTLS12, }, - Handler: withMiddlewares(Context.mux, limitRequestBody), ReadTimeout: web.conf.ReadTimeout, ReadHeaderTimeout: web.conf.ReadHeaderTimeout, WriteTimeout: web.conf.WriteTimeout, + ErrorLog: slog.NewLogLogger(logger.Handler(), slog.LevelError), } printHTTPAddresses(urlutil.SchemeHTTPS) @@ -342,7 +349,7 @@ func (web *webAPI) mustStartHTTP3(ctx context.Context, address string) { } // startPprof launches the debug and profiling server on the provided port. -func startPprof(port uint16) { +func startPprof(baseLogger *slog.Logger, port uint16) { addr := netip.AddrPortFrom(netutil.IPv4Localhost(), port) runtime.SetBlockProfileRate(1) @@ -352,12 +359,15 @@ func startPprof(port uint16) { httputil.RoutePprof(mux) go func() { - defer log.OnPanic("pprof server") + ctx := context.Background() + logger := baseLogger.With(slogutil.KeyPrefix, "pprof") - log.Info("pprof: listening on %q", addr) + defer slogutil.RecoverAndLog(ctx, logger) + + logger.InfoContext(ctx, "listening", "addr", addr) err := http.ListenAndServe(addr.String(), mux) if !errors.Is(err, http.ErrServerClosed) { - log.Error("pprof: shutting down: %s", err) + logger.ErrorContext(ctx, "shutting down", slogutil.KeyError, err) } }() }