Refactor logging (#104)

* Move logging into internal folder & package
* Create enum for logging levels
* Start moving functions into a utils package

clientui.go

@@ -10,7 +10,9 @@ import (
 	"sync/atomic"
 	"time"
 
+	"github.com/microsoft/ethr/internal/ethrLog"
 	"github.com/microsoft/ethr/internal/stats"
+	"github.com/microsoft/ethr/utils"
 )
 
 type clientUI struct {
@@ -21,22 +23,20 @@ func (u *clientUI) fini() {
 
 func (u *clientUI) printMsg(format string, a ...interface{}) {
 	s := fmt.Sprintf(format, a...)
-	logMsg(s)
+	ethrLog.Info(s)
 	fmt.Println(s)
 }
 
 func (u *clientUI) printErr(format string, a ...interface{}) {
 	s := fmt.Sprintf(format, a...)
-	logErr(s)
+	ethrLog.Error(s)
 	fmt.Println(s)
 }
 
 func (u *clientUI) printDbg(format string, a ...interface{}) {
-	if logDebug {
-		s := fmt.Sprintf(format, a...)
-		logDbg(s)
-		fmt.Println(s)
-	}
+	s := fmt.Sprintf(format, a...)
+	ethrLog.Debug(s)
+	fmt.Println(s)
 }
 
 func (u *clientUI) paint(seconds uint64) {
@@ -58,13 +58,13 @@ func (u *clientUI) emitLatencyHdr() {
 }
 
 func (u *clientUI) emitLatencyResults(remote, proto string, avg, min, max, p50, p90, p95, p99, p999, p9999 time.Duration) {
-	logLatency(remote, proto, avg, min, max, p50, p90, p95, p99, p999, p9999)
+	ethrLog.LogLatency(remote, proto, avg, min, max, p50, p90, p95, p99, p999, p9999)
 	fmt.Printf("%8s %8s %8s %8s %8s %8s %8s %8s %8s\n",
-		durationToString(avg), durationToString(min),
-		durationToString(p50), durationToString(p90),
-		durationToString(p95), durationToString(p99),
-		durationToString(p999), durationToString(p9999),
-		durationToString(max))
+		utils.DurationToString(avg), utils.DurationToString(min),
+		utils.DurationToString(p50), utils.DurationToString(p90),
+		utils.DurationToString(p95), utils.DurationToString(p99),
+		utils.DurationToString(p999), utils.DurationToString(p9999),
+		utils.DurationToString(max))
 }
 
 func (u *clientUI) emitTestResultEnd() {
@@ -112,7 +112,7 @@ func printTestResult(test *ethrTest, value uint64, seconds uint64) {
 				ui.printMsg("- - - - - - - - - - - - - - - - - - - - - - -")
 			}
 		}
-		logResults([]string{test.session.remoteAddr, protoToString(test.testParam.TestID.Protocol),
+		ethrLog.LogResults([]string{test.session.remoteAddr, protoToString(test.testParam.TestID.Protocol),
 			bytesToRate(cvalue), "", "", ""})
 	} else if test.testParam.TestID.Type == Cps {
 		if gInterval == 0 {
@@ -122,7 +122,7 @@ func printTestResult(test *ethrTest, value uint64, seconds uint64) {
 		ui.printMsg("  %-5s    %03d-%03d sec   %7s",
 			protoToString(test.testParam.TestID.Protocol),
 			gInterval, gInterval+1, cpsToString(value))
-		logResults([]string{test.session.remoteAddr, protoToString(test.testParam.TestID.Protocol),
+		ethrLog.LogResults([]string{test.session.remoteAddr, protoToString(test.testParam.TestID.Protocol),
 			"", cpsToString(value), "", ""})
 	} else if test.testParam.TestID.Type == Pps {
 		if gInterval == 0 {
@@ -132,7 +132,7 @@ func printTestResult(test *ethrTest, value uint64, seconds uint64) {
 		ui.printMsg("  %-5s    %03d-%03d sec   %7s",
 			protoToString(test.testParam.TestID.Protocol),
 			gInterval, gInterval+1, ppsToString(value))
-		logResults([]string{test.session.remoteAddr, protoToString(test.testParam.TestID.Protocol),
+		ethrLog.LogResults([]string{test.session.remoteAddr, protoToString(test.testParam.TestID.Protocol),
 			"", "", ppsToString(value), ""})
 	} else if test.testParam.TestID.Type == Bandwidth &&
 		(test.testParam.TestID.Protocol == HTTP || test.testParam.TestID.Protocol == HTTPS) {
@@ -143,7 +143,7 @@ func printTestResult(test *ethrTest, value uint64, seconds uint64) {
 		ui.printMsg("  %-5s    %03d-%03d sec   %7s",
 			protoToString(test.testParam.TestID.Protocol),
 			gInterval, gInterval+1, bytesToRate(value))
-		logResults([]string{test.session.remoteAddr, protoToString(test.testParam.TestID.Protocol),
+		ethrLog.LogResults([]string{test.session.remoteAddr, protoToString(test.testParam.TestID.Protocol),
 			bytesToRate(value), "", "", ""})
 	}
 	gInterval++

ethr.go

@@ -13,11 +13,15 @@ import (
 	"time"
 
 	"github.com/microsoft/ethr/internal/cmd"
+	"github.com/microsoft/ethr/internal/ethrLog"
 )
 
 const defaultLogFileName = "./ethrs.log for server, ./ethrc.log for client"
 
-var gVersion string
+var (
+	gVersion     string
+	loggingLevel ethrLog.LogLevel = ethrLog.LogLevelInfo
+)
 
 func main() {
 	//
@@ -75,6 +79,10 @@ func main() {
 	//
 	gIgnoreCert = *ic
 
+	if *debug {
+		loggingLevel = ethrLog.LogLevelDebug
+	}
+
 	xMode := false
 	switch *modeStr {
 	case "":
@@ -205,7 +213,7 @@ func main() {
 				logFileName = "ethrxc.log"
 			}
 		}
-		logInit(logFileName, *debug)
+		ethrLog.LogInit(logFileName)
 	}
 
 	clientParam := ethrClientParam{*duration, *gap}

internal/ethrLog/constants.go

@@ -0,0 +1,10 @@
+package ethrLog
+
+// LogLevel specifies the logging level to use in both screen and
+// file-based logging
+type LogLevel int
+
+const (
+	LogLevelInfo LogLevel = iota
+	LogLevelDebug
+)

internal/ethrLog/log.go

@@ -3,7 +3,7 @@
 // Licensed under the MIT license.
 // See LICENSE.txt file in the project root for full license information.
 //-----------------------------------------------------------------------------
-package main
+package ethrLog
 
 import (
 	"encoding/json"
@@ -11,6 +11,8 @@ import (
 	"log"
 	"os"
 	"time"
+
+	"github.com/microsoft/ethr/utils"
 )
 
 type logMessage struct {
@@ -47,14 +49,12 @@ type logTestResults struct {
 }
 
 var loggingActive = false
-var logDebug = false
 var logChan = make(chan string, 64)
 
-func logInit(fileName string, debug bool) {
+func LogInit(fileName string) {
 	if fileName == "" {
 		return
 	}
-	logDebug = debug
 	logFile, err := os.OpenFile(fileName, os.O_APPEND|os.O_CREATE|os.O_RDWR, 0666)
 	if err != nil {
 		fmt.Printf("Unable to open the log file %s, Error: %v", fileName, err)
@@ -66,7 +66,7 @@ func logInit(fileName string, debug bool) {
 	go runLogger(logFile)
 }
 
-func logFini() {
+func LogFini() {
 	loggingActive = false
 }
 
@@ -78,7 +78,7 @@ func runLogger(logFile *os.File) {
 	logFile.Close()
 }
 
-func _log(prefix, msg string) {
+func logMsg(prefix, msg string) {
 	if loggingActive {
 		logData := logMessage{}
 		logData.Time = time.Now().UTC().Format(time.RFC3339)
@@ -89,21 +89,19 @@ func _log(prefix, msg string) {
 	}
 }
 
-func logMsg(msg string) {
-	_log("INFO", msg)
+func Info(msg string) {
+	logMsg("INFO", msg)
 }
 
-func logErr(msg string) {
-	_log("ERROR", msg)
+func Error(msg string) {
+	logMsg("ERROR", msg)
 }
 
-func logDbg(msg string) {
-	if logDebug {
-		_log("DEBUG", msg)
-	}
+func Debug(msg string) {
+	logMsg("DEBUG", msg)
 }
 
-func logResults(s []string) {
+func LogResults(s []string) {
 	if loggingActive {
 		logData := logTestResults{}
 		logData.Time = time.Now().UTC().Format(time.RFC3339)
@@ -119,22 +117,22 @@ func logResults(s []string) {
 	}
 }
 
-func logLatency(remoteAddr, proto string, avg, min, p50, p90, p95, p99, p999, p9999, max time.Duration) {
+func LogLatency(remoteAddr, proto string, avg, min, p50, p90, p95, p99, p999, p9999, max time.Duration) {
 	if loggingActive {
 		logData := logLatencyData{}
 		logData.Time = time.Now().UTC().Format(time.RFC3339)
 		logData.Type = "LatencyResult"
 		logData.RemoteAddr = remoteAddr
 		logData.Protocol = proto
-		logData.Avg = durationToString(avg)
-		logData.Min = durationToString(min)
-		logData.P50 = durationToString(p50)
-		logData.P90 = durationToString(p90)
-		logData.P95 = durationToString(p95)
-		logData.P99 = durationToString(p99)
-		logData.P999 = durationToString(p999)
-		logData.P9999 = durationToString(p9999)
-		logData.Max = durationToString(max)
+		logData.Avg = utils.DurationToString(avg)
+		logData.Min = utils.DurationToString(min)
+		logData.P50 = utils.DurationToString(p50)
+		logData.P90 = utils.DurationToString(p90)
+		logData.P95 = utils.DurationToString(p95)
+		logData.P99 = utils.DurationToString(p99)
+		logData.P999 = utils.DurationToString(p999)
+		logData.P9999 = utils.DurationToString(p9999)
+		logData.Max = utils.DurationToString(max)
 		logJSON, _ := json.Marshal(logData)
 		logChan <- string(logJSON)
 	}

server.go

@@ -23,6 +23,8 @@ import (
 	"sort"
 	"sync/atomic"
 	"time"
+
+	"github.com/microsoft/ethr/internal/ethrLog"
 )
 
 var gCert []byte
@@ -55,7 +57,7 @@ func initServer(showUI bool) {
 
 func finiServer() {
 	ui.fini()
-	logFini()
+	ethrLog.LogFini()
 }
 
 func runControlChannel() net.Listener {

serverui.go

@@ -13,8 +13,10 @@ import (
 	"sync/atomic"
 	"time"
 
+	"github.com/microsoft/ethr/internal/ethrLog"
 	"github.com/microsoft/ethr/internal/plot"
 	"github.com/microsoft/ethr/internal/stats"
+	"github.com/microsoft/ethr/utils"
 	tm "github.com/nsf/termbox-go"
 )
 
@@ -148,7 +150,7 @@ func (u *serverTui) fini() {
 
 func (u *serverTui) printMsg(format string, a ...interface{}) {
 	s := fmt.Sprintf(format, a...)
-	logMsg(s)
+	ethrLog.Info(s)
 	ss := splitString(s, u.msgW)
 	u.ringLock.Lock()
 	u.msgRing = u.msgRing[len(ss):]
@@ -158,7 +160,7 @@ func (u *serverTui) printMsg(format string, a ...interface{}) {
 
 func (u *serverTui) printErr(format string, a ...interface{}) {
 	s := fmt.Sprintf(format, a...)
-	logErr(s)
+	ethrLog.Error(s)
 	ss := splitString(s, u.errW)
 	u.ringLock.Lock()
 	u.errRing = u.errRing[len(ss):]
@@ -167,15 +169,16 @@ func (u *serverTui) printErr(format string, a ...interface{}) {
 }
 
 func (u *serverTui) printDbg(format string, a ...interface{}) {
-	if logDebug {
-		s := fmt.Sprintf(format, a...)
-		logDbg(s)
-		ss := splitString(s, u.errW)
-		u.ringLock.Lock()
-		u.errRing = u.errRing[len(ss):]
-		u.errRing = append(u.errRing, ss...)
-		u.ringLock.Unlock()
+	if loggingLevel != ethrLog.LogLevelDebug {
+		return
 	}
+	s := fmt.Sprintf(format, a...)
+	ethrLog.Debug(s)
+	ss := splitString(s, u.errW)
+	u.ringLock.Lock()
+	u.errRing = u.errRing[len(ss):]
+	u.errRing = append(u.errRing, ss...)
+	u.ringLock.Unlock()
 }
 
 func (u *serverTui) emitTestResultBegin() {
@@ -191,7 +194,7 @@ func (u *serverTui) emitTestResult(s *ethrSession, proto EthrProtocol, seconds u
 
 func (u *serverTui) printTestResults(s []string) {
 	// Log before truncation of remote address.
-	logResults(s)
+	ethrLog.LogResults(s)
 	s[0] = truncateString(s[0], 13)
 	u.results = append(u.results, s)
 }
@@ -209,7 +212,7 @@ func (u *serverTui) emitLatencyHdr() {
 }
 
 func (u *serverTui) emitLatencyResults(remote, proto string, avg, min, max, p50, p90, p95, p99, p999, p9999 time.Duration) {
-	logLatency(remote, proto, avg, min, max, p50, p90, p95, p99, p999, p9999)
+	ethrLog.LogLatency(remote, proto, avg, min, max, p50, p90, p95, p99, p999, p9999)
 }
 
 func (u *serverTui) paint(seconds uint64) {
@@ -308,21 +311,22 @@ func (u *serverCli) fini() {
 func (u *serverCli) printMsg(format string, a ...interface{}) {
 	s := fmt.Sprintf(format, a...)
 	fmt.Println(s)
-	logMsg(s)
+	ethrLog.Info(s)
 }
 
 func (u *serverCli) printDbg(format string, a ...interface{}) {
-	if logDebug {
-		s := fmt.Sprintf(format, a...)
-		fmt.Println(s)
-		logDbg(s)
+	if loggingLevel != ethrLog.LogLevelDebug {
+		return
 	}
+	s := fmt.Sprintf(format, a...)
+	fmt.Println(s)
+	ethrLog.Debug(s)
 }
 
 func (u *serverCli) printErr(format string, a ...interface{}) {
 	s := fmt.Sprintf(format, a...)
 	fmt.Println(s)
-	logErr(s)
+	ethrLog.Error(s)
 }
 
 func (u *serverCli) paint(seconds uint64) {
@@ -358,14 +362,14 @@ func (u *serverCli) emitLatencyHdr() {
 }
 
 func (u *serverCli) emitLatencyResults(remote, proto string, avg, min, max, p50, p90, p95, p99, p999, p9999 time.Duration) {
-	logLatency(remote, proto, avg, min, max, p50, p90, p95, p99, p999, p9999)
+	ethrLog.LogLatency(remote, proto, avg, min, max, p50, p90, p95, p99, p999, p9999)
 }
 
 func (u *serverCli) emitStats(netStats stats.EthrNetStats) {
 }
 
 func (u *serverCli) printTestResults(s []string) {
-	logResults(s)
+	ethrLog.LogResults(s)
 	fmt.Printf("[%13s]  %5s  %7s  %7s  %7s  %8s\n", truncateString(s[0], 13),
 		s[1], s[2], s[3], s[4], s[5])
 }
@@ -443,7 +447,7 @@ func getTestResults(s *ethrSession, proto EthrProtocol, seconds uint64) []string
 			ppsStr = ppsToString(pps)
 		}
 		if latTestOn {
-			latStr = durationToString(time.Duration(latency))
+			latStr = utils.DurationToString(time.Duration(latency))
 		}
 		str := []string{s.remoteAddr, protoToString(proto),
 			bwStr, cpsStr, ppsStr, latStr}

utils.go

@@ -164,35 +164,6 @@ func unitToNumber(s string) uint64 {
 	}
 }
 
-func durationToString(d time.Duration) string {
-	if d < 0 {
-		return d.String()
-	}
-	ud := uint64(d)
-	val := float64(ud)
-	unit := ""
-	if ud < uint64(60*time.Second) {
-		switch {
-		case ud < uint64(time.Microsecond):
-			unit = "ns"
-		case ud < uint64(time.Millisecond):
-			val = val / 1000
-			unit = "us"
-		case ud < uint64(time.Second):
-			val = val / (1000 * 1000)
-			unit = "ms"
-		default:
-			val = val / (1000 * 1000 * 1000)
-			unit = "s"
-		}
-
-		result := strconv.FormatFloat(val, 'f', 2, 64)
-		return result + unit
-	}
-
-	return d.String()
-}
-
 func bytesToRate(bytes uint64) string {
 	bits := bytes * 8
 	result := numberToUnit(bits)

utils/utils.go

@@ -0,0 +1,35 @@
+package utils
+
+import (
+	"strconv"
+	"time"
+)
+
+func DurationToString(d time.Duration) string {
+	if d < 0 {
+		return d.String()
+	}
+	ud := uint64(d)
+	val := float64(ud)
+	unit := ""
+	if ud < uint64(60*time.Second) {
+		switch {
+		case ud < uint64(time.Microsecond):
+			unit = "ns"
+		case ud < uint64(time.Millisecond):
+			val = val / 1000
+			unit = "us"
+		case ud < uint64(time.Second):
+			val = val / (1000 * 1000)
+			unit = "ms"
+		default:
+			val = val / (1000 * 1000 * 1000)
+			unit = "s"
+		}
+
+		result := strconv.FormatFloat(val, 'f', 2, 64)
+		return result + unit
+	}
+
+	return d.String()
+}

xclient.go

@@ -11,6 +11,8 @@ import (
 	"os"
 	"sync/atomic"
 	"time"
+
+	"github.com/microsoft/ethr/utils"
 )
 
 func runXClient(testParam EthrTestParam, clientParam ethrClientParam, server string) {
@@ -70,8 +72,8 @@ func xcRunTCPConnLatencyTest(test *ethrTest, g time.Duration) {
 				case <-test.done:
 					ui.printMsg("TCP connect statistics for %s:", server)
 					ui.printMsg("  Sent = %d, Received = %d, Lost = %d", sent, rcvd, lost)
-					ui.printMsg("  Min = %s, Max = %s, Avg = %s", durationToString(min),
-						durationToString(max), durationToString(avg))
+					ui.printMsg("  Min = %s, Max = %s, Avg = %s", utils.DurationToString(min),
+						utils.DurationToString(max), utils.DurationToString(avg))
 					break ExitForLoop
 				default:
 					sent++
@@ -87,7 +89,7 @@ func xcRunTCPConnLatencyTest(test *ethrTest, g time.Duration) {
 					rserver, rport, _ := net.SplitHostPort(conn.RemoteAddr().String())
 					lserver, lport, _ := net.SplitHostPort(conn.LocalAddr().String())
 					ui.printMsg("[tcp] %sConnection from [%s]:%s to [%s]:%s: %s",
-						warmupText, lserver, lport, rserver, rport, durationToString(t1))
+						warmupText, lserver, lport, rserver, rport, utils.DurationToString(t1))
 					if !warmup {
 						rcvd++
 						sum += t1.Nanoseconds()

xserver.go

@@ -6,31 +6,13 @@
 package main
 
 import (
-	/*
-		"crypto/rand"
-		"crypto/rsa"
-		"crypto/tls"
-		"crypto/x509"
-		"crypto/x509/pkix"
-		"encoding/gob"
-	*/
 	"fmt"
-	/*
-		"io"
-		"io/ioutil"
-		"math/big"
-	*/
 	"net"
-	/*
-		"net/http"
-	*/
 	"os"
-	/*
-		"runtime"
-		"sort"
-	*/
 	"sync/atomic"
 	"time"
+
+	"github.com/microsoft/ethr/internal/ethrLog"
 )
 
 func runXServer(testParam EthrTestParam, serverParam ethrServerParam) {
@@ -52,7 +34,7 @@ func initXServer(showUI bool) {
 
 func finiXServer() {
 	ui.fini()
-	logFini()
+	ethrLog.LogFini()
 }
 
 func xsRunTCPServer() {