Logging (#22)

using logrus for logging.

Initial commit for using logrus for logging.
Two different types of logs are persisted.
1. task ranker logs pertaining to the library. Uses text formatter.
2. task ranking results logs pertaining to the results of executing
	the task ranking strategy. Uses json formatter.

Implemented hooks that wrap around io.Writer that persist the log
to the configured file if the provided topics are found as keys in
the fields.

Author: pradykaushik

README.md

@@ -148,3 +148,13 @@ HOST = localhost
 
 #### Tear-Down
 Once finished testing, tear down the test environment by running [`./tear_down_test_env`](./tear_down_test_env).
+
+### Logs
+Task Ranker uses [logrus](https://github.com/sirupsen/logrus) for logging. To prevent logs from Task Ranker
+mixing in with logs from the application that is using it, console logging is disabled.
+There are [two types of logs](./logger/logger.go) as mentioned below. 
+1. Task Ranker logs - These logs are Task Ranker specific and correspond to functioning of the library. 
+    These logs are written to a file named **_task\_ranker\_logs\_\<timestamp\>.log_**.
+2. Task Ranking Results logs - These are the results of task ranking using one of task ranking strategies.
+    These logs are written to a file named **_task\_ranking\_results\_\<timestamp\>.log_**. To simplify parsing
+    these logs are written in JSON format.

datafetcher/prometheus/dataFetcher.go

@@ -18,11 +18,13 @@ import (
 	"context"
 	"github.com/pkg/errors"
 	"github.com/pradykaushik/task-ranker/datafetcher"
+	"github.com/pradykaushik/task-ranker/logger"
 	"github.com/pradykaushik/task-ranker/query"
 	"github.com/pradykaushik/task-ranker/strategies"
 	"github.com/prometheus/client_golang/api"
 	"github.com/prometheus/client_golang/api/prometheus/v1"
 	"github.com/prometheus/common/model"
+	"github.com/sirupsen/logrus"
 	"net/http"
 	"time"
 )
@@ -94,13 +96,20 @@ func (f *DataFetcher) Fetch() (result model.Value, err error) {
 	var client api.Client
 	client, err = api.NewClient(api.Config{Address: f.endpoint})
 	if err != nil {
-		err = errors.Wrap(err, "failed to fetch data from prometheus")
+		err = errors.Wrap(err, "failed to create prometheus client")
 		return
 	}
 	v1Api := v1.NewAPI(client)
 	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
 	defer cancel()
 	// TODO do not ignore warnings. maybe log them?
 	result, _, err = v1Api.Query(ctx, queryString, time.Now())
+	if err == nil {
+		logger.WithFields(logrus.Fields{
+			"stage":        "data-fetcher",
+			"query":        queryString,
+			"query_result": result,
+		}).Log(logrus.InfoLevel, "data fetched")
+	}
 	return
 }

go.mod

@@ -9,5 +9,6 @@ require (
 	github.com/prometheus/client_golang v1.6.0
 	github.com/prometheus/common v0.9.1
 	github.com/robfig/cron/v3 v3.0.0
+	github.com/sirupsen/logrus v1.6.0
 	github.com/stretchr/testify v1.6.0
 )

go.sum

@@ -33,6 +33,7 @@ github.com/json-iterator/go v1.1.9 h1:9yzud/Ht36ygwatGx56VwCZtlI/2AD15T1X2sjSuGn
 github.com/json-iterator/go v1.1.9/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
 github.com/julienschmidt/httprouter v1.2.0/go.mod h1:SYymIcj16QtmaHHD7aYtjjsJG7VTCxuUUipMqKk8s4w=
 github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
+github.com/konsorten/go-windows-terminal-sequences v1.0.3/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
 github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc=
 github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
@@ -70,6 +71,8 @@ github.com/robfig/cron/v3 v3.0.0 h1:kQ6Cb7aHOHTSzNVNEhmp8EcWKLb4CbiMW9h9VyIhO4E=
 github.com/robfig/cron/v3 v3.0.0/go.mod h1:eQICP3HwyT7UooqI/z+Ov+PtYAWygg1TEWWzGIFLtro=
 github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
 github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
+github.com/sirupsen/logrus v1.6.0 h1:UBcNElsrwanuuMsnGSlYmtmgbb23qDR5dG+6X6Oo89I=
+github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88=
 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/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
@@ -89,6 +92,7 @@ golang.org/x/sys v0.0.0-20181116152217-5ac8a444bdc5/go.mod h1:STP8DvDyc/dI5b8T5h
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
 golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200106162015-b016eb3dc98e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20200420163511-1957bb5e6d1f h1:gWF768j/LaZugp8dyS4UwsslYCYz9XgFxvlgsn0n9H8=
 golang.org/x/sys v0.0.0-20200420163511-1957bb5e6d1f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

logger/hook.go

@@ -0,0 +1,81 @@
+// Copyright 2020 Pradyumna Kaushik
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package logger
+
+import (
+	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
+	"io"
+)
+
+// WriterHook is a hook that writes logs, that contain at least one of the specified set of topics
+// as keys in its fields, to the specified Writer. The logs are formatted using the specified formatter.
+type WriterHook struct {
+	formatter logrus.Formatter
+	writer    io.Writer
+	topics    map[string]struct{}
+}
+
+// newWriterHook instantiates and returns a new WriterHook.
+func newWriterHook(formatter logrus.Formatter, writer io.Writer, topics ...string) logrus.Hook {
+	hook := &WriterHook{
+		formatter: formatter,
+		writer:    writer,
+		topics:    make(map[string]struct{}),
+	}
+	for _, topic := range topics {
+		hook.topics[topic] = struct{}{}
+	}
+
+	return hook
+}
+
+// Levels return the list of levels for which this hook will be fired.
+func (h WriterHook) Levels() []logrus.Level {
+	// We do not want debug and trace level logs to be persisted as they are typically temporary.
+	return []logrus.Level{
+		logrus.PanicLevel,
+		logrus.FatalLevel,
+		logrus.ErrorLevel,
+		logrus.WarnLevel,
+		logrus.InfoLevel,
+	}
+}
+
+// Fire checks whether the fields in the provided entry contain at least one of the specified
+// topics and if yes, formats the entry using the specified formatter and then writes it to the
+// specified Writer.
+func (h *WriterHook) Fire(entry *logrus.Entry) error {
+	// Logging only if any of the provided topics are found as keys in fields.
+	allow := false
+	for topic := range h.topics {
+		if _, ok := entry.Data[topic]; ok {
+			allow = true
+			break
+		}
+	}
+
+	var err error
+	var formattedLog []byte
+	if allow {
+		formattedLog, err = h.formatter.Format(entry)
+		if err != nil {
+			err = errors.Wrap(err, "failed to format entry")
+		} else {
+			_, err = h.writer.Write(formattedLog)
+		}
+	}
+	return err
+}

logger/logger.go

@@ -0,0 +1,131 @@
+// Copyright 2020 Pradyumna Kaushik
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package logger
+
+import (
+	"fmt"
+	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
+	"io/ioutil"
+	"os"
+	"time"
+)
+
+const (
+	// Using RFC3339Nano as the timestamp format for logs as prometheus scrape interval can be in milliseconds.
+	timestampFormat = time.RFC3339Nano
+	// Prefix of the name of the log file to store task ranker logs.
+	// This will be suffixed with the timestamp, associated with creating the file, to obtain the log filename.
+	taskRankerLogFilePrefix = "task_ranker_logs"
+	// Prefix of the name of the log file to store task ranking results.
+	// This will be suffixed with the timestamp, associated with creating the file, to obtain the log filename.
+	taskRankingResultsLogFilePrefix = "task_ranking_results"
+	// Giving everyone read and write permissions to the log files.
+	logFilePermissions = 0666
+)
+
+// instantiating a Logger to be used. This instance is configured and maintained locally.
+var log = logrus.New()
+
+var taskRankerLogFile *os.File
+var taskRankingResultsLogFile *os.File
+
+// createTaskRankerLogFile creates the log file to which task ranker logs are persisted.
+func createTaskRankerLogFile(now time.Time) error {
+	var err error
+	filename := fmt.Sprintf("%s_%v.log", taskRankerLogFilePrefix, now.UnixNano())
+	taskRankerLogFile, err = os.OpenFile(filename, os.O_CREATE|os.O_WRONLY, logFilePermissions)
+	if err != nil {
+		err = errors.Wrap(err, "failed to create task ranker operations log file")
+	}
+	return err
+}
+
+// createTaskRankingResultsLogFile creates the log file to which task ranking results are persisted.
+func createTaskRankingResultsLogFile(now time.Time) error {
+	var err error
+	filename := fmt.Sprintf("%s_%v.log", taskRankingResultsLogFilePrefix, now.UnixNano())
+	taskRankingResultsLogFile, err = os.OpenFile(filename, os.O_CREATE|os.O_WRONLY, logFilePermissions)
+	if err != nil {
+		err = errors.Wrap(err, "failed to create task ranker log file")
+	}
+	return err
+}
+
+// Configure the logger. To be prevented task ranker logs from mixing with the logs of the application
+// that is using it, logging to the console is disabled and instead hooks that redirect logs to corresponding
+// log files are attached to the logger.
+func Configure() error {
+	// Disabling log to stdout.
+	log.SetOutput(ioutil.Discard)
+	// Setting highest log level.
+	log.SetLevel(logrus.InfoLevel)
+
+	// Creating the log files.
+	now := time.Now()
+	var err error
+
+	if err = createTaskRankerLogFile(now); err != nil {
+		return err
+	}
+	if err = createTaskRankingResultsLogFile(now); err != nil {
+		return err
+	}
+
+	// Instantiate the hooks.
+	jsonFormatter := &logrus.JSONFormatter{
+		DisableHTMLEscape: true,
+		TimestampFormat:   timestampFormat,
+	}
+
+	textFormatter := &logrus.TextFormatter{
+		DisableColors:   true,
+		FullTimestamp:   true,
+		TimestampFormat: timestampFormat,
+	}
+
+	log.AddHook(newWriterHook(textFormatter, taskRankerLogFile, "stage", "query", "query_result"))
+	log.AddHook(newWriterHook(jsonFormatter, taskRankingResultsLogFile, "task_ranking_results"))
+
+	return nil
+}
+
+func Done() error {
+	var err error
+	if taskRankerLogFile != nil {
+		err = taskRankerLogFile.Close()
+		if err != nil {
+			err = errors.Wrap(err, "failed to close task ranker log file")
+		}
+	}
+
+	if taskRankingResultsLogFile != nil {
+		err = taskRankingResultsLogFile.Close()
+		if err != nil {
+			err = errors.Wrap(err, "failed to close tank ranking results log file")
+		}
+	}
+	return err
+}
+
+// Aliasing logrus functions.
+var WithField = log.WithField
+var WithFields = log.WithFields
+var Info = log.Info
+var Infof = log.Infof
+var Error = log.Error
+var Errorf = log.Errorf
+var Warn = log.Warn
+var Warnf = log.Warnf

ranker.go

@@ -18,12 +18,13 @@ import (
 	"fmt"
 	"github.com/pkg/errors"
 	df "github.com/pradykaushik/task-ranker/datafetcher"
+	"github.com/pradykaushik/task-ranker/logger"
 	"github.com/pradykaushik/task-ranker/query"
 	"github.com/pradykaushik/task-ranker/strategies"
 	"github.com/pradykaushik/task-ranker/strategies/factory"
 	"github.com/pradykaushik/task-ranker/util"
 	"github.com/robfig/cron/v3"
-	"log"
+	"github.com/sirupsen/logrus"
 	"time"
 )
 
@@ -73,7 +74,16 @@ func New(options ...Option) (*TaskRanker, error) {
 	// Providing the prometheus scrape interval to the strategy.
 	tRanker.Strategy.SetPrometheusScrapeInterval(tRanker.prometheusScrapeInterval)
 	tRanker.termCh = util.NewSignalChannel()
-	return tRanker, nil
+
+	// Configuring logger.
+	err := logger.Configure()
+	if err != nil {
+		err = errors.Wrap(err, "failed to configure logger")
+		if err = logger.Done(); err != nil {
+			err = errors.Wrap(err, "failed to shutdown logger")
+		}
+	}
+	return tRanker, err
 }
 
 type Option func(*TaskRanker) error
@@ -163,6 +173,9 @@ func WithSchedule(specString string) Option {
 }
 
 func (tRanker *TaskRanker) Start() {
+	logger.WithFields(logrus.Fields{
+		"stage": "task-ranker",
+	}).Log(logrus.InfoLevel, "starting task ranker cron job")
 	tRanker.runner = cron.New(cron.WithSeconds())
 	tRanker.runner.Schedule(tRanker.Schedule, tRanker)
 	tRanker.runner.Start()
@@ -174,13 +187,22 @@ func (tRanker *TaskRanker) Run() {
 	}
 	result, err := tRanker.DataFetcher.Fetch()
 	if err != nil {
-		log.Println(err.Error())
+		logger.WithFields(logrus.Fields{
+			"stage": "data-fetcher",
+		}).Log(logrus.ErrorLevel, err.Error())
 	} else {
 		tRanker.Strategy.Execute(result)
 	}
 }
 
 func (tRanker *TaskRanker) Stop() {
+	logger.WithFields(logrus.Fields{
+		"stage": "task-ranker",
+	}).Log(logrus.InfoLevel, "stopping task ranker cron job")
 	tRanker.termCh.Close()
 	tRanker.runner.Stop()
+	err := logger.Done()
+	if err != nil {
+		fmt.Printf("failed to shutdown logger: %v", err)
+	}
 }

strategies/taskRankCpuSharesStrategy.go

@@ -17,8 +17,10 @@ package strategies
 import (
 	"github.com/pkg/errors"
 	"github.com/pradykaushik/task-ranker/entities"
+	"github.com/pradykaushik/task-ranker/logger"
 	"github.com/pradykaushik/task-ranker/query"
 	"github.com/prometheus/common/model"
+	"github.com/sirupsen/logrus"
 	"sort"
 	"time"
 )
@@ -120,6 +122,10 @@ func (s *TaskRankCpuSharesStrategy) Execute(data model.Value) {
 	}
 
 	// Submitting the ranked tasks to the receiver.
+	logger.WithFields(logrus.Fields{
+		"task_ranking_strategy": "cpushares",
+		"task_ranking_results":  tasks,
+	}).Log(logrus.InfoLevel, "strategy executed")
 	s.receiver.Receive(tasks)
 }