Improve client logging.

2025-09-10 20:04:19 +05:00
parent e3b9c9ae40
commit c2142cc1a6
15 changed files with 118 additions and 44 deletions
--- a/client/cmd/client/main.go
+++ b/client/cmd/client/main.go
@@ -1,7 +1,6 @@
 package main

 import (
-	"log/slog"
 	"os"

 	"bunker/client/internal/application"
@@ -18,12 +17,17 @@ import (
 )

 func main() {
-	slog.Info("Starting Bunker client...")
-
-	_ = slog.SetLogLoggerLevel(slog.LevelDebug)
-
 	app := application.New()

+	lgr := app.NewLogger("module", "main")
+	lgr.Info(
+		"Starting Bunker...",
+		"version", app.Fyne().Metadata().Custom["Version"],
+		"build_no", app.Fyne().Metadata().Custom["Build"],
+		"commit", app.Fyne().Metadata().Custom["Commit"],
+		"branch", app.Fyne().Metadata().Custom["Branch"],
+	)
+
 	checkError(translations.Initialize(app))
 	checkError(database.Initialize(app))
 	checkError(options.Initialize(app))
--- a/client/internal/application/application.go
+++ b/client/internal/application/application.go
@@ -19,8 +19,10 @@ var (

 // Application is a lifecycle controlling structure for application.
 type Application struct {
-	fyneApp  fyne.App
-	services []Service
+	fyneApp    fyne.App
+	baseLogger *slog.Logger
+	appLogger  *slog.Logger
+	services   []Service
 }

 // New creates new instance of lifecycle controlling structure.
@@ -39,7 +41,7 @@ func (a *Application) configure() error {
 			continue
 		}

-		slog.Debug("Launching configuration procedure for service", "service", service.Name())
+		a.appLogger.Debug("Launching configuration procedure for service", "service", service.Name())

 		if err := service.Configure(); err != nil {
 			return fmt.Errorf("configure service '%s': %w", service.Name(), err)
@@ -52,7 +54,7 @@ func (a *Application) configure() error {
 			continue
 		}

-		slog.Debug("Launching configuration procedure for service", "service", service.Name())
+		a.appLogger.Debug("Launching configuration procedure for service", "service", service.Name())

 		if err := service.Configure(); err != nil {
 			return fmt.Errorf("configure service '%s': %w", service.Name(), err)
@@ -69,7 +71,7 @@ func (a *Application) connectDependencies() error {
 			continue
 		}

-		slog.Debug("Connecting dependencies for service.", "service", service.Name())
+		a.appLogger.Debug("Connecting dependencies for service.", "service", service.Name())

 		if err := service.ConnectDependencies(); err != nil {
 			return fmt.Errorf("connect dependencies for service '%s': %w", service.Name(), err)
@@ -82,7 +84,7 @@ func (a *Application) connectDependencies() error {
 			continue
 		}

-		slog.Debug("Connecting dependencies for service.", "service", service.Name())
+		a.appLogger.Debug("Connecting dependencies for service.", "service", service.Name())

 		if err := service.ConnectDependencies(); err != nil {
 			return fmt.Errorf("connect dependencies for service '%s': %w", service.Name(), err)
@@ -104,6 +106,8 @@ func (a *Application) ContextWithTimeout(timeout time.Duration) context.Context
 }

 func (a *Application) initialize() {
+	a.initializeLogger()
+
 	a.services = make([]Service, 0)

 	a.initializeFyne()
@@ -119,7 +123,7 @@ func (a *Application) launchStartupTasks() error {
 			continue
 		}

-		slog.Debug("Launching startup tasks for service.", "service", service.Name())
+		a.appLogger.Debug("Launching startup tasks for service.", "service", service.Name())

 		if err := service.LaunchStartupTasks(); err != nil {
 			return fmt.Errorf("launch startup tasks for core/%s: %w", service.Name(), err)
@@ -131,7 +135,7 @@ func (a *Application) launchStartupTasks() error {
 			continue
 		}

-		slog.Debug("Launching startup tasks for service.", "service", service.Name())
+		a.appLogger.Debug("Launching startup tasks for service.", "service", service.Name())

 		if err := service.LaunchStartupTasks(); err != nil {
 			return fmt.Errorf("launch startup tasks for core/%s: %w", service.Name(), err)
@@ -161,7 +165,7 @@ func (a *Application) launchStartupTasks() error {

 // Shutdown stops application
 func (a *Application) Shutdown() error {
-	slog.Info("Stopping pztrn's Bunker...")
+	a.appLogger.Info("Stopping pztrn's Bunker...")

 	// Сначала тушим фичи.
 	for _, service := range a.services {
@@ -169,7 +173,7 @@ func (a *Application) Shutdown() error {
 			continue
 		}

-		slog.Debug("Shutting down service.", "service", service.Name())
+		a.appLogger.Debug("Shutting down service.", "service", service.Name())

 		if err := service.Shutdown(); err != nil {
 			return fmt.Errorf("shutting down service '%s': %w", service.Name(), err)
@@ -182,7 +186,7 @@ func (a *Application) Shutdown() error {
 			continue
 		}

-		slog.Debug("Shutting down service.", "service", service.Name())
+		a.appLogger.Debug("Shutting down service.", "service", service.Name())

 		if err := service.Shutdown(); err != nil {
 			return fmt.Errorf("shutting down service '%s': %w", service.Name(), err)
--- a/client/internal/application/logger.go
+++ b/client/internal/application/logger.go
@@ -0,0 +1,20 @@
+package application
+
+import (
+	"log/slog"
+	"os"
+)
+
+func (a *Application) initializeLogger() {
+	a.baseLogger = slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+		AddSource: true,
+		Level:     slog.LevelDebug,
+	}))
+
+	a.appLogger = a.baseLogger.With("module", "application")
+}
+
+// NewLogger creates new sub-instance of base logger and adds some additional data to it for persistent output.
+func (a *Application) NewLogger(withs ...interface{}) *slog.Logger {
+	return a.baseLogger.With(withs...)
+}
--- a/client/internal/services/core/database/database.go
+++ b/client/internal/services/core/database/database.go
@@ -21,6 +21,7 @@ type database struct {
 	options    core.Options
 	app        *application.Application
 	db         *sqlx.DB
+	logger     *slog.Logger
 	migrations map[string]fs.FS
 	dbPath     string
 	version    int64
@@ -51,7 +52,7 @@ func (d *database) Configure() error {

 	d.db = db

-	slog.Info("Database opened.", "path", d.dbPath)
+	d.logger.Info("Database opened.", "path", d.dbPath)

 	if err := d.initializeSysInfoHandler(); err != nil {
 		return fmt.Errorf("configure: %w", err)
@@ -93,6 +94,10 @@ func (d *database) ConnectDependencies() error {
 }

 func (d *database) Initialize() error {
+	d.logger = d.app.NewLogger("service", core.ServiceNameDatabase)
+
+	d.logger.Info("Initializing...")
+
 	d.migrations = make(map[string]fs.FS, 0)

 	return nil
--- a/client/internal/services/core/database/dbpath.go
+++ b/client/internal/services/core/database/dbpath.go
@@ -2,7 +2,6 @@ package database

 import (
 	"fmt"
-	"log/slog"
 	"os"
 	"path/filepath"

@@ -24,7 +23,7 @@ func (d *database) configureDBPath() error {

 	d.dbPath = filepath.Join(rootDir, "database.sqlite3")

-	slog.Info("Database path configured.", "path", d.dbPath)
+	d.logger.Info("Database path configured.", "path", d.dbPath)

 	return nil
 }
--- a/client/internal/services/core/database/migrations.go
+++ b/client/internal/services/core/database/migrations.go
@@ -9,6 +9,7 @@ import (
 	"strings"

 	"bunker/client/internal/services/core"
+	"bunker/commons"

 	"github.com/pressly/goose/v3"
 )
@@ -16,7 +17,7 @@ import (
 var errMigrationsAlreadyRegistered = errors.New("migrations already registered")

 func (d *database) applyMigrations() error {
-	slog.Info("Migrating database...")
+	d.logger.Info("Migrating database...")

 	modules := make([]string, 0)

@@ -28,8 +29,11 @@ func (d *database) applyMigrations() error {

 	_ = goose.SetDialect(string(goose.DialectSQLite3))

+	gooseLogger := commons.NewGooseLogger(d.logger)
+	goose.SetLogger(gooseLogger)
+
 	for _, module := range modules {
-		slog.Info("Migrating database for module...", "module", module)
+		d.logger.Info("Migrating database for module...", "module", module)

 		goose.SetBaseFS(d.migrations[module])
 		goose.SetTableName(strings.ReplaceAll(module, "/", "_") + "_migrations")
@@ -45,7 +49,7 @@ func (d *database) applyMigrations() error {

 		d.version += moduleDBVersion

-		slog.Info(
+		d.logger.Info(
 			"Database for module migrated to latest version",
 			"module", module,
 			"module_db_version", moduleDBVersion,
@@ -53,7 +57,7 @@ func (d *database) applyMigrations() error {
 		)
 	}

-	slog.Info("Database migrated.", "version", d.version)
+	d.logger.Info("Database migrated.", "version", d.version)

 	return nil
 }
--- a/client/internal/services/core/database/queries.go
+++ b/client/internal/services/core/database/queries.go
@@ -3,7 +3,6 @@ package database
 import (
 	"context"
 	"fmt"
-	"log/slog"
 	"strings"

 	"bunker/client/internal/services/core"
@@ -15,7 +14,7 @@ func (d *database) Exec(ctx context.Context, query string, params ...interface{}
 		query = d.db.Rebind(query)
 	}

-	slog.Debug("Executing query.", "query", query, "params", fmt.Sprintf("%+v", params), "module", "core/database")
+	d.logger.Debug("Executing query.", "query", query, "params", fmt.Sprintf("%+v", params), "module", "core/database")

 	if _, err := d.db.ExecContext(ctx, query, params...); err != nil {
 		return fmt.Errorf("%w: failed to Exec(): %w", core.ErrDatabase, err)
@@ -30,7 +29,7 @@ func (d *database) Get(ctx context.Context, target interface{}, query string, pa
 		query = d.db.Rebind(query)
 	}

-	slog.Debug(
+	d.logger.Debug(
 		"Getting single data from database with query.",
 		"query", query,
 		"params", fmt.Sprintf("%+v", params),
@@ -50,7 +49,7 @@ func (d *database) NamedExec(ctx context.Context, query string, param interface{
 		query = d.db.Rebind(query)
 	}

-	slog.Debug("Executing named query.", "query", query, "params", fmt.Sprintf("%+v", param), "module", "core/database")
+	d.logger.Debug("Executing named query.", "query", query, "params", fmt.Sprintf("%+v", param), "module", "core/database")

 	if _, err := d.db.NamedExecContext(ctx, query, param); err != nil {
 		return fmt.Errorf("%w: failed to NamedExec(): %w", core.ErrDatabase, err)
@@ -65,7 +64,7 @@ func (d *database) Select(ctx context.Context, target interface{}, query string,
 		query = d.db.Rebind(query)
 	}

-	slog.Debug(
+	d.logger.Debug(
 		"Selecting from database with query.",
 		"query", query,
 		"params", fmt.Sprintf("%+v", params),
--- a/client/internal/services/core/database/transaction.go
+++ b/client/internal/services/core/database/transaction.go
@@ -12,6 +12,7 @@ import (

 type transaction struct {
 	transaction *sqlx.Tx
+	logger      *slog.Logger
 }

 func (d *database) Transaction(ctx context.Context) (core.DatabaseTransaction, error) {
@@ -22,6 +23,7 @@ func (d *database) Transaction(ctx context.Context) (core.DatabaseTransaction, e

 	txHandler := &transaction{
 		transaction: txn,
+		logger:      d.logger.With("module", "transactioner"),
 	}

 	return txHandler, nil
@@ -30,7 +32,7 @@ func (d *database) Transaction(ctx context.Context) (core.DatabaseTransaction, e
 func (t *transaction) Apply(steps ...core.TransactionFunc) error {
 	for stepNumber, stepFunc := range steps {
 		if err := stepFunc(t.transaction); err != nil {
-			slog.Error(
+			t.logger.Error(
 				"Error occurred.",
 				"step", stepNumber,
 				"error", err.Error(),
@@ -39,7 +41,7 @@ func (t *transaction) Apply(steps ...core.TransactionFunc) error {
 			)

 			if rollbackErr := t.transaction.Rollback(); rollbackErr != nil {
-				slog.Error(
+				t.logger.Error(
 					"Transaction rollback failed.",
 					"error", err.Error(),
 					"module", "core/database",
@@ -54,7 +56,7 @@ func (t *transaction) Apply(steps ...core.TransactionFunc) error {
 	}

 	if err := t.transaction.Commit(); err != nil {
-		slog.Error(
+		t.logger.Error(
 			"Transaction commit failed.",
 			"error", err.Error(),
 			"module", "core/database",
@@ -62,7 +64,7 @@ func (t *transaction) Apply(steps ...core.TransactionFunc) error {
 		)

 		if rollbackErr := t.transaction.Rollback(); rollbackErr != nil {
-			slog.Error(
+			t.logger.Error(
 				"Transaction rollback failed.",
 				"error", err.Error(),
 				"module", "core/database",
--- a/client/internal/services/core/mainwindow/mainwindow.go
+++ b/client/internal/services/core/mainwindow/mainwindow.go
@@ -20,6 +20,7 @@ var _ = core.MainWindow(&mainWindow{})

 type mainWindow struct {
 	app             *application.Application
+	logger          *slog.Logger
 	window          fyne.Window
 	options         core.Options
 	tabs            *container.AppTabs
@@ -60,6 +61,10 @@ func (m *mainWindow) ConnectDependencies() error {
 }

 func (m *mainWindow) Initialize() error {
+	m.logger = m.app.NewLogger("service", core.ServiceNameMainWindow)
+
+	m.logger.Info("Initializing...")
+
 	m.sysInfoHandlers = make(map[string]*models.SysInfoHandler)

 	m.window = m.app.Fyne().NewWindow(lang.L("window.title"))
--- a/client/internal/services/core/mainwindow/mainwindow_menu.go
+++ b/client/internal/services/core/mainwindow/mainwindow_menu.go
@@ -1,15 +1,13 @@
 package mainwindow

 import (
-	"log/slog"
-
 	"fyne.io/fyne/v2"
 	"fyne.io/fyne/v2/lang"
 )

 func (m *mainWindow) initializeMenu() {
 	optionsMenuItem := fyne.NewMenuItem(lang.L("main_menu.file.options_menu_item"), func() {
-		slog.Info("Opening options...")
+		m.logger.Info("Opening options...")

 		m.options.ShowOptionsDialog()
 	})
--- a/client/internal/services/core/options/dialog.go
+++ b/client/internal/services/core/options/dialog.go
@@ -1,8 +1,6 @@
 package options

 import (
-	"log/slog"
-
 	"fyne.io/fyne/v2"
 	"fyne.io/fyne/v2/container"
 	"fyne.io/fyne/v2/dialog"
@@ -11,7 +9,7 @@ import (
 )

 func (o *options) closeOptionsDialog(save bool) {
-	slog.Debug("Closing options dialog.", "save", save)
+	o.logger.Debug("Closing options dialog.", "save", save)

 	if !save {
 		return
@@ -23,7 +21,7 @@ func (o *options) closeOptionsDialog(save bool) {
 		}

 		if err := widget.SaveHandler(); err != nil {
-			slog.Error("Failed to save options for module!", "module", widget.Name, "error", err.Error())
+			o.logger.Error("Failed to save options for module!", "module", widget.Name, "error", err.Error())
 		}
 	}
 }
--- a/client/internal/services/core/options/options.go
+++ b/client/internal/services/core/options/options.go
@@ -2,6 +2,7 @@ package options

 import (
 	"fmt"
+	"log/slog"

 	"bunker/client/internal/application"
 	"bunker/client/internal/services/core"
@@ -12,6 +13,7 @@ var _ = core.Options(&options{})

 type options struct {
 	app        *application.Application
+	logger     *slog.Logger
 	db         core.Database
 	mainWindow core.MainWindow

@@ -69,6 +71,10 @@ func (o *options) ConnectDependencies() error {
 }

 func (o *options) Initialize() error {
+	o.logger = o.app.NewLogger("service", core.ServiceNameOptions)
+
+	o.logger.Info("Initializing...")
+
 	o.widgets = make(map[string]*models.OptionPane)
 	o.widgetsItems = make([]string, 0)

--- a/client/internal/services/core/translations/sys_info_handler.go
+++ b/client/internal/services/core/translations/sys_info_handler.go
@@ -3,7 +3,6 @@ package translations
 import (
 	"encoding/json"
 	"fmt"
-	"log/slog"
 	"path/filepath"
 	"strings"

@@ -30,7 +29,7 @@ func (t *translations) sysInfoHandlerTranslationsLanguagesAndStringsCount() stri

 	entries, err := langfiles.LangFiles.ReadDir("files")
 	if err != nil {
-		slog.Error("Failed to read translations filesystem entries.", "error", err.Error())
+		t.logger.Error("Failed to read translations filesystem entries.", "error", err.Error())

 		return langString
 	}
@@ -43,7 +42,7 @@ func (t *translations) sysInfoHandlerTranslationsLanguagesAndStringsCount() stri
 		if strings.HasSuffix(entry.Name(), ".json") {
 			fileData, err := langfiles.LangFiles.ReadFile(filepath.Join("files", entry.Name()))
 			if err != nil {
-				slog.Error("Failed to read translation file!", "file", entry.Name(), "error", err.Error())
+				t.logger.Error("Failed to read translation file!", "file", entry.Name(), "error", err.Error())

 				return langString
 			}
@@ -51,7 +50,7 @@ func (t *translations) sysInfoHandlerTranslationsLanguagesAndStringsCount() stri
 			data := make(map[string]string)

 			if err := json.Unmarshal(fileData, &data); err != nil {
-				slog.Error("Failed to unmarshal translation file!", "file", entry.Name(), "error", err.Error())
+				t.logger.Error("Failed to unmarshal translation file!", "file", entry.Name(), "error", err.Error())

 				return langString
 			}
--- a/client/internal/services/core/translations/translations.go
+++ b/client/internal/services/core/translations/translations.go
@@ -16,6 +16,7 @@ var _ = core.Translations(&translations{})

 type translations struct {
 	app        *application.Application
+	logger     *slog.Logger
 	mainWindow core.MainWindow
 }

@@ -57,9 +58,13 @@ func (t *translations) ConnectDependencies() error {
 }

 func (t *translations) Initialize() error {
+	t.logger = t.app.NewLogger("service", core.ServiceNameTranslations)
+
+	t.logger.Info("Initializing...")
+
 	langFromEnv, _ := os.LookupEnv("LANG")

-	slog.Info("Current system locale.", "locale", lang.SystemLocale().String(), "LANG", langFromEnv)
+	t.logger.Info("Current system locale.", "locale", lang.SystemLocale().String(), "LANG", langFromEnv)

 	if err := lang.AddTranslationsFS(langfiles.LangFiles, "files"); err != nil {
 		return fmt.Errorf("%w: load translations: %w", core.ErrTranslations, err)
--- a/commons/goose_logger.go
+++ b/commons/goose_logger.go
@@ -0,0 +1,26 @@
+package commons
+
+import (
+	"fmt"
+	"log/slog"
+)
+
+// GooseLogger is a proxy struct that wraps Bunker logging for goose database migrator.
+type GooseLogger struct {
+	logger *slog.Logger
+}
+
+// NewGooseLogger creates proxy structure for goose database migrator logging.
+func NewGooseLogger(logger *slog.Logger) *GooseLogger {
+	return &GooseLogger{
+		logger: logger.With("module", "goose"),
+	}
+}
+
+func (gl *GooseLogger) Fatalf(format string, v ...interface{}) {
+	gl.logger.Error(fmt.Sprintf(format, v...))
+}
+
+func (gl *GooseLogger) Printf(format string, v ...interface{}) {
+	gl.logger.Info(fmt.Sprintf(format, v...))
+}