home: imp code

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

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

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

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,
+			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)
 		}
 	}()
 }