Make all loggers derive from non-default instance (#728)

5 files changed, 90 insertions, 55 deletions

diff --git a/matterclient/channels.go b/matterclient/channels.go
index ddd4d006..655efe96 100644
--- a/matterclient/channels.go
+++ b/matterclient/channels.go
@@ -5,7 +5,6 @@ import (
 	"strings"
 
 	"github.com/mattermost/mattermost-server/model"
-	"github.com/sirupsen/logrus"
 )
 
 // GetChannels returns all channels we're members off
@@ -155,11 +154,11 @@ func (m *MMClient) JoinChannel(channelId string) error { //nolint:golint
 	defer m.RUnlock()
 	for _, c := range m.Team.Channels {
 		if c.Id == channelId {
-			m.log.Debug("Not joining ", channelId, " already joined.")
+			m.logger.Debug("Not joining ", channelId, " already joined.")
 			return nil
 		}
 	}
-	m.log.Debug("Joining ", channelId)
+	m.logger.Debug("Joining ", channelId)
 	_, resp := m.Client.AddChannelMember(channelId, m.User.Id)
 	if resp.Error != nil {
 		return resp.Error
@@ -189,19 +188,19 @@ func (m *MMClient) UpdateChannels() error {
 
 func (m *MMClient) UpdateChannelHeader(channelId string, header string) { //nolint:golint
 	channel := &model.Channel{Id: channelId, Header: header}
-	m.log.Debugf("updating channelheader %#v, %#v", channelId, header)
+	m.logger.Debugf("updating channelheader %#v, %#v", channelId, header)
 	_, resp := m.Client.UpdateChannel(channel)
 	if resp.Error != nil {
-		logrus.Error(resp.Error)
+		m.logger.Error(resp.Error)
 	}
 }
 
 func (m *MMClient) UpdateLastViewed(channelId string) error { //nolint:golint
-	m.log.Debugf("posting lastview %#v", channelId)
+	m.logger.Debugf("posting lastview %#v", channelId)
 	view := &model.ChannelView{ChannelId: channelId}
 	_, resp := m.Client.ViewChannel(m.User.Id, view)
 	if resp.Error != nil {
-		m.log.Errorf("ChannelView update for %s failed: %s", channelId, resp.Error)
+		m.logger.Errorf("ChannelView update for %s failed: %s", channelId, resp.Error)
 		return resp.Error
 	}
 	return nil
diff --git a/matterclient/helpers.go b/matterclient/helpers.go
index 625fffaa..b3d43460 100644
--- a/matterclient/helpers.go
+++ b/matterclient/helpers.go
@@ -22,7 +22,7 @@ func (m *MMClient) doLogin(firstConnection bool, b *backoff.Backoff) error {
 	var logmsg = "trying login"
 	var err error
 	for {
-		m.log.Debugf("%s %s %s %s", logmsg, m.Credentials.Team, m.Credentials.Login, m.Credentials.Server)
+		m.logger.Debugf("%s %s %s %s", logmsg, m.Credentials.Team, m.Credentials.Login, m.Credentials.Server)
 		if m.Credentials.Token != "" {
 			resp, err = m.doLoginToken()
 			if err != nil {
@@ -34,14 +34,14 @@ func (m *MMClient) doLogin(firstConnection bool, b *backoff.Backoff) error {
 		appErr = resp.Error
 		if appErr != nil {
 			d := b.Duration()
-			m.log.Debug(appErr.DetailedError)
+			m.logger.Debug(appErr.DetailedError)
 			if firstConnection {
 				if appErr.Message == "" {
 					return errors.New(appErr.DetailedError)
 				}
 				return errors.New(appErr.Message)
 			}
-			m.log.Debugf("LOGIN: %s, reconnecting in %s", appErr, d)
+			m.logger.Debugf("LOGIN: %s, reconnecting in %s", appErr, d)
 			time.Sleep(d)
 			logmsg = "retrying login"
 			continue
@@ -59,17 +59,17 @@ func (m *MMClient) doLoginToken() (*model.Response, error) {
 	m.Client.AuthType = model.HEADER_BEARER
 	m.Client.AuthToken = m.Credentials.Token
 	if m.Credentials.CookieToken {
-		m.log.Debugf(logmsg + " with cookie (MMAUTH) token")
+		m.logger.Debugf(logmsg + " with cookie (MMAUTH) token")
 		m.Client.HttpClient.Jar = m.createCookieJar(m.Credentials.Token)
 	} else {
-		m.log.Debugf(logmsg + " with personal token")
+		m.logger.Debugf(logmsg + " with personal token")
 	}
 	m.User, resp = m.Client.GetMe("")
 	if resp.Error != nil {
 		return resp, resp.Error
 	}
 	if m.User == nil {
-		m.log.Errorf("LOGIN TOKEN: %s is invalid", m.Credentials.Pass)
+		m.logger.Errorf("LOGIN TOKEN: %s is invalid", m.Credentials.Pass)
 		return resp, errors.New("invalid token")
 	}
 	return resp, nil
@@ -126,7 +126,7 @@ func (m *MMClient) initUser() error {
 	defer m.Unlock()
 	// we only load all team data on initial login.
 	// all other updates are for channels from our (primary) team only.
-	//m.log.Debug("initUser(): loading all team data")
+	//m.logger.Debug("initUser(): loading all team data")
 	teams, resp := m.Client.GetTeamsForUser(m.User.Id, "")
 	if resp.Error != nil {
 		return resp.Error
@@ -156,7 +156,7 @@ func (m *MMClient) initUser() error {
 		m.OtherTeams = append(m.OtherTeams, t)
 		if team.Name == m.Credentials.Team {
 			m.Team = t
-			m.log.Debugf("initUser(): found our team %s (id: %s)", team.Name, team.Id)
+			m.logger.Debugf("initUser(): found our team %s (id: %s)", team.Name, team.Id)
 		}
 		// add all users
 		for k, v := range t.Users {
@@ -180,10 +180,10 @@ func (m *MMClient) serverAlive(firstConnection bool, b *backoff.Backoff) error {
 		}
 		m.ServerVersion = resp.ServerVersion
 		if m.ServerVersion == "" {
-			m.log.Debugf("Server not up yet, reconnecting in %s", d)
+			m.logger.Debugf("Server not up yet, reconnecting in %s", d)
 			time.Sleep(d)
 		} else {
-			m.log.Infof("Found version %s", m.ServerVersion)
+			m.logger.Infof("Found version %s", m.ServerVersion)
 			return nil
 		}
 	}
@@ -207,7 +207,7 @@ func (m *MMClient) wsConnect() {
 	header := http.Header{}
 	header.Set(model.HEADER_AUTH, "BEARER "+m.Client.AuthToken)
 
-	m.log.Debugf("WsClient: making connection: %s", wsurl)
+	m.logger.Debugf("WsClient: making connection: %s", wsurl)
 	for {
 		wsDialer := &websocket.Dialer{
 			TLSClientConfig: &tls.Config{InsecureSkipVerify: m.SkipTLSVerify}, //nolint:gosec
@@ -217,14 +217,14 @@ func (m *MMClient) wsConnect() {
 		m.WsClient, _, err = wsDialer.Dial(wsurl, header)
 		if err != nil {
 			d := b.Duration()
-			m.log.Debugf("WSS: %s, reconnecting in %s", err, d)
+			m.logger.Debugf("WSS: %s, reconnecting in %s", err, d)
 			time.Sleep(d)
 			continue
 		}
 		break
 	}
 
-	m.log.Debug("WsClient: connected")
+	m.logger.Debug("WsClient: connected")
 	m.WsSequence = 1
 	m.WsPingChan = make(chan *model.WebSocketResponse)
 	// only start to parse WS messages when login is completely done
@@ -252,7 +252,7 @@ func (m *MMClient) checkAlive() error {
 	if resp.Error != nil {
 		return resp.Error
 	}
-	m.log.Debug("WS PING")
+	m.logger.Debug("WS PING")
 	return m.sendWSRequest("ping", nil)
 }
 
@@ -262,7 +262,7 @@ func (m *MMClient) sendWSRequest(action string, data map[string]interface{}) err
 	req.Action = action
 	req.Data = data
 	m.WsSequence++
-	m.log.Debugf("sendWsRequest %#v", req)
+	m.logger.Debugf("sendWsRequest %#v", req)
 	return m.WsClient.WriteJSON(req)
 }
 
diff --git a/matterclient/matterclient.go b/matterclient/matterclient.go
index 07994c61..18006c7a 100644
--- a/matterclient/matterclient.go
+++ b/matterclient/matterclient.go
@@ -8,7 +8,7 @@ import (
 	"time"
 
 	"github.com/gorilla/websocket"
-	"github.com/hashicorp/golang-lru"
+	lru "github.com/hashicorp/golang-lru"
 	"github.com/jpillora/backoff"
 	prefixed "github.com/matterbridge/logrus-prefixed-formatter"
 	"github.com/mattermost/mattermost-server/model"
@@ -49,13 +49,13 @@ type Team struct {
 type MMClient struct {
 	sync.RWMutex
 	*Credentials
+
 	Team          *Team
 	OtherTeams    []*Team
 	Client        *model.Client4
 	User          *model.User
 	Users         map[string]*model.User
 	MessageChan   chan *Message
-	log           *logrus.Entry
 	WsClient      *websocket.Conn
 	WsQuit        bool
 	WsAway        bool
@@ -64,31 +64,61 @@ type MMClient struct {
 	WsPingChan    chan *model.WebSocketResponse
 	ServerVersion string
 	OnWsConnect   func()
-	lruCache      *lru.Cache
+
+	logger     *logrus.Entry
+	rootLogger *logrus.Logger
+	lruCache   *lru.Cache
 }
 
-func New(login, pass, team, server string) *MMClient {
-	cred := &Credentials{Login: login, Pass: pass, Team: team, Server: server}
-	mmclient := &MMClient{Credentials: cred, MessageChan: make(chan *Message, 100), Users: make(map[string]*model.User)}
-	logrus.SetFormatter(&prefixed.TextFormatter{PrefixPadding: 13, DisableColors: true})
-	mmclient.log = logrus.WithFields(logrus.Fields{"prefix": "matterclient"})
-	mmclient.lruCache, _ = lru.New(500)
-	return mmclient
+// New will instantiate a new Matterclient with the specified login details without connecting.
+func New(login string, pass string, team string, server string) *MMClient {
+	rootLogger := logrus.New()
+	rootLogger.SetFormatter(&prefixed.TextFormatter{
+		PrefixPadding: 13,
+		DisableColors: true,
+	})
+
+	cred := &Credentials{
+		Login:  login,
+		Pass:   pass,
+		Team:   team,
+		Server: server,
+	}
+
+	cache, _ := lru.New(500)
+	return &MMClient{
+		Credentials: cred,
+		MessageChan: make(chan *Message, 100),
+		Users:       make(map[string]*model.User),
+		rootLogger:  rootLogger,
+		lruCache:    cache,
+		logger:      rootLogger.WithFields(logrus.Fields{"prefix": "matterclient"}),
+	}
 }
 
+// SetDebugLog activates debugging logging on all Matterclient log output.
 func (m *MMClient) SetDebugLog() {
-	logrus.SetFormatter(&prefixed.TextFormatter{PrefixPadding: 13, DisableColors: true, FullTimestamp: false, ForceFormatting: true})
+	m.rootLogger.SetFormatter(&prefixed.TextFormatter{
+		PrefixPadding:   13,
+		DisableColors:   true,
+		FullTimestamp:   false,
+		ForceFormatting: true,
+	})
 }
 
+// SetLogLevel tries to parse the specified level and if successful sets
+// the log level accordingly. Accepted levels are: 'debug', 'info', 'warn',
+// 'error', 'fatal' and 'panic'.
 func (m *MMClient) SetLogLevel(level string) {
 	l, err := logrus.ParseLevel(level)
 	if err != nil {
-		logrus.SetLevel(logrus.InfoLevel)
-		return
+		m.logger.Warnf("Failed to parse specified log-level '%s': %#v", level, err)
+	} else {
+		m.rootLogger.SetLevel(l)
 	}
-	logrus.SetLevel(l)
 }
 
+// Login tries to connect the client with the loging details with which it was initialized.
 func (m *MMClient) Login() error {
 	// check if this is a first connect or a reconnection
 	firstConnection := true
@@ -131,13 +161,14 @@ func (m *MMClient) Login() error {
 	return nil
 }
 
+// Logout disconnects the client from the chat server.
 func (m *MMClient) Logout() error {
-	m.log.Debugf("logout as %s (team: %s) on %s", m.Credentials.Login, m.Credentials.Team, m.Credentials.Server)
+	m.logger.Debugf("logout as %s (team: %s) on %s", m.Credentials.Login, m.Credentials.Team, m.Credentials.Server)
 	m.WsQuit = true
 	m.WsClient.Close()
 	m.WsClient.UnderlyingConn().Close()
 	if strings.Contains(m.Credentials.Pass, model.SESSION_COOKIE_TOKEN) {
-		m.log.Debug("Not invalidating session in logout, credential is a token")
+		m.logger.Debug("Not invalidating session in logout, credential is a token")
 		return nil
 	}
 	_, resp := m.Client.Logout()
@@ -147,13 +178,16 @@ func (m *MMClient) Logout() error {
 	return nil
 }
 
+// WsReceiver implements the core loop that manages the connection to the chat server. In
+// case of a disconnect it will try to reconnect. A call to this method is blocking until
+// the 'WsQuite' field of the MMClient object is set to 'true'.
 func (m *MMClient) WsReceiver() {
 	for {
 		var rawMsg json.RawMessage
 		var err error
 
 		if m.WsQuit {
-			m.log.Debug("exiting WsReceiver")
+			m.logger.Debug("exiting WsReceiver")
 			return
 		}
 
@@ -163,14 +197,14 @@ func (m *MMClient) WsReceiver() {
 		}
 
 		if _, rawMsg, err = m.WsClient.ReadMessage(); err != nil {
-			m.log.Error("error:", err)
+			m.logger.Error("error:", err)
 			// reconnect
 			m.wsConnect()
 		}
 
 		var event model.WebSocketEvent
 		if err := json.Unmarshal(rawMsg, &event); err == nil && event.IsValid() {
-			m.log.Debugf("WsReceiver event: %#v", event)
+			m.logger.Debugf("WsReceiver event: %#v", event)
 			msg := &Message{Raw: &event, Team: m.Credentials.Team}
 			m.parseMessage(msg)
 			// check if we didn't empty the message
@@ -189,40 +223,42 @@ func (m *MMClient) WsReceiver() {
 
 		var response model.WebSocketResponse
 		if err := json.Unmarshal(rawMsg, &response); err == nil && response.IsValid() {
-			m.log.Debugf("WsReceiver response: %#v", response)
+			m.logger.Debugf("WsReceiver response: %#v", response)
 			m.parseResponse(response)
-			continue
 		}
 	}
 }
 
+// StatusLoop implements a ping-cycle that ensures that the connection to the chat servers
+// remains alive. In case of a disconnect it will try to reconnect. A call to this method
+// is blocking until the 'WsQuite' field of the MMClient object is set to 'true'.
 func (m *MMClient) StatusLoop() {
 	retries := 0
 	backoff := time.Second * 60
 	if m.OnWsConnect != nil {
 		m.OnWsConnect()
 	}
-	m.log.Debug("StatusLoop:", m.OnWsConnect != nil)
+	m.logger.Debug("StatusLoop:", m.OnWsConnect != nil)
 	for {
 		if m.WsQuit {
 			return
 		}
 		if m.WsConnected {
 			if err := m.checkAlive(); err != nil {
-				logrus.Errorf("Connection is not alive: %#v", err)
+				m.logger.Errorf("Connection is not alive: %#v", err)
 			}
 			select {
 			case <-m.WsPingChan:
-				m.log.Debug("WS PONG received")
+				m.logger.Debug("WS PONG received")
 				backoff = time.Second * 60
 			case <-time.After(time.Second * 5):
 				if retries > 3 {
-					m.log.Debug("StatusLoop() timeout")
+					m.logger.Debug("StatusLoop() timeout")
 					m.Logout()
 					m.WsQuit = false
 					err := m.Login()
 					if err != nil {
-						logrus.Errorf("Login failed: %#v", err)
+						m.logger.Errorf("Login failed: %#v", err)
 						break
 					}
 					if m.OnWsConnect != nil {
diff --git a/matterclient/messages.go b/matterclient/messages.go
index c2325c09..b46feff1 100644
--- a/matterclient/messages.go
+++ b/matterclient/messages.go
@@ -10,14 +10,14 @@ func (m *MMClient) parseActionPost(rmsg *Message) {
 	// add post to cache, if it already exists don't relay this again.
 	// this should fix reposts
 	if ok, _ := m.lruCache.ContainsOrAdd(digestString(rmsg.Raw.Data["post"].(string)), true); ok {
-		m.log.Debugf("message %#v in cache, not processing again", rmsg.Raw.Data["post"].(string))
+		m.logger.Debugf("message %#v in cache, not processing again", rmsg.Raw.Data["post"].(string))
 		rmsg.Text = ""
 		return
 	}
 	data := model.PostFromJson(strings.NewReader(rmsg.Raw.Data["post"].(string)))
 	// we don't have the user, refresh the userlist
 	if m.GetUser(data.UserId) == nil {
-		m.log.Infof("User '%v' is not known, ignoring message '%#v'",
+		m.logger.Infof("User '%v' is not known, ignoring message '%#v'",
 			data.UserId, data)
 		return
 	}
@@ -54,7 +54,7 @@ func (m *MMClient) parseMessage(rmsg *Message) {
 		}
 	case "group_added":
 		if err := m.UpdateChannels(); err != nil {
-			m.log.Errorf("failed to update channels: %#v", err)
+			m.logger.Errorf("failed to update channels: %#v", err)
 		}
 		/*
 			case model.ACTION_USER_REMOVED:
@@ -178,18 +178,18 @@ func (m *MMClient) SendDirectMessage(toUserId string, msg string, rootId string)
 }
 
 func (m *MMClient) SendDirectMessageProps(toUserId string, msg string, rootId string, props map[string]interface{}) { //nolint:golint
-	m.log.Debugf("SendDirectMessage to %s, msg %s", toUserId, msg)
+	m.logger.Debugf("SendDirectMessage to %s, msg %s", toUserId, msg)
 	// create DM channel (only happens on first message)
 	_, resp := m.Client.CreateDirectChannel(m.User.Id, toUserId)
 	if resp.Error != nil {
-		m.log.Debugf("SendDirectMessage to %#v failed: %s", toUserId, resp.Error)
+		m.logger.Debugf("SendDirectMessage to %#v failed: %s", toUserId, resp.Error)
 		return
 	}
 	channelName := model.GetDMNameFromIds(toUserId, m.User.Id)
 
 	// update our channels
 	if err := m.UpdateChannels(); err != nil {
-		m.log.Errorf("failed to update channels: %#v", err)
+		m.logger.Errorf("failed to update channels: %#v", err)
 	}
 
 	// build & send the message
diff --git a/matterclient/users.go b/matterclient/users.go
index 3dea7ce5..11f22aa0 100644
--- a/matterclient/users.go
+++ b/matterclient/users.go
@@ -124,7 +124,7 @@ func (m *MMClient) UpdateUserNick(nick string) error {
 func (m *MMClient) UsernamesInChannel(channelId string) []string { //nolint:golint
 	res, resp := m.Client.GetChannelMembers(channelId, 0, 50000, "")
 	if resp.Error != nil {
-		m.log.Errorf("UsernamesInChannel(%s) failed: %s", channelId, resp.Error)
+		m.logger.Errorf("UsernamesInChannel(%s) failed: %s", channelId, resp.Error)
 		return []string{}
 	}
 	allusers := m.GetUsers()