Unverified Commit 686c2fba authored by Christopher Speller's avatar Christopher Speller Committed by GitHub

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.
parent 2acbc77d
......@@ -7,13 +7,6 @@
revision = "2600fb119af974220d3916a5916d6e31176aac1b"
version = "v1.0.1"
[[projects]]
branch = "master"
name = "github.com/alecthomas/log4go"
packages = ["."]
revision = "9c17fbb2767ccbdda78584f28d545c44a4b29c4f"
source = "https://github.com/mattermost/log4go.git"
[[projects]]
branch = "master"
name = "github.com/armon/go-metrics"
......@@ -511,6 +504,31 @@
packages = ["."]
revision = "a0b114877d4caeffbd7f87e3757c17fce570fea7"
[[projects]]
name = "go.uber.org/atomic"
packages = ["."]
revision = "8474b86a5a6f79c443ce4b2992817ff32cf208b8"
version = "v1.3.1"
[[projects]]
name = "go.uber.org/multierr"
packages = ["."]
revision = "3c4937480c32f4c13a875a1829af76c98ca3d40a"
version = "v1.1.0"
[[projects]]
name = "go.uber.org/zap"
packages = [
".",
"buffer",
"internal/bufferpool",
"internal/color",
"internal/exit",
"zapcore"
]
revision = "eeedf312bc6c57391d84767a4cd413f02a917974"
version = "v1.8.0"
[[projects]]
branch = "master"
name = "golang.org/x/crypto"
......@@ -607,6 +625,12 @@
revision = "41f3572897373c5538c50a2402db15db079fa4fd"
version = "2.0.0"
[[projects]]
name = "gopkg.in/natefinch/lumberjack.v2"
packages = ["."]
revision = "a96e63847dc3c67d17befa69c303767e2f84e54f"
version = "v2.1"
[[projects]]
name = "gopkg.in/olivere/elastic.v5"
packages = [
......@@ -635,6 +659,6 @@
[solve-meta]
analyzer-name = "dep"
analyzer-version = 1
inputs-digest = "a6a107c250033694b6d11085333da149e3e1171da3c23ce5bc9362148adef141"
inputs-digest = "4f92b22eac4e8efa0aa098a6b1f1599ab087160296bd5fb74a9fad5366bbe1bc"
solver-name = "gps-cdcl"
solver-version = 1
......@@ -24,13 +24,6 @@
# go-tests = true
# unused-packages = true
# To use our own fork
[[constraint]]
name = "github.com/alecthomas/log4go"
branch = "master"
source = "https://github.com/mattermost/log4go.git"
# To keep us on latest since maintainer stopped releasing versions
[[constraint]]
name = "github.com/go-sql-driver/mysql"
......@@ -71,3 +64,7 @@
[prune]
go-tests = true
unused-packages = true
[[constraint]]
name = "gopkg.in/natefinch/lumberjack.v2"
version = "2.1.0"
......@@ -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
......
......@@ -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())
}
......
......@@ -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)
}
......
......@@ -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
}
}
......
......@@ -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)
......
......@@ -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())
}
})
}
......
......@@ -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
}
......
......@@ -4,11 +4,12 @@
package api4
import (
"fmt"
"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/mattermost/mattermost-server/utils"
......@@ -243,7 +244,7 @@ func Init(a *app.App, root *mux.Router, full bool) *API {
func Handle404(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)))
w.WriteHeader(err.StatusCode)
err.DetailedError = "There doesn't appear to be an api call for the url='" + r.URL.Path + "'."
......
......@@ -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())
}
......
......@@ -19,8 +19,8 @@ import (
"testing"
"time"
l4g "github.com/alecthomas/log4go"
"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"
......@@ -156,13 +156,13 @@ func (me *TestHelper) TearDown() {
options := map[string]bool{}
options[store.USER_SEARCH_OPTION_NAMES_ONLY_NO_FULL_NAME] = true
if result := <-me.App.Srv.Store.User().Search("", "fakeuser", options); result.Err != nil {
l4g.Error("Error tearing down test users")
mlog.Error("Error tearing down test users")
} else {
users := result.Data.([]*model.User)
for _, u := range users {
if err := me.App.PermanentDeleteUser(u); err != nil {
l4g.Error(err.Error())
mlog.Error(err.Error())
}
}
}
......@@ -171,13 +171,13 @@ func (me *TestHelper) TearDown() {
go func() {
defer wg.Done()
if result := <-me.App.Srv.Store.Team().SearchByName("faketeam"); result.Err != nil {
l4g.Error("Error tearing down test teams")
mlog.Error("Error tearing down test teams")
} else {
teams := result.Data.([]*model.Team)
for _, t := range teams {
if err := me.App.PermanentDeleteTeam(t); err != nil {
l4g.Error(err.Error())
mlog.Error(err.Error())
}
}
}
......@@ -186,7 +186,7 @@ func (me *TestHelper) TearDown() {
go func() {
defer wg.Done()
if result := <-me.App.Srv.Store.OAuth().GetApps(0, 1000); result.Err != nil {
l4g.Error("Error tearing down test oauth apps")
mlog.Error("Error tearing down test oauth apps")
} else {
apps := result.Data.([]*model.OAuthApp)
......@@ -450,8 +450,8 @@ func (me *TestHelper) UpdateActiveUser(user *model.User, active bool) {
_, err := me.App.UpdateActive(user, active)
if err != nil {
l4g.Error(err.Error())
l4g.Close()
mlog.Error(err.Error())
time.Sleep(time.Second)
panic(err)
}
......@@ -464,8 +464,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)
}
......@@ -478,8 +478,8 @@ func (me *TestHelper) AddUserToChannel(user *model.User, channel *model.Channel)
member, err := me.App.AddUserToChannel(user, channel)
if err != nil {
l4g.Error(err.Error())
l4g.Close()
mlog.Error(err.Error())
time.Sleep(time.Second)
panic(err)
}
......@@ -784,8 +784,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)
}
......@@ -798,8 +798,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)
}
......
......@@ -6,8 +6,7 @@ package api4
import (
"net/http"
l4g "github.com/alecthomas/log4go"
"github.com/mattermost/mattermost-server/mlog"
"github.com/mattermost/mattermost-server/model"
)
......@@ -139,7 +138,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())
}
}
......
......@@ -10,10 +10,10 @@ import (
"strings"
"time"