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. --- api/api.go | 4 ++-- api/api_test.go | 15 ++++++++++++--- api/apitestlib.go | 15 +++++++-------- api/channel.go | 12 ++++++------ api/context.go | 18 +++++++++--------- api/user.go | 13 ++++++------- api/websocket.go | 6 +++--- 7 files changed, 45 insertions(+), 38 deletions(-) (limited to 'api') diff --git a/api/api.go b/api/api.go index 70f36db85..2b226bbeb 100644 --- a/api/api.go +++ b/api/api.go @@ -6,9 +6,9 @@ package api import ( "net/http" - l4g "github.com/alecthomas/log4go" "github.com/gorilla/mux" "github.com/mattermost/mattermost-server/app" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" _ "github.com/nicksnyder/go-i18n/i18n" @@ -114,7 +114,7 @@ func Init(a *app.App, root *mux.Router) *API { a.InitEmailBatching() if *a.Config().ServiceSettings.EnableAPIv3 { - l4g.Info("API version 3 is scheduled for deprecation. Please see https://api.mattermost.com for details.") + mlog.Info("API version 3 is scheduled for deprecation. Please see https://api.mattermost.com for details.") } return api diff --git a/api/api_test.go b/api/api_test.go index d447fc9bd..a4ddf6a37 100644 --- a/api/api_test.go +++ b/api/api_test.go @@ -8,20 +8,29 @@ import ( "os" "testing" - l4g "github.com/alecthomas/log4go" - + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/store/storetest" "github.com/mattermost/mattermost-server/utils" ) func TestMain(m *testing.M) { flag.Parse() + + // 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() // In the case where a dev just wants to run a single test, it's faster to just use the default // store. if filter := flag.Lookup("test.run").Value.String(); filter != "" && filter != "." { - l4g.Info("-test.run used, not creating temporary containers") + mlog.Info("-test.run used, not creating temporary containers") os.Exit(m.Run()) } diff --git a/api/apitestlib.go b/api/apitestlib.go index 699b0eb90..20dbc4073 100644 --- a/api/apitestlib.go +++ b/api/apitestlib.go @@ -14,14 +14,13 @@ import ( "github.com/mattermost/mattermost-server/api4" "github.com/mattermost/mattermost-server/app" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" "github.com/mattermost/mattermost-server/store" "github.com/mattermost/mattermost-server/store/sqlstore" "github.com/mattermost/mattermost-server/store/storetest" "github.com/mattermost/mattermost-server/utils" "github.com/mattermost/mattermost-server/wsapi" - - l4g "github.com/alecthomas/log4go" ) type TestHelper struct { @@ -233,8 +232,8 @@ func (me *TestHelper) LinkUserToTeam(user *model.User, team *model.Team) { err := me.App.JoinUserToTeam(team, user, "") if err != nil { - l4g.Error(err.Error()) - l4g.Close() + mlog.Error(err.Error()) + time.Sleep(time.Second) panic(err) } @@ -248,8 +247,8 @@ func (me *TestHelper) UpdateUserToTeamAdmin(user *model.User, team *model.Team) tm := &model.TeamMember{TeamId: team.Id, UserId: user.Id, Roles: model.TEAM_USER_ROLE_ID + " " + model.TEAM_ADMIN_ROLE_ID} if tmr := <-me.App.Srv.Store.Team().UpdateMember(tm); tmr.Err != nil { utils.EnableDebugLogForTest() - l4g.Error(tmr.Err.Error()) - l4g.Close() + mlog.Error(tmr.Err.Error()) + time.Sleep(time.Second) panic(tmr.Err) } @@ -262,8 +261,8 @@ func (me *TestHelper) UpdateUserToNonTeamAdmin(user *model.User, team *model.Tea tm := &model.TeamMember{TeamId: team.Id, UserId: user.Id, Roles: model.TEAM_USER_ROLE_ID} if tmr := <-me.App.Srv.Store.Team().UpdateMember(tm); tmr.Err != nil { utils.EnableDebugLogForTest() - l4g.Error(tmr.Err.Error()) - l4g.Close() + mlog.Error(tmr.Err.Error()) + time.Sleep(time.Second) panic(tmr.Err) } diff --git a/api/channel.go b/api/channel.go index 976007725..9c465412c 100644 --- a/api/channel.go +++ b/api/channel.go @@ -4,13 +4,13 @@ package api import ( + "fmt" "net/http" "strconv" - l4g "github.com/alecthomas/log4go" "github.com/gorilla/mux" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" - "github.com/mattermost/mattermost-server/utils" ) func (api *API) InitChannel() { @@ -203,7 +203,7 @@ func updateChannel(c *Context, w http.ResponseWriter, r *http.Request) { } else { if oldChannelDisplayName != channel.DisplayName { if err := c.App.PostUpdateChannelDisplayNameMessage(c.Session.UserId, channel, oldChannelDisplayName, channel.DisplayName); err != nil { - l4g.Error(err.Error()) + mlog.Error(err.Error()) } } c.LogAudit("name=" + channel.Name) @@ -251,7 +251,7 @@ func updateChannelHeader(c *Context, w http.ResponseWriter, r *http.Request) { return } else { if err := c.App.PostUpdateChannelHeaderMessage(c.Session.UserId, channel, oldChannelHeader, channelHeader); err != nil { - l4g.Error(err.Error()) + mlog.Error(err.Error()) } c.LogAudit("name=" + channel.Name) w.Write([]byte(channel.ToJson())) @@ -297,7 +297,7 @@ func updateChannelPurpose(c *Context, w http.ResponseWriter, r *http.Request) { return } else { if err := c.App.PostUpdateChannelPurposeMessage(c.Session.UserId, channel, oldChannelPurpose, channelPurpose); err != nil { - l4g.Error(err.Error()) + mlog.Error(err.Error()) } c.LogAudit("name=" + channel.Name) w.Write([]byte(channel.ToJson())) @@ -318,7 +318,7 @@ func getChannels(c *Context, w http.ResponseWriter, r *http.Request) { if _, err := c.App.GetUser(c.Session.UserId); err != nil { c.Err = err c.RemoveSessionCookie(w, r) - l4g.Error(utils.T("api.channel.get_channels.error"), c.Session.UserId) + mlog.Error(fmt.Sprintf("Error in getting users profile for id=%v forcing logout", c.Session.UserId), mlog.String("user_id", c.Session.UserId)) return } } diff --git a/api/context.go b/api/context.go index 1eb1e3f4f..8ebb5f73b 100644 --- a/api/context.go +++ b/api/context.go @@ -11,11 +11,11 @@ import ( "sync/atomic" "time" - l4g "github.com/alecthomas/log4go" "github.com/gorilla/mux" goi18n "github.com/nicksnyder/go-i18n/i18n" "github.com/mattermost/mattermost-server/app" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" "github.com/mattermost/mattermost-server/utils" ) @@ -101,7 +101,7 @@ type handler struct { func (h handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { now := time.Now() - l4g.Debug("%v", r.URL.Path) + mlog.Debug(fmt.Sprintf("%v", r.URL.Path)) c := &Context{} c.App = h.app @@ -146,7 +146,7 @@ func (h handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { session, err := c.App.GetSession(token) if err != nil { - l4g.Error(utils.T("api.context.invalid_session.error"), err.Error()) + mlog.Error(fmt.Sprintf("Invalid session err=%v", err.Error())) c.RemoveSessionCookie(w, r) if h.requireUser || h.requireSystemAdmin { c.Err = model.NewAppError("ServeHTTP", "api.context.session_expired.app_error", nil, "token="+token, http.StatusUnauthorized) @@ -268,14 +268,14 @@ func (c *Context) LogError(err *model.AppError) { if c.Path == "/api/v3/users/websocket" && err.StatusCode == 401 || err.Id == "web.check_browser_compatibility.app_error" { c.LogDebug(err) } else if err.Id != "api.post.create_post.town_square_read_only" { - l4g.Error(utils.TDefault("api.context.log.error"), c.Path, err.Where, err.StatusCode, - c.RequestId, c.Session.UserId, c.IpAddress, err.SystemMessage(utils.TDefault), err.DetailedError) + mlog.Error(fmt.Sprintf("%v:%v code=%v rid=%v uid=%v ip=%v %v [details: %v]", c.Path, err.Where, err.StatusCode, + c.RequestId, c.Session.UserId, c.IpAddress, err.SystemMessage(utils.TDefault), err.DetailedError), mlog.String("user_id", c.Session.UserId)) } } func (c *Context) LogDebug(err *model.AppError) { - l4g.Debug(utils.TDefault("api.context.log.error"), c.Path, err.Where, err.StatusCode, - c.RequestId, c.Session.UserId, c.IpAddress, err.SystemMessage(utils.TDefault), err.DetailedError) + mlog.Debug(fmt.Sprintf("%v:%v code=%v rid=%v uid=%v ip=%v %v [details: %v]", c.Path, err.Where, err.StatusCode, + c.RequestId, c.Session.UserId, c.IpAddress, err.SystemMessage(utils.TDefault), err.DetailedError), mlog.String("user_id", c.Session.UserId)) } func (c *Context) UserRequired() { @@ -387,7 +387,7 @@ func (c *Context) GetTeamURL() string { if !c.teamURLValid { c.SetTeamURLFromSession() if !c.teamURLValid { - l4g.Debug(utils.T("api.context.invalid_team_url.debug")) + mlog.Debug("Team URL accessed when not valid. Team URL should not be used in API functions or those that are team independent") } } return c.teamURL @@ -424,7 +424,7 @@ func IsApiCall(r *http.Request) bool { func Handle404(a *app.App, w http.ResponseWriter, r *http.Request) { err := model.NewAppError("Handle404", "api.context.404.app_error", nil, "", http.StatusNotFound) - l4g.Debug("%v: code=404 ip=%v", r.URL.Path, utils.GetIpAddress(r)) + mlog.Debug(fmt.Sprintf("%v: code=404 ip=%v", r.URL.Path, utils.GetIpAddress(r))) if IsApiCall(r) { w.WriteHeader(err.StatusCode) diff --git a/api/user.go b/api/user.go index 35a3687b9..15fd4c7ea 100644 --- a/api/user.go +++ b/api/user.go @@ -11,12 +11,11 @@ import ( "strings" "time" - l4g "github.com/alecthomas/log4go" "github.com/gorilla/mux" "github.com/mattermost/mattermost-server/app" + "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 (api *API) InitUser() { @@ -245,7 +244,7 @@ func getMe(c *Context, w http.ResponseWriter, r *http.Request) { if user, err := c.App.GetUser(c.Session.UserId); err != nil { c.Err = err c.RemoveSessionCookie(w, r) - l4g.Error(utils.T("api.user.get_me.getting.error"), c.Session.UserId) + mlog.Error(fmt.Sprintf("Error in getting users profile for id=%v forcing logout", c.Session.UserId), mlog.String("user_id", c.Session.UserId)) return } else if c.HandleEtag(user.Etag(c.App.Config().PrivacySettings.ShowFullName, c.App.Config().PrivacySettings.ShowEmailAddress), "Get Me", w, r) { return @@ -1042,12 +1041,12 @@ func updateMfa(c *Context, w http.ResponseWriter, r *http.Request) { var user *model.User var err *model.AppError if user, err = c.App.GetUser(c.Session.UserId); err != nil { - l4g.Warn(err.Error()) + mlog.Warn(err.Error()) return } if err := c.App.SendMfaChangeEmail(user.Email, activate, user.Locale, c.App.GetSiteURL()); err != nil { - l4g.Error(err.Error()) + mlog.Error(err.Error()) } }) @@ -1171,7 +1170,7 @@ func completeSaml(c *Context, w http.ResponseWriter, r *http.Request) { if len(teamId) > 0 { c.App.Go(func() { if err := c.App.AddUserToTeamByTeamId(teamId, user); err != nil { - l4g.Error(err.Error()) + mlog.Error(err.Error()) } else { c.App.AddDirectChannels(teamId, user) } @@ -1185,7 +1184,7 @@ func completeSaml(c *Context, w http.ResponseWriter, r *http.Request) { c.LogAuditWithUserId(user.Id, "Revoked all sessions for user") c.App.Go(func() { if err := c.App.SendSignInChangeEmail(user.Email, strings.Title(model.USER_AUTH_SERVICE_SAML)+" SSO", user.Locale, c.App.GetSiteURL()); err != nil { - l4g.Error(err.Error()) + mlog.Error(err.Error()) } }) } diff --git a/api/websocket.go b/api/websocket.go index 0da18d896..7f2c9c0db 100644 --- a/api/websocket.go +++ b/api/websocket.go @@ -4,12 +4,12 @@ package api import ( + "fmt" "net/http" - l4g "github.com/alecthomas/log4go" "github.com/gorilla/websocket" + "github.com/mattermost/mattermost-server/mlog" "github.com/mattermost/mattermost-server/model" - "github.com/mattermost/mattermost-server/utils" ) func (api *API) InitWebSocket() { @@ -25,7 +25,7 @@ func connect(c *Context, w http.ResponseWriter, r *http.Request) { ws, err := upgrader.Upgrade(w, r, nil) if err != nil { - l4g.Error(utils.T("api.web_socket.connect.error"), err) + mlog.Error(fmt.Sprintf("websocket connect err: %v", err)) c.Err = model.NewAppError("connect", "api.web_socket.connect.upgrade.app_error", nil, "", http.StatusInternalServerError) return } -- cgit v1.2.3-1-g7c22