Improved logging

Made better use of warn/info/debug levels. Introduced LogginMiddleware to router. Removed second logging library from project. Fixes #53.
fleaz · Mar 26, 2020 · 59369ff · 59369ff
1 parent 8dc00a3
commit 59369ff
Show file tree

Hide file tree

Showing 9 changed files with 93 additions and 33 deletions.
diff --git a/go.mod b/go.mod
@@ -7,10 +7,10 @@ require (
 	github.com/dustin/go-humanize v1.0.0
 	github.com/lrstanley/girc v0.0.0-20181114171214-3aee8c249519
 	github.com/mitchellh/mapstructure v1.1.2 // indirect
-	github.com/sirupsen/logrus v1.2.0
+	github.com/sirupsen/logrus v1.4.2
 	github.com/spf13/cast v1.3.0 // indirect
 	github.com/spf13/pflag v1.0.3 // indirect
 	github.com/spf13/viper v1.2.1
-	golang.org/x/crypto v0.0.0-20181112202954-3d3f9f413869 // indirect
-	golang.org/x/sys v0.0.0-20181121002834-0cf1ed9e522b // indirect
+	github.com/stretchr/testify v1.3.0 // indirect
+	gopkg.in/yaml.v2 v2.2.4 // indirect
 )
diff --git a/go.sum b/go.sum
@@ -1,5 +1,6 @@
 github.com/BurntSushi/toml v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ=
 github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03qcyfWMU=
+github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/dustin/go-humanize v1.0.0 h1:VSnTsYCnlFHaM2/igO1h6X3HA71jcobQuxemgkq4zYo=
@@ -21,8 +22,8 @@ github.com/pelletier/go-toml v1.2.0 h1:T5zMGML61Wp+FlcbWjRDT7yAxhJNAiPPLOFECq181
 github.com/pelletier/go-toml v1.2.0/go.mod h1:5z9KED0ma1S8pY6P1sdut58dfprrGBbd/94hg7ilaic=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
-github.com/sirupsen/logrus v1.2.0 h1:juTguoYk5qI21pwyTXY3B3Y5cOTH3ZUyZCg1v/mihuo=
-github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
+github.com/sirupsen/logrus v1.4.2 h1:SPIRibHv4MatM3XXNO2BJeFLZwZ2LvZgfQ5+UNI2im4=
+github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
 github.com/spf13/afero v1.1.2 h1:m8/z1t7/fwjysjQRYbP0RD+bUIF/8tJwPdEZsI83ACI=
 github.com/spf13/afero v1.1.2/go.mod h1:j4pytiNVoe2o6bmDsKpLACNPDBIoEAkihy7loJ1B0CQ=
 github.com/spf13/cast v1.2.0/go.mod h1:r2rcYCSwa1IExKTDiTfzaxqT2FNHs8hODu4LnUfgKEg=
@@ -35,19 +36,20 @@ github.com/spf13/pflag v1.0.3 h1:zPAT6CGy6wXeQ7NtTnaTerfKOsV6V6F8agHXFiazDkg=
 github.com/spf13/pflag v1.0.3/go.mod h1:DYY7MBk1bdzusC3SYhjObp+wFpr4gzcvqqNjLnInEg4=
 github.com/spf13/viper v1.2.1 h1:bIcUwXqLseLF3BDAZduuNfekWG87ibtFxi59Bq+oI9M=
 github.com/spf13/viper v1.2.1/go.mod h1:P4AexN0a+C9tGAnUFNwDMYYZv3pjFuvmeiMyKRaNVlI=
+github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/testify v1.2.2 h1:bSDNvY7ZPG5RlJ8otE/7V6gMiyenm9RtJ7IUVIAoJ1w=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
-golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
-golang.org/x/crypto v0.0.0-20181112202954-3d3f9f413869 h1:kkXA53yGe04D0adEYJwEVQjeBppL01Exg+fnMjfUraU=
-golang.org/x/crypto v0.0.0-20181112202954-3d3f9f413869/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
-golang.org/x/sys v0.0.0-20180905080454-ebe1bf3edb33/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+github.com/stretchr/testify v1.3.0 h1:TivCn/peBQ7UY8ooIcPgZFpTNSz0Q2U6UrFlUfqbe0Q=
+github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 golang.org/x/sys v0.0.0-20180906133057-8cf3aee42992/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
-golang.org/x/sys v0.0.0-20181121002834-0cf1ed9e522b h1:fpg9kqwtLzitbbnpLJATV5Ty8sDv8sJ2ii9+e6fG89A=
-golang.org/x/sys v0.0.0-20181121002834-0cf1ed9e522b/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20190422165155-953cdadca894 h1:Cz4ceDQGXuKRnVBDTS23GTn/pU5OE2C0WrNTOYK1Uuc=
+golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v2 v2.2.1 h1:mUhvW9EsL+naU5Q3cakzfE91YhliOondGd6ZrsDBHQE=
 gopkg.in/yaml.v2 v2.2.1/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
+gopkg.in/yaml.v2 v2.2.4 h1:/eiJrUcujPVeJ3xlSWaiNi3uSVmDGBK1pDHUHAnao1I=
+gopkg.in/yaml.v2 v2.2.4/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
diff --git a/input/gitlab.go b/input/gitlab.go
@@ -55,7 +55,7 @@ func (m *GitlabModule) Init(c *viper.Viper, channel *chan IRCMessage) {
 		if 0 < commitLimit && commitLimit <= 20 {
 			m.commitLimit = commitLimit
 		} else {
-			log.Debug("commit_limit was set to an invalid value. Using default of 3")
+			log.Warn("commit_limit was set to an invalid value. Using default of 3")
 			m.commitLimit = 3
 		}
 	} else {
@@ -84,6 +84,11 @@ func (m GitlabModule) sendMessage(message string, projectName string, namespace
 		var event IRCMessage
 		event.Messages = append(event.Messages, message)
 		event.Channel = channelName
+		event.generateID()
+		log.WithFields(log.Fields{
+			"MsgID":  event.ID,
+			"Module": "Gitlab",
+		}).Info("Dispatching message to IRC handler")
 		m.channel <- event
 	}
 
@@ -189,11 +194,13 @@ func (m GitlabModule) GetHandler() http.HandlerFunc {
 	}
 
 	return func(wr http.ResponseWriter, req *http.Request) {
-		log.Debug("Got a request for the GitlabModule")
 		defer req.Body.Close()
 		decoder := json.NewDecoder(req.Body)
 
 		var eventType = req.Header.Get("X-Gitlab-Event")
+		log.WithFields(log.Fields{
+			"EventType": eventType,
+		}).Debug("Got a request for the GitlabModule")
 
 		type Project struct {
 			Name      string `json:"name"`
@@ -287,7 +294,6 @@ func (m GitlabModule) GetHandler() http.HandlerFunc {
 		switch eventType {
 
 		case "Pipeline Hook":
-			log.Printf("Got a Hook for a Pipeline Event")
 			var pipelineEvent PipelineEvent
 			if err := decoder.Decode(&pipelineEvent); err != nil {
 				log.Error(err)
@@ -319,7 +325,6 @@ func (m GitlabModule) GetHandler() http.HandlerFunc {
 			}
 
 		case "Job Hook":
-			log.Printf("Got a Hook for a Job Event")
 			var jobEvent JobEvent
 			if err := decoder.Decode(&jobEvent); err != nil {
 				log.Error(err)
@@ -344,7 +349,6 @@ func (m GitlabModule) GetHandler() http.HandlerFunc {
 			m.sendMessage(buf.String(), jobEvent.Repository.Name, namespace)
 
 		case "Merge Request Hook", "Merge Request Event":
-			log.Printf("Got Hook for a Merge Request")
 			var mergeEvent MergeEvent
 			if err := decoder.Decode(&mergeEvent); err != nil {
 				log.Error(err)
@@ -358,7 +362,6 @@ func (m GitlabModule) GetHandler() http.HandlerFunc {
 			m.sendMessage(buf.String(), mergeEvent.Project.Name, mergeEvent.Project.Namespace)
 
 		case "Issue Hook", "Issue Event":
-			log.Printf("Got Hook for an Issue")
 			var issueEvent IssueEvent
 			if err := decoder.Decode(&issueEvent); err != nil {
 				log.Error(err)
@@ -372,7 +375,6 @@ func (m GitlabModule) GetHandler() http.HandlerFunc {
 			m.sendMessage(buf.String(), issueEvent.Project.Name, issueEvent.Project.Namespace)
 
 		case "Push Hook", "Push Event":
-			log.Printf("Got Hook for a Push Event")
 			var pushEvent PushEvent
 			if err := decoder.Decode(&pushEvent); err != nil {
 				log.Error(err)
@@ -449,7 +451,9 @@ func (m GitlabModule) GetHandler() http.HandlerFunc {
 			}
 
 		default:
-			log.Printf("Unknown event: %s", eventType)
+			log.WithFields(log.Fields{
+				"EventType": eventType,
+			}).Warn("Can't handle this event type")
 		}
 
 	}

diff --git a/input/helper.go b/input/helper.go
@@ -1,11 +1,14 @@
 package input
 
 import (
+	"math/rand"
 	"net/http"
 
 	"github.com/spf13/viper"
 )
 
+var letterRunes = []rune("0123456789ABCDEFGHIJKLMNOPQRSTUVWXYZ")
+
 // Module defines a common interface for all CptHook modules
 type Module interface {
 	Init(c *viper.Viper, channel *chan IRCMessage)
@@ -15,6 +18,15 @@ type Module interface {
 
 // IRCMessage are send over the inputChannel from the different modules
 type IRCMessage struct {
+	ID       string
 	Messages []string
 	Channel  string
 }
+
+func (m *IRCMessage) generateID() {
+	b := make([]rune, 6)
+	for i := range b {
+		b[i] = letterRunes[rand.Intn(len(letterRunes))]
+	}
+	m.ID = string(b)
+}
diff --git a/input/icinga2.go b/input/icinga2.go
@@ -180,6 +180,11 @@ func (m Icinga2Module) sendMessage(message string, notification Notification) {
 		var event IRCMessage
 		event.Messages = append(event.Messages, message)
 		event.Channel = channelName
+		event.generateID()
+		log.WithFields(log.Fields{
+			"MsgID":  event.ID,
+			"Module": "Icinga2",
+		}).Info("Dispatching message to IRC handler")
 		m.channel <- event
 	}
 
@@ -279,7 +284,6 @@ func (m Icinga2Module) GetHandler() http.HandlerFunc {
 	}
 
 	return func(wr http.ResponseWriter, req *http.Request) {
-		log.Debug("[icinga2] Got a request for the Icinga2Module")
 		defer req.Body.Close()
 		decoder := json.NewDecoder(req.Body)
 
@@ -290,11 +294,13 @@ func (m Icinga2Module) GetHandler() http.HandlerFunc {
 			return
 		}
 
+		log.WithFields(log.Fields{
+			"event": notification.Target,
+		}).Warn("Got a request for the Icinga2Module")
+
 		switch notification.Target {
 
 		case "service":
-			log.Printf("[icinga2] Got a Hook for a Service Event")
-
 			if notification.Type == "ACKNOWLEDGEMENT" { // Acknowledge
 				err = serviceAckTemplate.Execute(&buf, &notification)
 				m.sendMessage(buf.String(), notification)
@@ -319,8 +325,6 @@ func (m Icinga2Module) GetHandler() http.HandlerFunc {
 			}
 
 		case "host":
-			log.Printf("[icinga2] Got a Hook for a Host Event")
-
 			if notification.Type == "ACKNOWLEDGEMENT" { // Acknowledge
 				err = hostAckTemplate.Execute(&buf, &notification)
 				m.sendMessage(buf.String(), notification)
@@ -344,7 +348,9 @@ func (m Icinga2Module) GetHandler() http.HandlerFunc {
 				m.sendMessage(buf.String(), notification)
 			}
 		default:
-			log.Printf("[icinga2] Unknown event: %s", notification.Target)
+			log.WithFields(log.Fields{
+				"event": notification.Target,
+			}).Warn("Unknown event")
 		}
 
 	}

diff --git a/input/prometheus.go b/input/prometheus.go
@@ -191,6 +191,11 @@ func (m PrometheusModule) GetHandler() http.HandlerFunc {
 				_ = hostListTemplate.Execute(&buf, &instanceList)
 				event.Messages = append(event.Messages, buf.String())
 				event.Channel = m.defaultChannel
+				event.generateID()
+				log.WithFields(log.Fields{
+					"MsgID":  event.ID,
+					"Module": "Prometheus",
+				}).Info("Dispatching message to IRC handler")
 				m.channel <- event
 			}
 		}

diff --git a/input/simple.go b/input/simple.go
@@ -45,9 +45,15 @@ func (m SimpleModule) GetHandler() http.HandlerFunc {
 		}
 
 		// Send message
-		m.channel <- IRCMessage{
+		msg := IRCMessage{
 			Messages: lines,
 			Channel:  channel,
 		}
+		msg.generateID()
+		log.WithFields(log.Fields{
+			"MsgID":  msg.ID,
+			"Module": "Simple",
+		}).Info("Dispatching message to IRC handler")
+		m.channel <- msg
 	}
 }
diff --git a/irc.go b/irc.go
@@ -9,6 +9,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/sirupsen/logrus"
 	log "github.com/sirupsen/logrus"
 
 	"github.com/lrstanley/girc"
@@ -29,6 +30,7 @@ func ircConnection(config *viper.Viper, channelList []string) {
 	}
 
 	if config.IsSet("auth") {
+		log.Info("Configuring SASL-Auth for IRC connection")
 		auth := config.Sub("auth")
 
 		switch auth.GetString("method") {
@@ -49,7 +51,7 @@ func ircConnection(config *viper.Viper, channelList []string) {
 	}
 
 	if config.IsSet("ssl") {
-		// Enable / Disable SSL
+		log.Info("Configuring SSL for IRC connection")
 		config.SetDefault("ssl.enabled", true)
 		clientConfig.SSL = config.GetBool("ssl.enabled")
 
@@ -59,6 +61,9 @@ func ircConnection(config *viper.Viper, channelList []string) {
 
 		// Configure server certificate
 		if cafile := config.GetString("ssl.cafile"); cafile != "" {
+			log.WithFields(logrus.Fields{
+				"cafile": cafile,
+			}).Info("Configuring custpm for IRC connection")
 			caCert, err := ioutil.ReadFile(cafile)
 			if err != nil {
 				log.Fatal(err)
@@ -70,6 +75,7 @@ func ircConnection(config *viper.Viper, channelList []string) {
 
 		// Configure client certificate
 		if config.IsSet("ssl.client_cert") {
+			log.Info("Configuring SSL client certificate for IRC connection")
 			certfile := config.GetString("ssl.client_cert.certfile")
 			keyfile := config.GetString("ssl.client_cert.keyfile")
 
@@ -86,6 +92,7 @@ func ircConnection(config *viper.Viper, channelList []string) {
 	client = girc.New(clientConfig)
 
 	client.Handlers.Add(girc.CONNECTED, func(c *girc.Client, e girc.Event) {
+		log.Info("Sucessfully connected to the IRC server. Starting to join channel.")
 		clientLock.Unlock()
 		for _, name := range removeDuplicates(channelList) {
 			joinChannel(name)
@@ -94,8 +101,10 @@ func ircConnection(config *viper.Viper, channelList []string) {
 
 	client.Handlers.Add(girc.PRIVMSG, func(c *girc.Client, e girc.Event) {
 		if e.IsFromUser() {
-			log.Debugf("Received a query: %v", e)
-			message := "Hi. I'm a CptHook bot."
+			log.WithFields(log.Fields{
+				"Event": e.String(),
+			}).Debug("Received a PRIMSG")
+			message := "Hi. I'm a CptHook bot. Visit https://github.com/fleaz/CptHook to learn more"
 			if version == "dev" {
 				message += fmt.Sprintf(" I was compiled by hand at %v", date)
 			} else {
@@ -108,6 +117,7 @@ func ircConnection(config *viper.Viper, channelList []string) {
 	// Start thread to process message queue
 	go channelReceiver()
 
+	log.Info("Connecting to IRC server")
 	for {
 		if err := client.Connect(); err != nil {
 			clientLock.Lock()
@@ -142,7 +152,11 @@ func channelReceiver() {
 	log.Info("ChannelReceiver started")
 
 	for elem := range inputChannel {
-		log.Debug("Took IRC event out of channel.")
+		log.WithFields(log.Fields{
+			"MsgID":   elem.ID,
+			"text":    elem.Messages,
+			"channel": elem.Channel,
+		}).Debug("IRC handler received a message")
 		joinChannel(elem.Channel)
 		for _, message := range elem.Messages {
 			clientLock.RLock()
@@ -161,7 +175,7 @@ func joinChannel(newChannel string) {
 
 	log.WithFields(log.Fields{
 		"channel": newChannel,
-	}).Debug("Need to join new channel")
+	}).Info("Need to join a new channel")
 
 	clientLock.RLock()
 	client.Cmd.Join(newChannel)

diff --git a/main.go b/main.go
@@ -92,6 +92,18 @@ func validateConfig(c Configuration) {
 
 }
 
+func loggingMiddleware(next http.HandlerFunc) http.HandlerFunc {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		log.WithFields(log.Fields{
+			"remote": r.RemoteAddr,
+			"method": r.Method,
+			"host":   r.Host,
+			"uri":    r.URL,
+		}).Debug("Received HTTP request")
+		next.ServeHTTP(w, r)
+	})
+}
+
 func main() {
 	confDirPtr := flag.String("config", "/etc/cpthook.yml", "Path to the configfile")
 	flag.Parse()
@@ -130,8 +142,7 @@ func main() {
 		configPath := fmt.Sprintf("modules.%s", blockName)
 		module.Init(viper.Sub(configPath), &inputChannel)
 		channelList = append(channelList, module.GetChannelList()...)
-		http.HandleFunc(blockConfig.Endpoint, module.GetHandler())
-
+		http.HandleFunc(blockConfig.Endpoint, loggingMiddleware(module.GetHandler()))
 	}
 
 	// Start IRC connection