From 686c2fbab7607d42183ae685a27ea3d7dce8c3f6 Mon Sep 17 00:00:00 2001 From: Christopher Speller Date: Fri, 27 Apr 2018 12:49:45 -0700 Subject: 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. --- store/layered_store.go | 4 +- store/redis_supplier.go | 4 +- store/redis_supplier_reactions.go | 11 ++--- store/redis_supplier_roles.go | 17 ++++--- store/sqlstore/channel_member_history_store.go | 5 +- store/sqlstore/channel_store.go | 4 +- store/sqlstore/command_webhook_store.go | 7 ++- store/sqlstore/post_store.go | 14 +++--- store/sqlstore/preference_store.go | 4 +- store/sqlstore/session_store.go | 9 ++-- store/sqlstore/store_test.go | 10 ++++ store/sqlstore/supplier.go | 66 +++++++++++++------------- store/sqlstore/supplier_reactions.go | 7 ++- store/sqlstore/tokens_store.go | 7 ++- store/sqlstore/upgrade.go | 23 +++++---- store/store.go | 4 +- store/storetest/docker.go | 11 ++--- 17 files changed, 105 insertions(+), 102 deletions(-) (limited to 'store') diff --git a/store/layered_store.go b/store/layered_store.go index 5ef907260..a0a31fb39 100644 --- a/store/layered_store.go +++ b/store/layered_store.go @@ -6,8 +6,8 @@ package store import ( "context" - l4g "github.com/alecthomas/log4go" "github.com/mattermost/mattermost-server/einterfaces" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" ) @@ -42,7 +42,7 @@ func NewLayeredStore(db LayeredStoreDatabaseLayer, metrics einterfaces.MetricsIn // Setup the chain if ENABLE_EXPERIMENTAL_REDIS { - l4g.Debug("Experimental redis enabled.") + mlog.Debug("Experimental redis enabled.") store.RedisLayer = NewRedisSupplier() store.RedisLayer.SetChainNext(store.DatabaseLayer) store.LayerChainHead = store.RedisLayer diff --git a/store/redis_supplier.go b/store/redis_supplier.go index 751227be9..ce8cb0f0d 100644 --- a/store/redis_supplier.go +++ b/store/redis_supplier.go @@ -9,8 +9,8 @@ import ( "time" - l4g "github.com/alecthomas/log4go" "github.com/go-redis/redis" + "github.com/mattermost/mattermost-server/mlog" ) const REDIS_EXPIRY_TIME = 30 * time.Minute @@ -45,7 +45,7 @@ func NewRedisSupplier() *RedisSupplier { }) if _, err := supplier.client.Ping().Result(); err != nil { - l4g.Error("Unable to ping redis server: " + err.Error()) + mlog.Error("Unable to ping redis server: " + err.Error()) return nil } diff --git a/store/redis_supplier_reactions.go b/store/redis_supplier_reactions.go index cece8113d..ec9a4b4e0 100644 --- a/store/redis_supplier_reactions.go +++ b/store/redis_supplier_reactions.go @@ -6,21 +6,20 @@ package store import ( "context" - l4g "github.com/alecthomas/log4go" - + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" ) func (s *RedisSupplier) ReactionSave(ctx context.Context, reaction *model.Reaction, hints ...LayeredStoreHint) *LayeredStoreSupplierResult { if err := s.client.Del("reactions:" + reaction.PostId).Err(); err != nil { - l4g.Error("Redis failed to remove key reactions:" + reaction.PostId + " Error: " + err.Error()) + mlog.Error("Redis failed to remove key reactions:" + reaction.PostId + " Error: " + err.Error()) } return s.Next().ReactionSave(ctx, reaction, hints...) } func (s *RedisSupplier) ReactionDelete(ctx context.Context, reaction *model.Reaction, hints ...LayeredStoreHint) *LayeredStoreSupplierResult { if err := s.client.Del("reactions:" + reaction.PostId).Err(); err != nil { - l4g.Error("Redis failed to remove key reactions:" + reaction.PostId + " Error: " + err.Error()) + mlog.Error("Redis failed to remove key reactions:" + reaction.PostId + " Error: " + err.Error()) } return s.Next().ReactionDelete(ctx, reaction, hints...) } @@ -34,13 +33,13 @@ func (s *RedisSupplier) ReactionGetForPost(ctx context.Context, postId string, h return result } if err != nil { - l4g.Error("Redis encountered an error on read: " + err.Error()) + mlog.Error("Redis encountered an error on read: " + err.Error()) } result := s.Next().ReactionGetForPost(ctx, postId, hints...) if err := s.save("reactions:"+postId, result.Data, REDIS_EXPIRY_TIME); err != nil { - l4g.Error("Redis encountered and error on write: " + err.Error()) + mlog.Error("Redis encountered and error on write: " + err.Error()) } return result diff --git a/store/redis_supplier_roles.go b/store/redis_supplier_roles.go index 232a8c040..c53614113 100644 --- a/store/redis_supplier_roles.go +++ b/store/redis_supplier_roles.go @@ -7,8 +7,7 @@ import ( "context" "fmt" - l4g "github.com/alecthomas/log4go" - + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" ) @@ -16,7 +15,7 @@ func (s *RedisSupplier) RoleSave(ctx context.Context, role *model.Role, hints .. key := buildRedisKeyForRoleName(role.Name) if err := s.client.Del(key).Err(); err != nil { - l4g.Error("Redis failed to remove key " + key + " Error: " + err.Error()) + mlog.Error("Redis failed to remove key " + key + " Error: " + err.Error()) } return s.Next().RoleSave(ctx, role, hints...) @@ -34,7 +33,7 @@ func (s *RedisSupplier) RoleGetByName(ctx context.Context, name string, hints .. var role *model.Role found, err := s.load(key, &role) if err != nil { - l4g.Error("Redis encountered an error on read: " + err.Error()) + mlog.Error("Redis encountered an error on read: " + err.Error()) } else if found { result := NewSupplierResult() result.Data = role @@ -45,7 +44,7 @@ func (s *RedisSupplier) RoleGetByName(ctx context.Context, name string, hints .. if result.Err == nil { if err := s.save(key, result.Data, REDIS_EXPIRY_TIME); err != nil { - l4g.Error("Redis encountered and error on write: " + err.Error()) + mlog.Error("Redis encountered and error on write: " + err.Error()) } } @@ -64,7 +63,7 @@ func (s *RedisSupplier) RoleGetByNames(ctx context.Context, roleNames []string, } else { rolesToQuery = append(rolesToQuery, roleName) if err != nil { - l4g.Error("Redis encountered an error on read: " + err.Error()) + mlog.Error("Redis encountered an error on read: " + err.Error()) } } } @@ -75,7 +74,7 @@ func (s *RedisSupplier) RoleGetByNames(ctx context.Context, roleNames []string, rolesFound := result.Data.([]*model.Role) for _, role := range rolesFound { if err := s.save(buildRedisKeyForRoleName(role.Name), role, REDIS_EXPIRY_TIME); err != nil { - l4g.Error("Redis encountered and error on write: " + err.Error()) + mlog.Error("Redis encountered and error on write: " + err.Error()) } } result.Data = append(foundRoles, result.Data.([]*model.Role)...) @@ -87,10 +86,10 @@ func (s *RedisSupplier) RoleGetByNames(ctx context.Context, roleNames []string, func (s *RedisSupplier) RolePermanentDeleteAll(ctx context.Context, hints ...LayeredStoreHint) *LayeredStoreSupplierResult { defer func() { if keys, err := s.client.Keys("roles:*").Result(); err != nil { - l4g.Error("Redis encountered an error on read: " + err.Error()) + mlog.Error("Redis encountered an error on read: " + err.Error()) } else { if err := s.client.Del(keys...).Err(); err != nil { - l4g.Error("Redis encountered an error on delete: " + err.Error()) + mlog.Error("Redis encountered an error on delete: " + err.Error()) } } }() diff --git a/store/sqlstore/channel_member_history_store.go b/store/sqlstore/channel_member_history_store.go index 6fc78b514..70ad16467 100644 --- a/store/sqlstore/channel_member_history_store.go +++ b/store/sqlstore/channel_member_history_store.go @@ -4,11 +4,12 @@ package sqlstore import ( + "fmt" "net/http" "database/sql" - l4g "github.com/alecthomas/log4go" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" "github.com/mattermost/mattermost-server/store" ) @@ -60,7 +61,7 @@ func (s SqlChannelMemberHistoryStore) LogLeaveEvent(userId string, channelId str result.Err = model.NewAppError("SqlChannelMemberHistoryStore.LogLeaveEvent", "store.sql_channel_member_history.log_leave_event.update_error", params, err.Error(), http.StatusInternalServerError) } else if rows, err := sqlResult.RowsAffected(); err == nil && rows != 1 { // there was no join event to update - this is best effort, so no need to raise an error - l4g.Warn("Channel join event for user %v and channel %v not found", userId, channelId) + mlog.Warn(fmt.Sprintf("Channel join event for user %v and channel %v not found", userId, channelId), mlog.String("user_id", userId)) } }) } diff --git a/store/sqlstore/channel_store.go b/store/sqlstore/channel_store.go index 21785c461..3bd87961a 100644 --- a/store/sqlstore/channel_store.go +++ b/store/sqlstore/channel_store.go @@ -11,9 +11,9 @@ import ( "strconv" "strings" - l4g "github.com/alecthomas/log4go" "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" @@ -852,7 +852,7 @@ func (s SqlChannelStore) IsUserInChannelUseCache(userId string, channelId string } if result := <-s.GetAllChannelMembersForUser(userId, true); result.Err != nil { - l4g.Error("SqlChannelStore.IsUserInChannelUseCache: " + result.Err.Error()) + mlog.Error("SqlChannelStore.IsUserInChannelUseCache: " + result.Err.Error()) return false } else { ids := result.Data.(map[string]string) diff --git a/store/sqlstore/command_webhook_store.go b/store/sqlstore/command_webhook_store.go index 40fa8577c..1ea4f7328 100644 --- a/store/sqlstore/command_webhook_store.go +++ b/store/sqlstore/command_webhook_store.go @@ -7,8 +7,7 @@ import ( "database/sql" "net/http" - l4g "github.com/alecthomas/log4go" - + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" "github.com/mattermost/mattermost-server/store" ) @@ -86,9 +85,9 @@ func (s SqlCommandWebhookStore) TryUse(id string, limit int) store.StoreChannel } func (s SqlCommandWebhookStore) Cleanup() { - l4g.Debug("Cleaning up command webhook store.") + mlog.Debug("Cleaning up command webhook store.") exptime := model.GetMillis() - model.COMMAND_WEBHOOK_LIFETIME if _, err := s.GetMaster().Exec("DELETE FROM CommandWebhooks WHERE CreateAt < :ExpTime", map[string]interface{}{"ExpTime": exptime}); err != nil { - l4g.Error("Unable to cleanup command webhook store.") + mlog.Error("Unable to cleanup command webhook store.") } } diff --git a/store/sqlstore/post_store.go b/store/sqlstore/post_store.go index dc7248057..75154791c 100644 --- a/store/sqlstore/post_store.go +++ b/store/sqlstore/post_store.go @@ -12,8 +12,8 @@ import ( "strings" "sync" - l4g "github.com/alecthomas/log4go" "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" @@ -947,7 +947,7 @@ func (s *SqlPostStore) Search(teamId string, userId string, params *model.Search _, err := s.GetSearchReplica().Select(&posts, searchQuery, queryParams) if err != nil { - l4g.Warn(utils.T("store.sql_post.search.warn"), err.Error()) + mlog.Warn(fmt.Sprintf("Query error searching posts: %v", err.Error())) // Don't return the error to the caller as it is of no use to the user. Instead return an empty set of search results. } else { for _, p := range posts { @@ -1147,7 +1147,7 @@ func (s *SqlPostStore) GetPostsByIds(postIds []string) store.StoreChannel { _, err := s.GetReplica().Select(&posts, query, params) if err != nil { - l4g.Error(err) + mlog.Error(fmt.Sprint(err)) result.Err = model.NewAppError("SqlPostStore.GetPostsByIds", "store.sql_post.get_posts_by_ids.app_error", nil, "", http.StatusInternalServerError) } else { result.Data = posts @@ -1247,7 +1247,7 @@ func (s *SqlPostStore) determineMaxPostSize() int { table_name = 'posts' AND column_name = 'message' `); err != nil { - l4g.Error(utils.T("store.sql_post.query_max_post_size.error") + err.Error()) + mlog.Error(utils.T("store.sql_post.query_max_post_size.error") + err.Error()) } } else if s.DriverName() == model.DATABASE_DRIVER_MYSQL { // The Post.Message column in MySQL has historically been TEXT, with a maximum @@ -1263,10 +1263,10 @@ func (s *SqlPostStore) determineMaxPostSize() int { AND column_name = 'Message' LIMIT 0, 1 `); err != nil { - l4g.Error(utils.T("store.sql_post.query_max_post_size.error") + err.Error()) + mlog.Error(utils.T("store.sql_post.query_max_post_size.error") + err.Error()) } } else { - l4g.Warn(utils.T("store.sql_post.query_max_post_size.unrecognized_driver")) + mlog.Warn("No implementation found to determine the maximum supported post size") } // Assume a worst-case representation of four bytes per rune. @@ -1279,7 +1279,7 @@ func (s *SqlPostStore) determineMaxPostSize() int { maxPostSize = model.POST_MESSAGE_MAX_RUNES_V1 } - l4g.Info(utils.T("store.sql_post.query_max_post_size.max_post_size_bytes"), maxPostSize, maxPostSizeBytes) + mlog.Info(fmt.Sprintf("Post.Message supports at most %d characters (%d bytes)", maxPostSize, maxPostSizeBytes)) return maxPostSize } diff --git a/store/sqlstore/preference_store.go b/store/sqlstore/preference_store.go index 791b51d2f..bfe5f6613 100644 --- a/store/sqlstore/preference_store.go +++ b/store/sqlstore/preference_store.go @@ -6,9 +6,9 @@ package sqlstore import ( "net/http" - l4g "github.com/alecthomas/log4go" "github.com/mattermost/gorp" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" "github.com/mattermost/mattermost-server/store" ) @@ -38,7 +38,7 @@ func (s SqlPreferenceStore) CreateIndexesIfNotExists() { } func (s SqlPreferenceStore) DeleteUnusedFeatures() { - l4g.Debug("Deleting any unused pre-release features") + mlog.Debug("Deleting any unused pre-release features") sql := `DELETE FROM Preferences diff --git a/store/sqlstore/session_store.go b/store/sqlstore/session_store.go index 221603865..c63abefbb 100644 --- a/store/sqlstore/session_store.go +++ b/store/sqlstore/session_store.go @@ -4,10 +4,11 @@ package sqlstore import ( + "fmt" "net/http" "time" - l4g "github.com/alecthomas/log4go" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" "github.com/mattermost/mattermost-server/store" ) @@ -223,7 +224,7 @@ func (me SqlSessionStore) AnalyticsSessionCount() store.StoreChannel { } func (me SqlSessionStore) Cleanup(expiryTime int64, batchSize int64) { - l4g.Debug("Cleaning up session store.") + mlog.Debug("Cleaning up session store.") var query string if me.DriverName() == model.DATABASE_DRIVER_POSTGRES { @@ -236,13 +237,13 @@ func (me SqlSessionStore) Cleanup(expiryTime int64, batchSize int64) { for rowsAffected > 0 { if sqlResult, err := me.GetMaster().Exec(query, map[string]interface{}{"ExpiresAt": expiryTime, "Limit": batchSize}); err != nil { - l4g.Error("Unable to cleanup session store. err=%v", err.Error()) + mlog.Error(fmt.Sprintf("Unable to cleanup session store. err=%v", err.Error())) return } else { var rowErr error rowsAffected, rowErr = sqlResult.RowsAffected() if rowErr != nil { - l4g.Error("Unable to cleanup session store. err=%v", err.Error()) + mlog.Error(fmt.Sprintf("Unable to cleanup session store. err=%v", err.Error())) return } } diff --git a/store/sqlstore/store_test.go b/store/sqlstore/store_test.go index 41d6a9b7e..58065d65d 100644 --- a/store/sqlstore/store_test.go +++ b/store/sqlstore/store_test.go @@ -8,6 +8,7 @@ import ( "sync" "testing" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" "github.com/mattermost/mattermost-server/store" "github.com/mattermost/mattermost-server/store/storetest" @@ -98,6 +99,15 @@ func tearDownStores() { } func TestMain(m *testing.M) { + // Setup a global logger to catch tests logging outside of app context + // The global logger will be stomped by apps initalizing but that's fine for testing. Ideally this won't happen. + mlog.InitGlobalLogger(mlog.NewLogger(&mlog.LoggerConfiguration{ + EnableConsole: true, + ConsoleJson: true, + ConsoleLevel: "error", + EnableFile: false, + })) + utils.TranslationsPreInit() status := 0 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() diff --git a/store/sqlstore/supplier_reactions.go b/store/sqlstore/supplier_reactions.go index aa3b078ea..5a9c9302a 100644 --- a/store/sqlstore/supplier_reactions.go +++ b/store/sqlstore/supplier_reactions.go @@ -5,14 +5,13 @@ package sqlstore import ( "context" + "fmt" "net/http" - l4g "github.com/alecthomas/log4go" - "github.com/mattermost/gorp" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" "github.com/mattermost/mattermost-server/store" - "github.com/mattermost/mattermost-server/utils" ) func initSqlSupplierReactions(sqlStore SqlStore) { @@ -136,7 +135,7 @@ func (s *SqlSupplier) ReactionDeleteAllWithEmojiName(ctx context.Context, emojiN for _, reaction := range reactions { if _, err := s.GetMaster().Exec(UPDATE_POST_HAS_REACTIONS_ON_DELETE_QUERY, map[string]interface{}{"PostId": reaction.PostId, "UpdateAt": model.GetMillis()}); err != nil { - l4g.Warn(utils.T("store.sql_reaction.delete_all_with_emoji_name.update_post.warn"), reaction.PostId, err.Error()) + mlog.Warn(fmt.Sprintf("Unable to update Post.HasReactions while removing reactions post_id=%v, error=%v", reaction.PostId, err.Error())) } } diff --git a/store/sqlstore/tokens_store.go b/store/sqlstore/tokens_store.go index ccb58cef1..6dde1bfbf 100644 --- a/store/sqlstore/tokens_store.go +++ b/store/sqlstore/tokens_store.go @@ -7,8 +7,7 @@ import ( "database/sql" "net/http" - l4g "github.com/alecthomas/log4go" - + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" "github.com/mattermost/mattermost-server/store" ) @@ -70,9 +69,9 @@ func (s SqlTokenStore) GetByToken(tokenString string) store.StoreChannel { } func (s SqlTokenStore) Cleanup() { - l4g.Debug("Cleaning up token store.") + mlog.Debug("Cleaning up token store.") deltime := model.GetMillis() - model.MAX_TOKEN_EXIPRY_TIME if _, err := s.GetMaster().Exec("DELETE FROM Tokens WHERE CreateAt < :DelTime", map[string]interface{}{"DelTime": deltime}); err != nil { - l4g.Error("Unable to cleanup token store.") + mlog.Error("Unable to cleanup token store.") } } diff --git a/store/sqlstore/upgrade.go b/store/sqlstore/upgrade.go index 059d1a866..ec2b1a1c0 100644 --- a/store/sqlstore/upgrade.go +++ b/store/sqlstore/upgrade.go @@ -5,14 +5,13 @@ package sqlstore import ( "encoding/json" + "fmt" "os" "strings" "time" - l4g "github.com/alecthomas/log4go" - + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" - "github.com/mattermost/mattermost-server/utils" ) const ( @@ -82,17 +81,17 @@ func UpgradeDatabase(sqlStore SqlStore) { // so lets set it to the current version. if sqlStore.GetCurrentSchemaVersion() == "" { if result := <-sqlStore.System().SaveOrUpdate(&model.System{Name: "Version", Value: model.CurrentVersion}); result.Err != nil { - l4g.Critical(result.Err.Error()) + mlog.Critical(result.Err.Error()) time.Sleep(time.Second) os.Exit(EXIT_VERSION_SAVE_MISSING) } - l4g.Info("The database schema has been set to version %v", model.CurrentVersion) + mlog.Info(fmt.Sprintf("The database schema has been set to version %v", model.CurrentVersion)) } // If we're not on the current version then it's too old to be upgraded if sqlStore.GetCurrentSchemaVersion() != model.CurrentVersion { - l4g.Critical(utils.T("store.sql.schema_version.critical"), sqlStore.GetCurrentSchemaVersion(), OLDEST_SUPPORTED_VERSION, model.CurrentVersion, OLDEST_SUPPORTED_VERSION) + mlog.Critical(fmt.Sprintf("Database schema version %v is no longer supported. This Mattermost server supports automatic upgrades from schema version %v through schema version %v. Downgrades are not supported. Please manually upgrade to at least version %v before continuing", sqlStore.GetCurrentSchemaVersion(), OLDEST_SUPPORTED_VERSION, model.CurrentVersion, OLDEST_SUPPORTED_VERSION)) time.Sleep(time.Second) os.Exit(EXIT_TOO_OLD) } @@ -100,18 +99,18 @@ func UpgradeDatabase(sqlStore SqlStore) { func saveSchemaVersion(sqlStore SqlStore, version string) { if result := <-sqlStore.System().Update(&model.System{Name: "Version", Value: version}); result.Err != nil { - l4g.Critical(result.Err.Error()) + mlog.Critical(result.Err.Error()) time.Sleep(time.Second) os.Exit(EXIT_VERSION_SAVE) } - l4g.Warn(utils.T("store.sql.upgraded.warn"), version) + mlog.Warn(fmt.Sprintf("The database schema has been upgraded to version %v", version)) } func shouldPerformUpgrade(sqlStore SqlStore, currentSchemaVersion string, expectedSchemaVersion string) bool { if sqlStore.GetCurrentSchemaVersion() == currentSchemaVersion { - l4g.Warn(utils.T("store.sql.schema_out_of_date.warn"), currentSchemaVersion) - l4g.Warn(utils.T("store.sql.schema_upgrade_attempt.warn"), expectedSchemaVersion) + mlog.Warn(fmt.Sprintf("The database schema version of %v appears to be out of date", currentSchemaVersion)) + mlog.Warn(fmt.Sprintf("Attempting to upgrade the database schema version to %v", expectedSchemaVersion)) return true } @@ -135,7 +134,7 @@ func UpgradeDatabaseToVersion32(sqlStore SqlStore) { } func themeMigrationFailed(err error) { - l4g.Critical(utils.T("store.sql_user.migrate_theme.critical"), err) + mlog.Critical(fmt.Sprintf("Failed to migrate User.ThemeProps to Preferences table %v", err)) time.Sleep(time.Second) os.Exit(EXIT_THEME_MIGRATION) } @@ -403,7 +402,7 @@ func UpgradeDatabaseToVersion49(sqlStore SqlStore) { defaultTimezone := model.DefaultUserTimezone() defaultTimezoneValue, err := json.Marshal(defaultTimezone) if err != nil { - l4g.Critical(err) + mlog.Critical(fmt.Sprint(err)) } sqlStore.CreateColumnIfNotExists("Users", "Timezone", "varchar(256)", "varchar(256)", string(defaultTimezoneValue)) sqlStore.RemoveIndexIfExists("idx_channels_displayname", "Channels") diff --git a/store/store.go b/store/store.go index e64089068..0b5c9df5f 100644 --- a/store/store.go +++ b/store/store.go @@ -6,8 +6,6 @@ package store import ( "time" - l4g "github.com/alecthomas/log4go" - "github.com/mattermost/mattermost-server/model" ) @@ -32,7 +30,7 @@ func Do(f func(result *StoreResult)) StoreChannel { func Must(sc StoreChannel) interface{} { r := <-sc if r.Err != nil { - l4g.Close() + time.Sleep(time.Second) panic(r.Err) } diff --git a/store/storetest/docker.go b/store/storetest/docker.go index cd2a3075a..f3830a6fe 100644 --- a/store/storetest/docker.go +++ b/store/storetest/docker.go @@ -12,8 +12,7 @@ import ( "strings" "time" - l4g "github.com/alecthomas/log4go" - + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" ) @@ -31,7 +30,7 @@ type RunningContainer struct { } func (c *RunningContainer) Stop() error { - l4g.Info("Removing container: %v", c.Id) + mlog.Info(fmt.Sprintf("Removing container: %v", c.Id)) return exec.Command("docker", "rm", "-f", c.Id).Run() } @@ -47,7 +46,7 @@ func NewMySQLContainer() (*RunningContainer, *model.SqlSettings, error) { if err != nil { return nil, nil, err } - l4g.Info("Waiting for mysql connectivity") + mlog.Info("Waiting for mysql connectivity") port := container.NetworkSettings.Ports["3306/tcp"][0].HostPort if err := waitForPort(port); err != nil { container.Stop() @@ -66,7 +65,7 @@ func NewPostgreSQLContainer() (*RunningContainer, *model.SqlSettings, error) { if err != nil { return nil, nil, err } - l4g.Info("Waiting for postgres connectivity") + mlog.Info("Waiting for postgres connectivity") port := container.NetworkSettings.Ports["5432/tcp"][0].HostPort if err := waitForPort(port); err != nil { container.Stop() @@ -111,7 +110,7 @@ func runContainer(args []string) (*RunningContainer, error) { exec.Command("docker", "rm", "-f", id).Run() return nil, err } - l4g.Info("Running container: %v", id) + mlog.Info(fmt.Sprintf("Running container: %v", id)) return &RunningContainer{containers[0]}, nil } -- cgit v1.2.3-1-g7c22