Modified startup log messages

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

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

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,32 +78,34 @@ 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()
 	ctx, cancelfunc := context.WithTimeout(context.Background(), 5*time.Second)
 	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
 }

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

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

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

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

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

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