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, 14 insertions, 15 deletions

diff --git a/app/web_conn.go b/app/web_conn.go
index 9ae5505b2..9d8134f34 100644
--- a/app/web_conn.go
+++ b/app/web_conn.go
@@ -8,10 +8,9 @@ import (
 	"sync/atomic"
 	"time"
 
+	"github.com/mattermost/mattermost-server/mlog"
 	"github.com/mattermost/mattermost-server/model"
-	"github.com/mattermost/mattermost-server/utils"
 
-	l4g "github.com/alecthomas/log4go"
 	"github.com/gorilla/websocket"
 	goi18n "github.com/nicksnyder/go-i18n/i18n"
 )
@@ -138,9 +137,9 @@ func (c *WebConn) readPump() {
 		if err := c.WebSocket.ReadJSON(&req); err != nil {
 			// browsers will appear as CloseNoStatusReceived
 			if websocket.IsCloseError(err, websocket.CloseNormalClosure, websocket.CloseNoStatusReceived) {
-				l4g.Debug(fmt.Sprintf("websocket.read: client side closed socket userId=%v", c.UserId))
+				mlog.Debug(fmt.Sprintf("websocket.read: client side closed socket userId=%v", c.UserId))
 			} else {
-				l4g.Debug(fmt.Sprintf("websocket.read: closing websocket for userId=%v error=%v", c.UserId, err.Error()))
+				mlog.Debug(fmt.Sprintf("websocket.read: closing websocket for userId=%v error=%v", c.UserId, err.Error()))
 			}
 
 			return
@@ -177,7 +176,7 @@ func (c *WebConn) writePump() {
 				if msg.EventType() == model.WEBSOCKET_EVENT_TYPING ||
 					msg.EventType() == model.WEBSOCKET_EVENT_STATUS_CHANGE ||
 					msg.EventType() == model.WEBSOCKET_EVENT_CHANNEL_VIEWED {
-					l4g.Info(fmt.Sprintf("websocket.slow: dropping message userId=%v type=%v channelId=%v", c.UserId, msg.EventType(), evt.Broadcast.ChannelId))
+					mlog.Info(fmt.Sprintf("websocket.slow: dropping message userId=%v type=%v channelId=%v", c.UserId, msg.EventType(), evt.Broadcast.ChannelId))
 					skipSend = true
 				}
 			}
@@ -196,9 +195,9 @@ func (c *WebConn) writePump() {
 
 				if len(c.Send) >= SEND_DEADLOCK_WARN {
 					if evtOk {
-						l4g.Error(fmt.Sprintf("websocket.full: message userId=%v type=%v channelId=%v size=%v", c.UserId, msg.EventType(), evt.Broadcast.ChannelId, len(msg.ToJson())))
+						mlog.Error(fmt.Sprintf("websocket.full: message userId=%v type=%v channelId=%v size=%v", c.UserId, msg.EventType(), evt.Broadcast.ChannelId, len(msg.ToJson())))
 					} else {
-						l4g.Error(fmt.Sprintf("websocket.full: message userId=%v type=%v size=%v", c.UserId, msg.EventType(), len(msg.ToJson())))
+						mlog.Error(fmt.Sprintf("websocket.full: message userId=%v type=%v size=%v", c.UserId, msg.EventType(), len(msg.ToJson())))
 					}
 				}
 
@@ -206,9 +205,9 @@ func (c *WebConn) writePump() {
 				if err := c.WebSocket.WriteMessage(websocket.TextMessage, msgBytes); err != nil {
 					// browsers will appear as CloseNoStatusReceived
 					if websocket.IsCloseError(err, websocket.CloseNormalClosure, websocket.CloseNoStatusReceived) {
-						l4g.Debug(fmt.Sprintf("websocket.send: client side closed socket userId=%v", c.UserId))
+						mlog.Debug(fmt.Sprintf("websocket.send: client side closed socket userId=%v", c.UserId))
 					} else {
-						l4g.Debug(fmt.Sprintf("websocket.send: closing websocket for userId=%v, error=%v", c.UserId, err.Error()))
+						mlog.Debug(fmt.Sprintf("websocket.send: closing websocket for userId=%v, error=%v", c.UserId, err.Error()))
 					}
 
 					return
@@ -226,9 +225,9 @@ func (c *WebConn) writePump() {
 			if err := c.WebSocket.WriteMessage(websocket.PingMessage, []byte{}); err != nil {
 				// browsers will appear as CloseNoStatusReceived
 				if websocket.IsCloseError(err, websocket.CloseNormalClosure, websocket.CloseNoStatusReceived) {
-					l4g.Debug(fmt.Sprintf("websocket.ticker: client side closed socket userId=%v", c.UserId))
+					mlog.Debug(fmt.Sprintf("websocket.ticker: client side closed socket userId=%v", c.UserId))
 				} else {
-					l4g.Debug(fmt.Sprintf("websocket.ticker: closing websocket for userId=%v error=%v", c.UserId, err.Error()))
+					mlog.Debug(fmt.Sprintf("websocket.ticker: closing websocket for userId=%v error=%v", c.UserId, err.Error()))
 				}
 
 				return
@@ -237,7 +236,7 @@ func (c *WebConn) writePump() {
 			return
 		case <-authTicker.C:
 			if c.GetSessionToken() == "" {
-				l4g.Debug(fmt.Sprintf("websocket.authTicker: did not authenticate ip=%v", c.WebSocket.RemoteAddr()))
+				mlog.Debug(fmt.Sprintf("websocket.authTicker: did not authenticate ip=%v", c.WebSocket.RemoteAddr()))
 				return
 			}
 			authTicker.Stop()
@@ -261,7 +260,7 @@ func (webCon *WebConn) IsAuthenticated() bool {
 
 		session, err := webCon.App.GetSession(webCon.GetSessionToken())
 		if err != nil {
-			l4g.Error(utils.T("api.websocket.invalid_session.error"), err.Error())
+			mlog.Error(fmt.Sprintf("Invalid session err=%v", err.Error()))
 			webCon.SetSessionToken("")
 			webCon.SetSession(nil)
 			webCon.SetSessionExpiresAt(0)
@@ -334,7 +333,7 @@ func (webCon *WebConn) ShouldSendEvent(msg *model.WebSocketEvent) bool {
 
 		if webCon.AllChannelMembers == nil {
 			if result := <-webCon.App.Srv.Store.Channel().GetAllChannelMembersForUser(webCon.UserId, true); result.Err != nil {
-				l4g.Error("webhub.shouldSendEvent: " + result.Err.Error())
+				mlog.Error("webhub.shouldSendEvent: " + result.Err.Error())
 				return false
 			} else {
 				webCon.AllChannelMembers = result.Data.(map[string]string)
@@ -365,7 +364,7 @@ func (webCon *WebConn) IsMemberOfTeam(teamId string) bool {
 	if currentSession == nil || len(currentSession.Token) == 0 {
 		session, err := webCon.App.GetSession(webCon.GetSessionToken())
 		if err != nil {
-			l4g.Error(utils.T("api.websocket.invalid_session.error"), err.Error())
+			mlog.Error(fmt.Sprintf("Invalid session err=%v", err.Error()))
 			return false
 		} else {
 			webCon.SetSession(session)