From 4053d67f4932a3293117df8ac6dfa3dc66423deb Mon Sep 17 00:00:00 2001 From: Mik Mueller <83001409+MikMuellerDev@users.noreply.github.com> Date: Sun, 22 May 2022 22:43:20 +0200 Subject: [PATCH] Modified startup log messages --- core/config/setup.go | 10 +++++----- core/database/connection.go | 8 ++++---- core/database/init.go | 14 +++++++++----- core/event/event.go | 4 ++-- core/hardware/handler.go | 1 + core/scheduler/automation/automation.go | 22 ++++++++++++++-------- server/middleware/sessions.go | 1 + server/routes/routes.go | 1 + server/templates/templates.go | 4 ++-- 9 files changed, 39 insertions(+), 26 deletions(-) diff --git a/core/config/setup.go b/core/config/setup.go index 44e465f6..58802ee9 100644 --- a/core/config/setup.go +++ b/core/config/setup.go @@ -20,7 +20,7 @@ var setupPath = "./data/config/setup.json" // TODO: add some sort of web import / export later // Returns the setup struct, a bool that indicates that a setup file has been read and an error func readSetupFile() (Setup, bool, error) { - log.Trace("Looking for `setup.json`") + log.Trace(fmt.Sprintf("Detecting setup file at `%s`", setupPath)) // Read file from on disk content, err := ioutil.ReadFile(setupPath) if err != nil { @@ -48,18 +48,18 @@ func RunSetup() error { return err } if !shouldProceed { - log.Debug("No setup file found: starting without setup.") + log.Debug("No setup file detected: skipping setup") return nil } if err := createRoomsInDatabase(setup.Rooms); err != nil { - log.Error("Aborting setup: could not create room entries in database: ", err.Error()) + log.Error("Aborting setup: could not create rooms in database: ", err.Error()) return err } if err := createHardwareNodesInDatabase(setup.HardwareNodes); err != nil { - log.Error("Aborting setup: could not create hardware node entries in database: ", err.Error()) + log.Error("Aborting setup: could not create hardware nodes in database: ", err.Error()) return err } - log.Info("Successfully ran setup") + log.Info(fmt.Sprintf("Successfully ran setup using `%s`", setupPath)) return nil } diff --git a/core/database/connection.go b/core/database/connection.go index c8ec43f8..61ab7310 100644 --- a/core/database/connection.go +++ b/core/database/connection.go @@ -15,17 +15,17 @@ func databaseConnectionString() string { func connection() (*sql.DB, error) { dbTemp, err := sql.Open("mysql", databaseConnectionString()) if err != nil { - log.Error("Could not connect to Database: ", err.Error()) + log.Error("Could not setup database connection: pre-connection error: ", err.Error()) return nil, err } ctx, cancelfunc := context.WithTimeout(context.Background(), 5*time.Second) defer cancelfunc() err = dbTemp.PingContext(ctx) if err != nil { - log.Error("Could not connect to database: ping failed: ", err.Error()) + log.Error("Could not establish database connection: pinging database failed: ", err.Error()) return nil, err } - log.Debug(fmt.Sprintf("Successfully connected to database `%s`", config.Database)) + log.Debug(fmt.Sprintf("Successfully established connection to database `%s`", config.Database)) return dbTemp, nil } @@ -34,7 +34,7 @@ func CheckDatabase() error { ctx, cancelfunc := context.WithTimeout(context.Background(), 5*time.Second) defer cancelfunc() if err := db.PingContext(ctx); err != nil { - log.Error("Database health check failed: ", err.Error()) + log.Error("database health-check using ping failed: ", err.Error()) return err } return nil diff --git a/core/database/init.go b/core/database/init.go index 23094f79..2f341dfb 100644 --- a/core/database/init.go +++ b/core/database/init.go @@ -10,6 +10,7 @@ import ( ) func Init(databaseConfig DatabaseConfig, adminPassword string) error { + log.Trace("Initializing database connection...") config = databaseConfig if err := createDatabase(); err != nil { return err @@ -18,6 +19,7 @@ func Init(databaseConfig DatabaseConfig, adminPassword string) error { if err != nil { return err } + log.Trace("Initializing database schema...") db = dbTemp if err := createConfigTable(); err != nil { return err @@ -76,13 +78,14 @@ func Init(databaseConfig DatabaseConfig, adminPassword string) error { if err := createHasCameraPermissionsTable(); err != nil { return err } + log.Info(fmt.Sprintf("Successfully initialized database `%s`", databaseConfig.Database)) return nil } func createDatabase() error { dbTemp, err := sql.Open("mysql", fmt.Sprintf("%s:%s@tcp(%s:%d)/", config.Username, config.Password, config.Hostname, config.Port)) if err != nil { - log.Error("Could not connect to Database: ", err.Error()) + log.Error("Could not connect to intermediate database: ", err.Error()) return err } defer dbTemp.Close() @@ -90,18 +93,19 @@ func createDatabase() error { defer cancelfunc() res, err := dbTemp.ExecContext(ctx, "CREATE DATABASE IF NOT EXISTS "+config.Database) if err != nil { - log.Error(fmt.Sprintf("Failed to create database `%s`: Query execution error: %s", config.Database, err.Error())) + log.Error(fmt.Sprintf("Failed to create database `%s`: executing query failed: %s", config.Database, err.Error())) return err } + log.Trace("Successfully connected to database using intermediate connection") rowsAffected, err := res.RowsAffected() if err != nil { - log.Error(fmt.Sprintf("Failed to get result of `create database` `%s`: Reading rows affected failed with error: %s", config.Database, err.Error())) + log.Error(fmt.Sprintf("Failed to evaluate outcome of database creation: reading rows affected failed: %s", err.Error())) return err } if rowsAffected == 1 { - log.Info(fmt.Sprintf("Successfully initialized database `%s`", config.Database)) + log.Info(fmt.Sprintf("Successfully created new database `%s`", config.Database)) } else { - log.Debug(fmt.Sprintf("Using existing database `%s`", config.Database)) + log.Debug(fmt.Sprintf("Skipped database creation: using existing database `%s`", config.Database)) } return nil } diff --git a/core/event/event.go b/core/event/event.go index 1595017e..ad74b779 100644 --- a/core/event/event.go +++ b/core/event/event.go @@ -63,11 +63,11 @@ func Fatal(name string, description string) { } func FlushOldLogs() error { - log.Debug("Flushing logs older than 30 days") + log.Trace("Flushing logs older than 30 days...") return database.FlushOldLogs() } func FlushAllLogs() error { - log.Debug("Flushing all logs") + log.Trace("Flushing all logs...") return database.FlushAllLogs() } diff --git a/core/hardware/handler.go b/core/hardware/handler.go index 5cbb1611..56bc82e6 100644 --- a/core/hardware/handler.go +++ b/core/hardware/handler.go @@ -189,6 +189,7 @@ func Init() { // Initialize thread-safe variables, for more info, look at the top for mutexes jobsWithErrorInHandlerCount.Store(0) daemonRunning.Store(false) + log.Debug("Initialized hardware handler and job scheduler") } // Returns the number of currently pending jobs in the queue diff --git a/core/scheduler/automation/automation.go b/core/scheduler/automation/automation.go index 3059af9e..0b8f9076 100644 --- a/core/scheduler/automation/automation.go +++ b/core/scheduler/automation/automation.go @@ -8,6 +8,7 @@ import ( "github.com/sirupsen/logrus" "github.com/smarthome-go/smarthome/core/database" + "github.com/smarthome-go/smarthome/core/user" ) // The scheduler which will run all predefined automation jobs @@ -32,23 +33,28 @@ func ActivateAutomationSystem() error { for _, automation := range automations { if !IsValidCronExpression(automation.Data.CronExpression) { log.Error(fmt.Sprintf("Could not activate automation '%d': invalid cron expression", automation.Id)) - continue // non-critical error + if err := user.Notify(automation.Owner, "Automation Activation Failed", fmt.Sprintf("The automation %s could not be activated due to an internall error. Please remove it from the system.", automation.Data.Name), 3); err != nil { + log.Error("Failed to notify user about failing automation: ", err.Error()) + } + continue // non-critical error, will only affect this automation } if !automation.Data.Enabled { - log.Debug(fmt.Sprintf("Skipping activation of automation %d: automation is disabled", automation.Id)) + log.Debug(fmt.Sprintf("Skipping activation of automation '%d': automation is disabled", automation.Id)) continue // Skip disabled automations } automationJob := scheduler.Cron(automation.Data.CronExpression) automationJob.Tag(fmt.Sprintf("%d", automation.Id)) _, err := automationJob.Do(automationRunnerFunc, automation.Id) if err != nil { - log.Error("Failed to register cron job: ", err.Error()) + log.Error(fmt.Sprintf("Could not activate automation '%d': failed to register cron job: %s", automation.Id, err.Error())) return err } activatedItems += 1 log.Debug(fmt.Sprintf("Successfully activated automation '%d' of user '%s'", automation.Id, automation.Owner)) } - log.Debug(fmt.Sprintf("Activated saved automations: registered %d total automation jobs", activatedItems)) + if activatedItems > 0 { + log.Info(fmt.Sprintf("Successfully activated saved automations: registered %d total automation jobs", activatedItems)) + } return nil } @@ -62,7 +68,7 @@ func DeactivateAutomationSystem() error { for _, automation := range automations { if automation.Data.Enabled { if err := scheduler.RemoveByTag(fmt.Sprintf("%d", automation.Id)); err != nil { - log.Error(fmt.Sprintf("Failed to deactivate automation '%d': could not stop scheduler: %s", automation.Id, err.Error())) + log.Error(fmt.Sprintf("Failed to deactivate automation '%d': could not stop scheduler: '%s'", automation.Id, err.Error())) continue } log.Debug(fmt.Sprintf("Successfully deactivated automation '%d' of user '%s'", automation.Id, automation.Owner)) @@ -80,7 +86,7 @@ func Init() error { return err } if !found { - log.Error("Failed to initialize automation scheduler: could not retrieve server configuration: no results in query") + log.Error("Failed to initialize automation scheduler: could not retrieve server configuration: no results for server config") return err } scheduler = gocron.NewScheduler(time.Local) @@ -90,9 +96,9 @@ func Init() error { log.Error("Failed to activate automation system: could not activate persistent jobs: ", err.Error()) return err } - log.Info("Successfully activated automation scheduler system") + log.Info("Successfully activated automation system") } else { - log.Info("Not activating scheduler automation system because it is disabled") + log.Info("Skipping activation of automation system due to it being disabled") } scheduler.StartAsync() return nil diff --git a/server/middleware/sessions.go b/server/middleware/sessions.go index 8fff668c..a6c852e8 100644 --- a/server/middleware/sessions.go +++ b/server/middleware/sessions.go @@ -17,4 +17,5 @@ func Init(useRandomSeed bool) { log.Warn("\x1b[33mUsing static session encryption. This is a security risk.") Store = sessions.NewCookieStore([]byte("")) } + log.Debug("Successfully initialized middleware session store") } diff --git a/server/routes/routes.go b/server/routes/routes.go index 31365bb2..dd377f60 100644 --- a/server/routes/routes.go +++ b/server/routes/routes.go @@ -19,6 +19,7 @@ func InitLogger(logger *logrus.Logger) { } func NewRouter() *mux.Router { + log.Trace("Initializing server router...") r := mux.NewRouter() // Auth: middleware that checks if the user is logged in, will redirect to `/login` if the user is not logged in // ApiAuth: middleware that checks if the user is logged in for API request, will return JSON errors if the user is not logged in diff --git a/server/templates/templates.go b/server/templates/templates.go index a69e3d64..effaadc5 100644 --- a/server/templates/templates.go +++ b/server/templates/templates.go @@ -18,12 +18,12 @@ var templates *template.Template func LoadTemplates(pattern string) { templates = template.Must(template.ParseGlob(pattern)) - log.Debug(fmt.Sprintf("Templates loaded: %s", pattern)) + log.Debug(fmt.Sprintf("Successfully loaded templates using pattern: %s", pattern)) } func ExecuteTemplate(responseWriter http.ResponseWriter, templateName string, data interface{}) { if err := templates.ExecuteTemplate(responseWriter, templateName, data); err != nil { - log.Error("Could not render template: ", err.Error()) + log.Error(fmt.Sprintf("Could not render template '%s': %s", templateName, err.Error())) return } }