Use prefixed-formatter for better logging

17 files changed, 71 insertions, 42 deletions

diff --git a/bridge/api/api.go b/bridge/api/api.go
index 6055cd5c..cbea9eee 100644
--- a/bridge/api/api.go
+++ b/bridge/api/api.go
@@ -30,7 +30,7 @@ var flog *log.Entry
 var protocol = "api"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Api {
diff --git a/bridge/bridge.go b/bridge/bridge.go
index 0a2bfed1..87db37e3 100644
--- a/bridge/bridge.go
+++ b/bridge/bridge.go
@@ -36,6 +36,12 @@ type Bridge struct {
 	Joined   map[string]bool
 }
 
+var flog *log.Entry
+
+func init() {
+	flog = log.WithFields(log.Fields{"prefix": "bridge"})
+}
+
 func New(cfg *config.Config, bridge *config.Bridge, c chan config.Message) *Bridge {
 	b := new(Bridge)
 	b.Channels = make(map[string]config.ChannelInfo)
@@ -100,7 +106,7 @@ func (b *Bridge) JoinChannels() error {
 func (b *Bridge) joinChannels(channels map[string]config.ChannelInfo, exists map[string]bool) error {
 	for ID, channel := range channels {
 		if !exists[ID] {
-			log.Infof("%s: joining %s (ID: %s)", b.Account, channel.Name, ID)
+			flog.Infof("%s: joining %s (ID: %s)", b.Account, channel.Name, ID)
 			err := b.JoinChannel(channel)
 			if err != nil {
 				return err
diff --git a/bridge/discord/discord.go b/bridge/discord/discord.go
index 70e11e0e..4ca68149 100644
--- a/bridge/discord/discord.go
+++ b/bridge/discord/discord.go
@@ -4,8 +4,8 @@ import (
 	"bytes"
 	"github.com/42wim/matterbridge/bridge/config"
 	"github.com/42wim/matterbridge/bridge/helper"
-	log "github.com/sirupsen/logrus"
 	"github.com/bwmarrin/discordgo"
+	log "github.com/sirupsen/logrus"
 	"regexp"
 	"strings"
 	"sync"
@@ -29,7 +29,7 @@ var flog *log.Entry
 var protocol = "discord"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *bdiscord {
diff --git a/bridge/gitter/gitter.go b/bridge/gitter/gitter.go
index 9f988f54..f11af6a7 100644
--- a/bridge/gitter/gitter.go
+++ b/bridge/gitter/gitter.go
@@ -21,7 +21,7 @@ var flog *log.Entry
 var protocol = "gitter"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Bgitter {
diff --git a/bridge/irc/irc.go b/bridge/irc/irc.go
index d7b45b7f..958eb6c1 100644
--- a/bridge/irc/irc.go
+++ b/bridge/irc/irc.go
@@ -6,11 +6,11 @@ import (
 	"fmt"
 	"github.com/42wim/matterbridge/bridge/config"
 	"github.com/42wim/matterbridge/bridge/helper"
-	log "github.com/sirupsen/logrus"
 	"github.com/lrstanley/girc"
 	"github.com/paulrosania/go-charset/charset"
 	_ "github.com/paulrosania/go-charset/data"
 	"github.com/saintfish/chardet"
+	log "github.com/sirupsen/logrus"
 	"io"
 	"io/ioutil"
 	"net"
@@ -37,7 +37,7 @@ var flog *log.Entry
 var protocol = "irc"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Birc {
diff --git a/bridge/matrix/matrix.go b/bridge/matrix/matrix.go
index d0b435e6..56616357 100644
--- a/bridge/matrix/matrix.go
+++ b/bridge/matrix/matrix.go
@@ -25,7 +25,7 @@ var flog *log.Entry
 var protocol = "matrix"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Bmatrix {
diff --git a/bridge/mattermost/mattermost.go b/bridge/mattermost/mattermost.go
index 2b93b9bf..bd1292bb 100644
--- a/bridge/mattermost/mattermost.go
+++ b/bridge/mattermost/mattermost.go
@@ -42,7 +42,7 @@ var flog *log.Entry
 var protocol = "mattermost"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Bmattermost {
diff --git a/bridge/rocketchat/rocketchat.go b/bridge/rocketchat/rocketchat.go
index 893cea74..dec02e5d 100644
--- a/bridge/rocketchat/rocketchat.go
+++ b/bridge/rocketchat/rocketchat.go
@@ -22,7 +22,7 @@ var flog *log.Entry
 var protocol = "rocketchat"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Brocketchat {
diff --git a/bridge/slack/slack.go b/bridge/slack/slack.go
index fa49da90..80886446 100644
--- a/bridge/slack/slack.go
+++ b/bridge/slack/slack.go
@@ -40,7 +40,7 @@ var flog *log.Entry
 var protocol = "slack"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Bslack {
diff --git a/bridge/sshchat/sshchat.go b/bridge/sshchat/sshchat.go
index 4b91df01..cce4da59 100644
--- a/bridge/sshchat/sshchat.go
+++ b/bridge/sshchat/sshchat.go
@@ -20,7 +20,7 @@ var flog *log.Entry
 var protocol = "sshchat"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Bsshchat {
diff --git a/bridge/steam/steam.go b/bridge/steam/steam.go
index 2ce6e0bc..b630c428 100644
--- a/bridge/steam/steam.go
+++ b/bridge/steam/steam.go
@@ -25,7 +25,7 @@ var flog *log.Entry
 var protocol = "steam"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Bsteam {
diff --git a/bridge/telegram/telegram.go b/bridge/telegram/telegram.go
index 63853578..e411690c 100644
--- a/bridge/telegram/telegram.go
+++ b/bridge/telegram/telegram.go
@@ -21,7 +21,7 @@ var flog *log.Entry
 var protocol = "telegram"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Btelegram {
diff --git a/bridge/xmpp/xmpp.go b/bridge/xmpp/xmpp.go
index c2f63e7a..45daee17 100644
--- a/bridge/xmpp/xmpp.go
+++ b/bridge/xmpp/xmpp.go
@@ -22,7 +22,7 @@ var flog *log.Entry
 var protocol = "xmpp"
 
 func init() {
-	flog = log.WithFields(log.Fields{"module": protocol})
+	flog = log.WithFields(log.Fields{"prefix": protocol})
 }
 
 func New(cfg *config.BridgeConfig) *Bxmpp {
diff --git a/gateway/gateway.go b/gateway/gateway.go
index 27f6ffca..e2db20eb 100644
--- a/gateway/gateway.go
+++ b/gateway/gateway.go
@@ -34,6 +34,12 @@ type BrMsgID struct {
 	ChannelID string
 }
 
+var flog *log.Entry
+
+func init() {
+	flog = log.WithFields(log.Fields{"prefix": "gateway"})
+}
+
 func New(cfg config.Gateway, r *Router) *Gateway {
 	gw := &Gateway{Channels: make(map[string]*config.ChannelInfo), Message: r.Message,
 		Router: r, Bridges: make(map[string]*bridge.Bridge), Config: r.Config}
@@ -78,10 +84,10 @@ func (gw *Gateway) reconnectBridge(br *bridge.Bridge) {
 	br.Disconnect()
 	time.Sleep(time.Second * 5)
 RECONNECT:
-	log.Infof("Reconnecting %s", br.Account)
+	flog.Infof("Reconnecting %s", br.Account)
 	err := br.Connect()
 	if err != nil {
-		log.Errorf("Reconnection failed: %s. Trying again in 60 seconds", err)
+		flog.Errorf("Reconnection failed: %s. Trying again in 60 seconds", err)
 		time.Sleep(time.Second * 60)
 		goto RECONNECT
 	}
@@ -145,7 +151,7 @@ func (gw *Gateway) getDestChannel(msg *config.Message, dest bridge.Bridge) []con
 			continue
 		}
 
-		// do samechannelgateway logic
+		// do samechannelgateway flogic
 		if channel.SameChannel[msg.Gateway] {
 			if msg.Channel == channel.Name && msg.Account != dest.Account {
 				channels = append(channels, *channel)
@@ -196,7 +202,7 @@ func (gw *Gateway) handleMessage(msg config.Message, dest *bridge.Bridge) []*BrM
 
 	// broadcast to every out channel (irc QUIT)
 	if msg.Channel == "" && msg.Event != config.EVENT_JOIN_LEAVE {
-		log.Debug("empty channel")
+		flog.Debug("empty channel")
 		return brMsgIDs
 	}
 	originchannel := msg.Channel
@@ -214,7 +220,7 @@ func (gw *Gateway) handleMessage(msg config.Message, dest *bridge.Bridge) []*BrM
 				continue
 			}
 		}
-		log.Debugf("Sending %#v from %s (%s) to %s (%s)", msg, msg.Account, originchannel, dest.Account, channel.Name)
+		flog.Debugf("Sending %#v from %s (%s) to %s (%s)", msg, msg.Account, originchannel, dest.Account, channel.Name)
 		msg.Channel = channel.Name
 		msg.Avatar = gw.modifyAvatar(origmsg, dest)
 		msg.Username = gw.modifyUsername(origmsg, dest)
@@ -258,12 +264,12 @@ func (gw *Gateway) ignoreMessage(msg *config.Message) bool {
 				len(msg.Extra[config.EVENT_FILE_FAILURE_SIZE]) > 0) {
 			return false
 		}
-		log.Debugf("ignoring empty message %#v from %s", msg, msg.Account)
+		flog.Debugf("ignoring empty message %#v from %s", msg, msg.Account)
 		return true
 	}
 	for _, entry := range strings.Fields(gw.Bridges[msg.Account].Config.IgnoreNicks) {
 		if msg.Username == entry {
-			log.Debugf("ignoring %s from %s", msg.Username, msg.Account)
+			flog.Debugf("ignoring %s from %s", msg.Username, msg.Account)
 			return true
 		}
 	}
@@ -272,11 +278,11 @@ func (gw *Gateway) ignoreMessage(msg *config.Message) bool {
 		if entry != "" {
 			re, err := regexp.Compile(entry)
 			if err != nil {
-				log.Errorf("incorrect regexp %s for %s", entry, msg.Account)
+				flog.Errorf("incorrect regexp %s for %s", entry, msg.Account)
 				continue
 			}
 			if re.MatchString(msg.Text) {
-				log.Debugf("matching %s. ignoring %s from %s", entry, msg.Text, msg.Account)
+				flog.Debugf("matching %s. ignoring %s from %s", entry, msg.Text, msg.Account)
 				return true
 			}
 		}
@@ -303,7 +309,7 @@ func (gw *Gateway) modifyUsername(msg config.Message, dest *bridge.Bridge) strin
 		// TODO move compile to bridge init somewhere
 		re, err := regexp.Compile(search)
 		if err != nil {
-			log.Errorf("regexp in %s failed: %s", msg.Account, err)
+			flog.Errorf("regexp in %s failed: %s", msg.Account, err)
 			break
 		}
 		msg.Username = re.ReplaceAllString(msg.Username, replace)
@@ -351,7 +357,7 @@ func (gw *Gateway) modifyMessage(msg *config.Message) {
 		// TODO move compile to bridge init somewhere
 		re, err := regexp.Compile(search)
 		if err != nil {
-			log.Errorf("regexp in %s failed: %s", msg.Account, err)
+			flog.Errorf("regexp in %s failed: %s", msg.Account, err)
 			break
 		}
 		msg.Text = re.ReplaceAllString(msg.Text, replace)
@@ -383,10 +389,10 @@ func (gw *Gateway) handleFiles(msg *config.Message) {
 			req.Header.Set("Content-Type", "binary/octet-stream")
 			_, err := client.Do(req)
 			if err != nil {
-				log.Errorf("mediaserver upload failed: %#v", err)
+				flog.Errorf("mediaserver upload failed: %#v", err)
 				continue
 			}
-			log.Debugf("mediaserver download URL = %s", durl)
+			flog.Debugf("mediaserver download URL = %s", durl)
 			// we uploaded the file successfully. Add the SHA
 			extra.SHA = sha1sum
 			msg.Extra["file"][i] = extra
diff --git a/gateway/router.go b/gateway/router.go
index e1944d4a..7c3d8585 100644
--- a/gateway/router.go
+++ b/gateway/router.go
@@ -5,7 +5,7 @@ import (
 	"github.com/42wim/matterbridge/bridge"
 	"github.com/42wim/matterbridge/bridge/config"
 	"github.com/42wim/matterbridge/gateway/samechannel"
-	log "github.com/sirupsen/logrus"
+	//log "github.com/sirupsen/logrus"
 	//	"github.com/davecgh/go-spew/spew"
 	"time"
 )
@@ -42,13 +42,13 @@ func NewRouter(cfg *config.Config) (*Router, error) {
 func (r *Router) Start() error {
 	m := make(map[string]*bridge.Bridge)
 	for _, gw := range r.Gateways {
-		log.Infof("Parsing gateway %s", gw.Name)
+		flog.Infof("Parsing gateway %s", gw.Name)
 		for _, br := range gw.Bridges {
 			m[br.Account] = br
 		}
 	}
 	for _, br := range m {
-		log.Infof("Starting bridge: %s ", br.Account)
+		flog.Infof("Starting bridge: %s ", br.Account)
 		err := br.Connect()
 		if err != nil {
 			return fmt.Errorf("Bridge %s failed to start: %v", br.Account, err)
diff --git a/matterbridge.go b/matterbridge.go
index 0691a1f0..5e1e3f46 100644
--- a/matterbridge.go
+++ b/matterbridge.go
@@ -18,7 +18,8 @@ var (
 )
 
 func main() {
-	log.SetFormatter(&prefixed.TextFormatter{FullTimestamp: true})
+	log.SetFormatter(&prefixed.TextFormatter{PrefixPadding: 10, DisableColors: true, FullTimestamp: true})
+	flog := log.WithFields(log.Fields{"prefix": "main"})
 	flagConfig := flag.String("conf", "matterbridge.toml", "config file")
 	flagDebug := flag.Bool("debug", false, "enable debug")
 	flagVersion := flag.Bool("version", false, "show version")
@@ -33,24 +34,24 @@ func main() {
 		return
 	}
 	if *flagDebug || os.Getenv("DEBUG") == "1" {
-		log.SetFormatter(&prefixed.TextFormatter{FullTimestamp: false})
-		log.Info("Enabling debug")
+		log.SetFormatter(&prefixed.TextFormatter{PrefixPadding: 10, DisableColors: true, FullTimestamp: false})
+		flog.Info("Enabling debug")
 		log.SetLevel(log.DebugLevel)
 	}
-	log.Printf("Running version %s %s", version, githash)
+	flog.Printf("Running version %s %s", version, githash)
 	if strings.Contains(version, "-dev") {
-		log.Println("WARNING: THIS IS A DEVELOPMENT VERSION. Things may break.")
+		flog.Println("WARNING: THIS IS A DEVELOPMENT VERSION. Things may break.")
 	}
 	cfg := config.NewConfig(*flagConfig)
 	cfg.General.Debug = *flagDebug
 	r, err := gateway.NewRouter(cfg)
 	if err != nil {
-		log.Fatalf("Starting gateway failed: %s", err)
+		flog.Fatalf("Starting gateway failed: %s", err)
 	}
 	err = r.Start()
 	if err != nil {
-		log.Fatalf("Starting gateway failed: %s", err)
+		flog.Fatalf("Starting gateway failed: %s", err)
 	}
-	log.Printf("Gateway(s) started succesfully. Now relaying messages")
+	flog.Printf("Gateway(s) started succesfully. Now relaying messages")
 	select {}
 }
diff --git a/vendor/github.com/x-cray/logrus-prefixed-formatter/formatter.go b/vendor/github.com/x-cray/logrus-prefixed-formatter/formatter.go
index 1235bcc3..7cb807da 100644
--- a/vendor/github.com/x-cray/logrus-prefixed-formatter/formatter.go
+++ b/vendor/github.com/x-cray/logrus-prefixed-formatter/formatter.go
@@ -11,8 +11,8 @@ import (
 	"sync"
 	"time"
 
-	"github.com/sirupsen/logrus"
 	"github.com/mgutz/ansi"
+	"github.com/sirupsen/logrus"
 	"golang.org/x/crypto/ssh/terminal"
 )
 
@@ -110,6 +110,11 @@ type TextFormatter struct {
 	// Its default value is zero, which means no padding will be applied for msg.
 	SpacePadding int
 
+	// Pad prefix field with spaces on the right for display.
+	// The value for this parameter will be the size of padding.
+	// Its default value is zero, which means no padding will be applied for prefix.
+	PrefixPadding int
+
 	// Color scheme to use.
 	colorScheme *compiledColorScheme
 
@@ -253,14 +258,25 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys
 	prefix := ""
 	message := entry.Message
 
+	adjustedPrefixPadding := f.PrefixPadding //compensate for ANSI color sequences
+
 	if prefixValue, ok := entry.Data["prefix"]; ok {
+		rawPrefixLength := len(prefixValue.(string))
 		prefix = colorScheme.PrefixColor(" " + prefixValue.(string) + ":")
+		adjustedPrefixPadding = f.PrefixPadding + (len(prefix) - rawPrefixLength - 1)
 	} else {
 		prefixValue, trimmedMsg := extractPrefix(entry.Message)
+		rawPrefixLength := len(prefixValue)
 		if len(prefixValue) > 0 {
 			prefix = colorScheme.PrefixColor(" " + prefixValue + ":")
 			message = trimmedMsg
 		}
+		adjustedPrefixPadding = f.PrefixPadding + (len(prefix) - rawPrefixLength - 1)
+	}
+
+	prefixFormat := "%s"
+	if f.PrefixPadding != 0 {
+		prefixFormat = fmt.Sprintf("%%-%ds", adjustedPrefixPadding)
 	}
 
 	messageFormat := "%s"
@@ -269,7 +285,7 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys
 	}
 
 	if f.DisableTimestamp {
-		fmt.Fprintf(b, "%s%s "+messageFormat, level, prefix, message)
+		fmt.Fprintf(b, "%s"+prefixFormat+" "+messageFormat, level, prefix, message)
 	} else {
 		var timestamp string
 		if !f.FullTimestamp {
@@ -277,7 +293,7 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys
 		} else {
 			timestamp = fmt.Sprintf("[%s]", entry.Time.Format(timestampFormat))
 		}
-		fmt.Fprintf(b, "%s %s%s "+messageFormat, colorScheme.TimestampColor(timestamp), level, prefix, message)
+		fmt.Fprintf(b, "%s %s"+prefixFormat+" "+messageFormat, colorScheme.TimestampColor(timestamp), level, prefix, message)
 	}
 	for _, k := range keys {
 		if k != "prefix" {