Structured logging (#8673)

* Implementing structured logging

* Changes to en.json to allow refactor to run.

* Fixing global logger

* Structured logger initalization.

* Add caller.

* Do some log redirection.

* Auto refactor

* Cleaning up l4g reference and removing dependancy.

* Removing junk.

* Copyright headers.

* Fixing tests

* Revert "Changes to en.json to allow refactor to run."

This reverts commit fd8249e99bcad0231e6ea65cd77c32aae9a54026.

* Fixing some auto refactor strangeness and typo.

* Making keys more human readable.

1 files changed, 33 insertions, 33 deletions

diff --git a/store/sqlstore/supplier.go b/store/sqlstore/supplier.go
index 8f37db0cd..69b30be59 100644
--- a/store/sqlstore/supplier.go
+++ b/store/sqlstore/supplier.go
@@ -15,11 +15,11 @@ import (
 	"sync/atomic"
 	"time"
 
-	l4g "github.com/alecthomas/log4go"
 	"github.com/go-sql-driver/mysql"
 	"github.com/lib/pq"
 	"github.com/mattermost/gorp"
 	"github.com/mattermost/mattermost-server/einterfaces"
+	"github.com/mattermost/mattermost-server/mlog"
 	"github.com/mattermost/mattermost-server/model"
 	"github.com/mattermost/mattermost-server/store"
 	"github.com/mattermost/mattermost-server/utils"
@@ -144,7 +144,7 @@ func NewSqlSupplier(settings model.SqlSettings, metrics einterfaces.MetricsInter
 
 	err := supplier.GetMaster().CreateTablesIfNotExists()
 	if err != nil {
-		l4g.Critical(utils.T("store.sql.creating_tables.critical"), err)
+		mlog.Critical(fmt.Sprintf("Error creating database tables: %v", err))
 		time.Sleep(time.Second)
 		os.Exit(EXIT_CREATE_TABLE)
 	}
@@ -189,13 +189,13 @@ func (s *SqlSupplier) Next() store.LayeredStoreSupplier {
 func setupConnection(con_type string, dataSource string, settings *model.SqlSettings) *gorp.DbMap {
 	db, err := dbsql.Open(*settings.DriverName, dataSource)
 	if err != nil {
-		l4g.Critical("Failed to open SQL connection to err:%v", err.Error())
+		mlog.Critical(fmt.Sprintf("Failed to open SQL connection to err:%v", err.Error()))
 		time.Sleep(time.Second)
 		os.Exit(EXIT_DB_OPEN)
 	}
 
 	for i := 0; i < DB_PING_ATTEMPTS; i++ {
-		l4g.Info("Pinging SQL %v database", con_type)
+		mlog.Info(fmt.Sprintf("Pinging SQL %v database", con_type))
 		ctx, cancel := context.WithTimeout(context.Background(), DB_PING_TIMEOUT_SECS*time.Second)
 		defer cancel()
 		err = db.PingContext(ctx)
@@ -203,11 +203,11 @@ func setupConnection(con_type string, dataSource string, settings *model.SqlSett
 			break
 		} else {
 			if i == DB_PING_ATTEMPTS-1 {
-				l4g.Critical("Failed to ping DB, server will exit err=%v", err)
+				mlog.Critical(fmt.Sprintf("Failed to ping DB, server will exit err=%v", err))
 				time.Sleep(time.Second)
 				os.Exit(EXIT_PING)
 			} else {
-				l4g.Error("Failed to ping DB retrying in %v seconds err=%v", DB_PING_TIMEOUT_SECS, err)
+				mlog.Error(fmt.Sprintf("Failed to ping DB retrying in %v seconds err=%v", DB_PING_TIMEOUT_SECS, err))
 				time.Sleep(DB_PING_TIMEOUT_SECS * time.Second)
 			}
 		}
@@ -228,7 +228,7 @@ func setupConnection(con_type string, dataSource string, settings *model.SqlSett
 	} else if *settings.DriverName == model.DATABASE_DRIVER_POSTGRES {
 		dbmap = &gorp.DbMap{Db: db, TypeConverter: mattermConverter{}, Dialect: gorp.PostgresDialect{}, QueryTimeout: connectionTimeout}
 	} else {
-		l4g.Critical(utils.T("store.sql.dialect_driver.critical"))
+		mlog.Critical("Failed to create dialect specific driver")
 		time.Sleep(time.Second)
 		os.Exit(EXIT_NO_DRIVER)
 	}
@@ -338,7 +338,7 @@ func (ss *SqlSupplier) DoesTableExist(tableName string) bool {
 		)
 
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.table_exists.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to check if table exists %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_TABLE_EXISTS)
 		}
@@ -360,7 +360,7 @@ func (ss *SqlSupplier) DoesTableExist(tableName string) bool {
 		)
 
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.table_exists.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to check if table exists %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_TABLE_EXISTS_MYSQL)
 		}
@@ -382,7 +382,7 @@ func (ss *SqlSupplier) DoesTableExist(tableName string) bool {
 		return count > 0
 
 	} else {
-		l4g.Critical(utils.T("store.sql.column_exists_missing_driver.critical"))
+		mlog.Critical("Failed to check if column exists because of missing driver")
 		time.Sleep(time.Second)
 		os.Exit(EXIT_COLUMN_EXISTS)
 		return false
@@ -406,7 +406,7 @@ func (ss *SqlSupplier) DoesColumnExist(tableName string, columnName string) bool
 				return false
 			}
 
-			l4g.Critical(utils.T("store.sql.column_exists.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to check if column exists %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_DOES_COLUMN_EXISTS_POSTGRES)
 		}
@@ -429,7 +429,7 @@ func (ss *SqlSupplier) DoesColumnExist(tableName string, columnName string) bool
 		)
 
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.column_exists.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to check if column exists %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_DOES_COLUMN_EXISTS_MYSQL)
 		}
@@ -452,7 +452,7 @@ func (ss *SqlSupplier) DoesColumnExist(tableName string, columnName string) bool
 		return count > 0
 
 	} else {
-		l4g.Critical(utils.T("store.sql.column_exists_missing_driver.critical"))
+		mlog.Critical("Failed to check if column exists because of missing driver")
 		time.Sleep(time.Second)
 		os.Exit(EXIT_DOES_COLUMN_EXISTS_MISSING)
 		return false
@@ -468,7 +468,7 @@ func (ss *SqlSupplier) CreateColumnIfNotExists(tableName string, columnName stri
 	if ss.DriverName() == model.DATABASE_DRIVER_POSTGRES {
 		_, err := ss.GetMaster().ExecNoTimeout("ALTER TABLE " + tableName + " ADD " + columnName + " " + postgresColType + " DEFAULT '" + defaultValue + "'")
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.create_column.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to create column %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_CREATE_COLUMN_POSTGRES)
 		}
@@ -478,7 +478,7 @@ func (ss *SqlSupplier) CreateColumnIfNotExists(tableName string, columnName stri
 	} else if ss.DriverName() == model.DATABASE_DRIVER_MYSQL {
 		_, err := ss.GetMaster().ExecNoTimeout("ALTER TABLE " + tableName + " ADD " + columnName + " " + mySqlColType + " DEFAULT '" + defaultValue + "'")
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.create_column.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to create column %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_CREATE_COLUMN_MYSQL)
 		}
@@ -486,7 +486,7 @@ func (ss *SqlSupplier) CreateColumnIfNotExists(tableName string, columnName stri
 		return true
 
 	} else {
-		l4g.Critical(utils.T("store.sql.create_column_missing_driver.critical"))
+		mlog.Critical("Failed to create column because of missing driver")
 		time.Sleep(time.Second)
 		os.Exit(EXIT_CREATE_COLUMN_MISSING)
 		return false
@@ -501,7 +501,7 @@ func (ss *SqlSupplier) RemoveColumnIfExists(tableName string, columnName string)
 
 	_, err := ss.GetMaster().ExecNoTimeout("ALTER TABLE " + tableName + " DROP COLUMN " + columnName)
 	if err != nil {
-		l4g.Critical("Failed to drop column %v", err)
+		mlog.Critical(fmt.Sprintf("Failed to drop column %v", err))
 		time.Sleep(time.Second)
 		os.Exit(EXIT_REMOVE_COLUMN)
 	}
@@ -516,7 +516,7 @@ func (ss *SqlSupplier) RemoveTableIfExists(tableName string) bool {
 
 	_, err := ss.GetMaster().ExecNoTimeout("DROP TABLE " + tableName)
 	if err != nil {
-		l4g.Critical("Failed to drop table %v", err)
+		mlog.Critical(fmt.Sprintf("Failed to drop table %v", err))
 		time.Sleep(time.Second)
 		os.Exit(EXIT_REMOVE_TABLE)
 	}
@@ -537,7 +537,7 @@ func (ss *SqlSupplier) RenameColumnIfExists(tableName string, oldColumnName stri
 	}
 
 	if err != nil {
-		l4g.Critical(utils.T("store.sql.rename_column.critical"), err)
+		mlog.Critical(fmt.Sprintf("Failed to rename column %v", err))
 		time.Sleep(time.Second)
 		os.Exit(EXIT_RENAME_COLUMN)
 	}
@@ -559,7 +559,7 @@ func (ss *SqlSupplier) GetMaxLengthOfColumnIfExists(tableName string, columnName
 	}
 
 	if err != nil {
-		l4g.Critical(utils.T("store.sql.maxlength_column.critical"), err)
+		mlog.Critical(fmt.Sprintf("Failed to get max length of column %v", err))
 		time.Sleep(time.Second)
 		os.Exit(EXIT_MAX_COLUMN)
 	}
@@ -580,7 +580,7 @@ func (ss *SqlSupplier) AlterColumnTypeIfExists(tableName string, columnName stri
 	}
 
 	if err != nil {
-		l4g.Critical(utils.T("store.sql.alter_column_type.critical"), err)
+		mlog.Critical(fmt.Sprintf("Failed to alter column type %v", err))
 		time.Sleep(time.Second)
 		os.Exit(EXIT_ALTER_COLUMN)
 	}
@@ -621,7 +621,7 @@ func (ss *SqlSupplier) createIndexIfNotExists(indexName string, tableName string
 		query := ""
 		if indexType == INDEX_TYPE_FULL_TEXT {
 			if len(columnNames) != 1 {
-				l4g.Critical("Unable to create multi column full text index")
+				mlog.Critical("Unable to create multi column full text index")
 				os.Exit(EXIT_CREATE_INDEX_POSTGRES)
 			}
 			columnName := columnNames[0]
@@ -633,7 +633,7 @@ func (ss *SqlSupplier) createIndexIfNotExists(indexName string, tableName string
 
 		_, err := ss.GetMaster().ExecNoTimeout(query)
 		if err != nil {
-			l4g.Critical("Failed to create index %v, %v", errExists, err)
+			mlog.Critical(fmt.Sprintf("Failed to create index %v, %v", errExists, err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_CREATE_INDEX_POSTGRES)
 		}
@@ -641,7 +641,7 @@ func (ss *SqlSupplier) createIndexIfNotExists(indexName string, tableName string
 
 		count, err := ss.GetMaster().SelectInt("SELECT COUNT(0) AS index_exists FROM information_schema.statistics WHERE TABLE_SCHEMA = DATABASE() and table_name = ? AND index_name = ?", tableName, indexName)
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.check_index.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to check index %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_CREATE_INDEX_MYSQL)
 		}
@@ -657,19 +657,19 @@ func (ss *SqlSupplier) createIndexIfNotExists(indexName string, tableName string
 
 		_, err = ss.GetMaster().ExecNoTimeout("CREATE  " + uniqueStr + fullTextIndex + " INDEX " + indexName + " ON " + tableName + " (" + strings.Join(columnNames, ", ") + ")")
 		if err != nil {
-			l4g.Critical("Failed to create index %v", err)
+			mlog.Critical(fmt.Sprintf("Failed to create index %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_CREATE_INDEX_FULL_MYSQL)
 		}
 	} else if ss.DriverName() == model.DATABASE_DRIVER_SQLITE {
 		_, err := ss.GetMaster().ExecNoTimeout("CREATE INDEX IF NOT EXISTS " + indexName + " ON " + tableName + " (" + strings.Join(columnNames, ", ") + ")")
 		if err != nil {
-			l4g.Critical("Failed to create index %v", err)
+			mlog.Critical(fmt.Sprintf("Failed to create index %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_CREATE_INDEX_SQLITE)
 		}
 	} else {
-		l4g.Critical(utils.T("store.sql.create_index_missing_driver.critical"))
+		mlog.Critical("Failed to create index because of missing driver")
 		time.Sleep(time.Second)
 		os.Exit(EXIT_CREATE_INDEX_MISSING)
 	}
@@ -688,7 +688,7 @@ func (ss *SqlSupplier) RemoveIndexIfExists(indexName string, tableName string) b
 
 		_, err = ss.GetMaster().ExecNoTimeout("DROP INDEX " + indexName)
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.remove_index.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to remove index %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_REMOVE_INDEX_POSTGRES)
 		}
@@ -698,7 +698,7 @@ func (ss *SqlSupplier) RemoveIndexIfExists(indexName string, tableName string) b
 
 		count, err := ss.GetMaster().SelectInt("SELECT COUNT(0) AS index_exists FROM information_schema.statistics WHERE TABLE_SCHEMA = DATABASE() and table_name = ? AND index_name = ?", tableName, indexName)
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.check_index.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to check index %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_REMOVE_INDEX_MYSQL)
 		}
@@ -709,19 +709,19 @@ func (ss *SqlSupplier) RemoveIndexIfExists(indexName string, tableName string) b
 
 		_, err = ss.GetMaster().ExecNoTimeout("DROP INDEX " + indexName + " ON " + tableName)
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.remove_index.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to remove index %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_REMOVE_INDEX_MYSQL)
 		}
 	} else if ss.DriverName() == model.DATABASE_DRIVER_SQLITE {
 		_, err := ss.GetMaster().ExecNoTimeout("DROP INDEX IF EXISTS " + indexName)
 		if err != nil {
-			l4g.Critical(utils.T("store.sql.remove_index.critical"), err)
+			mlog.Critical(fmt.Sprintf("Failed to remove index %v", err))
 			time.Sleep(time.Second)
 			os.Exit(EXIT_REMOVE_INDEX_SQLITE)
 		}
 	} else {
-		l4g.Critical(utils.T("store.sql.create_index_missing_driver.critical"))
+		mlog.Critical("Failed to create index because of missing driver")
 		time.Sleep(time.Second)
 		os.Exit(EXIT_REMOVE_INDEX_MISSING)
 	}
@@ -758,7 +758,7 @@ func (ss *SqlSupplier) GetAllConns() []*gorp.DbMap {
 }
 
 func (ss *SqlSupplier) Close() {
-	l4g.Info(utils.T("store.sql.closing.info"))
+	mlog.Info("Closing SqlStore")
 	ss.master.Db.Close()
 	for _, replica := range ss.replicas {
 		replica.Db.Close()