From bf21604d425b4feb1b95e4e94643e7a658eeea90 Mon Sep 17 00:00:00 2001 From: Wim Date: Sat, 23 Feb 2019 22:51:27 +0100 Subject: Make all loggers derive from non-default instance (#728) --- matterclient/channels.go | 13 +++---- matterclient/helpers.go | 30 +++++++-------- matterclient/matterclient.go | 88 +++++++++++++++++++++++++++++++------------- matterclient/messages.go | 12 +++--- matterclient/users.go | 2 +- 5 files changed, 90 insertions(+), 55 deletions(-) (limited to 'matterclient') 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() -- cgit v1.2.3