Logger Changes (#158)

* Changes to logger, adding tracing capabilities v1

* Started changing Logr struct to incorporate log.entry + cleaning

* Updated

* Integrated tracing with Debug, Info, and Trace

* Updated Start Context and End Context

* Cleaning up code on logger.go and logger_test.go

* Changes made to support ending and restarting a span

* Removed log line

* removed test.log

Author: stsingh1

glide.lock

@@ -68,3 +68,9 @@ import:
   version: 4e5b6552494c8005c60de6c60b50ebaefc69e592
 - package: github.com/fsnotify/fsnotify
   version: ^v1.4.9
+- package: github.com/opentracing/opentracing-go
+  version: ^v1.2.0
+- package: github.com/uber/jaeger-client-go
+  version: ^v2.29
+- package: "github.com/opentracing/opentracing-go/ext"
+  version: ^v1.2.0

glide.yaml

@@ -16,7 +16,10 @@ import (
 	"sync"
 	"time"
 
+	"github.com/opentracing/opentracing-go"
+	otLog "github.com/opentracing/opentracing-go/log"
 	log "github.com/sirupsen/logrus"
+	"github.com/uber/jaeger-client-go/config"
 	"golang.org/x/crypto/ssh/terminal"
 	"gopkg.in/natefinch/lumberjack.v2"
 )
@@ -41,6 +44,12 @@ type LogParams struct {
 	Format     string
 }
 
+type Logr struct {
+	ctx      context.Context
+	logEntry *log.Entry
+	cl       io.Closer
+}
+
 var (
 	logParams LogParams
 	initMutex sync.Mutex
@@ -163,8 +172,28 @@ func updateLogParamsFromEnv() {
 	}
 }
 
+//Initalizes opentracing tracing
+func InitOpentracing(service string) (opentracing.Tracer, io.Closer) {
+	cfg := &config.Configuration{
+		ServiceName: service,
+		Sampler: &config.SamplerConfig{
+			Type:  "const",
+			Param: 1,
+		},
+		Reporter: &config.ReporterConfig{
+			LogSpans: true,
+		},
+	}
+	//add tracer as a input of NewTracer so that the logspans declared true above will work
+	tracer, closer, err := cfg.NewTracer()
+	if err != nil {
+		panic(fmt.Sprintf("ERROR: cannot init tracing: %v\n", err))
+	}
+	return tracer, closer
+}
+
 // Initialize logging with given params
-func InitLogging(logName string, params *LogParams, alsoLogToStderr bool) (err error) {
+func InitLogging(logName string, params *LogParams, alsoLogToStderr bool, initTracing bool) (err error, l *Logr) {
 	initMutex.Lock()
 	defer initMutex.Unlock()
 
@@ -190,23 +219,27 @@ func InitLogging(logName string, params *LogParams, alsoLogToStderr bool) (err e
 	// No output except for the hooks
 	log.SetOutput(ioutil.Discard)
 
+	//Default Logr
+	logEntry := sourced()
+	lg := Logr{nil, logEntry, nil}
+
 	if logParams.GetFile() != "" {
 		err = AddFileHook()
 		if err != nil {
-			return err
+			return err, &lg
 		}
 	}
 	if alsoLogToStderr {
 		err = AddConsoleHook()
 		if err != nil {
-			return err
+			return err, &lg
 		}
 	}
 
 	// Set log level
 	level, err := log.ParseLevel(logParams.GetLevel())
 	if err != nil {
-		return err
+		return err, &lg
 	}
 	log.SetLevel(level)
 
@@ -217,7 +250,64 @@ func InitLogging(logName string, params *LogParams, alsoLogToStderr bool) (err e
 		"alsoLogToStderr": alsoLogToStderr,
 	}).Info("Initialized logging.")
 
-	return nil
+	//initializes tracing capabilites if true
+	if initTracing {
+		//Initializing the tracer
+		tracer, closer := InitOpentracing("CSI-Driver")
+		opentracing.SetGlobalTracer(tracer)
+
+		//Span Initialized with default context
+		span := tracer.StartSpan("CSI-Driver")
+		log.Printf("Span Context --- Traceid:Spanid:ParentSpanid:Flags  : %v", span.Context())
+		ctx := opentracing.ContextWithSpan(context.Background(), span)
+		logEntry := sourced()
+		l := Logr{ctx, logEntry, closer}
+
+		l.LogToTrace("Info", "Tracing Initialized")
+		defer span.Finish()
+
+		return nil, &l
+	}
+
+	return nil, &lg
+}
+
+func (l *Logr) CloseTracer() {
+	l.cl.Close()
+}
+
+//Logs given string to tracer
+func (l *Logr) LogToTrace(level, msg string) {
+	span := opentracing.SpanFromContext(l.ctx)
+	//fmt.Print("In LogToTrace")
+	if span != nil {
+		span.LogFields(otLog.String("event", msg))
+	}
+	if span == nil {
+		fmt.Print("Span is nil")
+	}
+	span.Finish()
+}
+
+//Sets context of called Logr to given context
+func (l *Logr) SetContext(context context.Context) {
+	l.ctx = context
+}
+
+//Starts and returns a span for the inputted Logr
+func (l *Logr) StartContext(spanName string) (s opentracing.Span) {
+	s = opentracing.SpanFromContext(l.ctx)
+	if s == nil || s.BaggageItem(spanName) == "" {
+		s = opentracing.StartSpan(spanName)
+		s.SetBaggageItem(spanName, "true")
+		l.ctx = opentracing.ContextWithSpan(context.Background(), s)
+	}
+	return s
+}
+
+//Ends the inputted span
+func EndContext(span opentracing.Span) {
+	span.Finish()
 }
 
 func AddConsoleHook() error {
@@ -455,7 +545,6 @@ func IsSensitive(key string) bool {
 		"token",
 		"accesskey",
 		"passphrase",
-
 	}
 	key = strings.ToLower(key)
 	for _, bad := range badWords {
@@ -506,24 +595,42 @@ func sourced() *log.Entry {
 	return log.WithField("file", fmt.Sprintf("%s:%d", file, line))
 }
 
-// Trace logs a message at level Trace on the standard logger.
 func Trace(args ...interface{}) {
 	sourced().Trace(args...)
 }
 
-// Debug logs a message at level Debug on the standard logger.
+// Trace logs a message at level Trace on the standard logger.
+func (lg *Logr) Trace(args ...interface{}) {
+	lg.logEntry.Trace(args...)
+	str := fmt.Sprintf("%v", args)
+	lg.LogToTrace("Trace", str)
+}
+
 func Debug(args ...interface{}) {
-	sourced().Debug(args...)
+	sourced().Trace(args...)
+}
+
+// Debug logs a message at level Debug on the standard logger.
+func (lg *Logr) Debug(args ...interface{}) {
+	lg.logEntry.Debug(args...)
+	str := fmt.Sprintf("%v", args)
+	lg.LogToTrace("Debug", str)
 }
 
 // Print logs a message at level Info on the standard logger.
 func Print(args ...interface{}) {
 	sourced().Print(args...)
 }
 
-// Info logs a message at level Info on the standard logger.
 func Info(args ...interface{}) {
-	sourced().Info(args...)
+	sourced().Trace(args...)
+}
+
+// Info logs a message at level Info on the standard logger.
+func (lg *Logr) Info(args ...interface{}) {
+	lg.logEntry.Info(args...)
+	str := fmt.Sprintf("%v", args)
+	lg.LogToTrace("Info", str)
 }
 
 // Warn logs a message at level Warn on the standard logger.

logger/logger.go

@@ -8,6 +8,7 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/hpe-storage/common-host-libs/logger"
 	log "github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 )
@@ -68,7 +69,7 @@ func TestInitLogging(t *testing.T) {
 	os.RemoveAll(logFile)
 
 	// Test1: test overrides with params to log to only stdout
-	InitLogging("", nil, true)
+	InitLogging("", nil, true, false)
 
 	// verify logging with override to stdout only
 	testName := "test_param_override_stdout_only"
@@ -78,7 +79,7 @@ func TestInitLogging(t *testing.T) {
 	assert.Equal(t, true, os.IsNotExist(err))
 
 	// Test 2: initialize logger with nil params to verify default levels
-	InitLogging(logFile, nil, false)
+	InitLogging(logFile, nil, false, false)
 
 	// verify default info level setting with no params
 	assert.Equal(t, DefaultLogLevel, log.GetLevel().String())
@@ -93,7 +94,7 @@ func TestInitLogging(t *testing.T) {
 	testContains(t, logFile, testName, "debug", false)
 
 	// Test3: initialize logger with override of trace level
-	InitLogging(logFile, &LogParams{Level: "trace"}, false)
+	InitLogging(logFile, &LogParams{Level: "trace"}, false, false)
 
 	// verify trace level setting with param override
 	assert.Equal(t, log.TraceLevel.String(), log.GetLevel().String())
@@ -109,7 +110,7 @@ func TestInitLogging(t *testing.T) {
 
 	// Test4: initialize logger with env vars for info level
 	os.Setenv("LOG_LEVEL", "debug")
-	InitLogging(logFile, nil, false)
+	InitLogging(logFile, nil, false, false)
 	// verify logging with debug level and below
 	testName = "test_env_debug_level"
 	logAllLevels(testName)
@@ -121,20 +122,20 @@ func TestInitLogging(t *testing.T) {
 
 	// Test5: initialize logger with invalid log format through env
 	os.Setenv("LOG_FORMAT", "yaml")
-	InitLogging(logFile, nil, false)
+	InitLogging(logFile, nil, false, false)
 
 	// verify log format is set to default value of text
 	assert.Equal(t, logParams.GetLogFormat(), DefaultLogFormat)
 
 	// Test6: initialize logger with invalid log files limit through config
-	InitLogging(logFile, &LogParams{MaxFiles: 1000}, false)
+	InitLogging(logFile, &LogParams{MaxFiles: 1000}, false, false)
 
 	// verify log files is set to default value of 10
 	assert.Equal(t, logParams.GetMaxFiles(), DefaultMaxLogFiles)
 
 	// Test7: test overrides with env variables even when params is not nil
 	os.Setenv("LOG_LEVEL", "info")
-	InitLogging(logFile, &LogParams{Level: "trace"}, false)
+	InitLogging(logFile, &LogParams{Level: "trace"}, false, false)
 
 	// verify logging with only info level and below with override from env
 	testName = "test_env_override_info_level"
@@ -148,3 +149,24 @@ func TestInitLogging(t *testing.T) {
 	// cleanup log file after test
 	os.RemoveAll(logFile)
 }
+
+func TestInitJaeger(t *testing.T) {
+	_, lg := logger.InitLogging("test.log", nil, true, true)
+
+	lg.Info("************** Start Workflow 1 **************")
+	lg.Info("********** Workflow 1 Line 1 **********")
+	s := lg.StartContext("Workflow 2")
+	lg.Info("**************** Start Workflow 2 *****************")
+	lg.Info("********** Workflow 2 Line 1 ******************")
+	logger.EndContext(s)
+	sp := lg.StartContext("Workflow 2")
+	lg.Info("**************** Start Workflow 2 *****************")
+	lg.Info("********** Workflow 2 Line 1 ******************")
+	logger.EndContext(sp)
+	sp2 := lg.StartContext("Workflow 3")
+	lg.Info("**************** Start Workflow 3 *****************")
+	lg.Info("********** Workflow 3 Line 1 ******************")
+	logger.EndContext(sp2)
+	lg.CloseTracer()
+
+}