2 files changed, 78 insertions, 18 deletions

diff --git a/internal/logger/logger.go b/internal/logger/logger.go
index f1db4b0..f9cf734 100644
--- a/internal/logger/logger.go
+++ b/internal/logger/logger.go
@@ -3,10 +3,13 @@ package logger
 import (
 	"fmt"
 	"io"
+	"io/ioutil"
 	golog "log"
 	"log/syslog"
+	"math"
 	"os"
 	"sync"
+	"time"
 
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 
@@ -26,13 +29,19 @@ func Configure(cfg *config.Config) error {
 	defer mutex.Unlock()
 
 	pid = os.Getpid()
+	ProgName, _ = os.Executable()
 
-	var err error
-	logWriter, err = os.OpenFile(cfg.LogFile, os.O_WRONLY|os.O_APPEND, 0)
+	// Avoid leaking output if we can't set up the logging output
+	log.SetOutput(ioutil.Discard)
+
+	output, err := os.OpenFile(cfg.LogFile, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
 	if err != nil {
+		setupBootstrapLogger()
+		logPrint("Unable to configure logging", err)
 		return err
 	}
 
+	logWriter = output
 	log.SetOutput(logWriter)
 	if cfg.LogFormat == "json" {
 		log.SetFormatter(&log.JSONFormatter{})
@@ -41,12 +50,14 @@ func Configure(cfg *config.Config) error {
 	return nil
 }
 
+// If our log file is not available we want to log somewhere else, but
+// not to standard error because that leaks information to the user. This
+// function attempts to log to syslog.
 func logPrint(msg string, err error) {
-	mutex.Lock()
-	defer mutex.Unlock()
-
 	if logWriter == nil {
-		bootstrapLogPrint(msg, err)
+		if bootstrapLogger != nil {
+			bootstrapLogger.Print(ProgName+":", msg+":", err)
+		}
 		return
 	}
 
@@ -56,6 +67,10 @@ func logPrint(msg string, err error) {
 }
 
 func Fatal(msg string, err error) {
+	mutex.Lock()
+	defer mutex.Unlock()
+	setupBootstrapLogger()
+
 	logPrint(msg, err)
 	// We don't show the error to the end user because it can leak
 	// information that is private to the GitLab server.
@@ -63,20 +78,23 @@ func Fatal(msg string, err error) {
 	os.Exit(1)
 }
 
-// If our log file is not available we want to log somewhere else, but
-// not to standard error because that leaks information to the user. This
-// function attempts to log to syslog.
-//
 // We assume the logging mutex is already locked.
-func bootstrapLogPrint(msg string, err error) {
+func setupBootstrapLogger() {
 	if bootstrapLogger == nil {
-		var err error
-		bootstrapLogger, err = syslog.NewLogger(syslog.LOG_ERR|syslog.LOG_USER, 0)
-		if err != nil {
-			// The message will not be logged.
-			return
-		}
+		bootstrapLogger, _ = syslog.NewLogger(syslog.LOG_ERR|syslog.LOG_USER, 0)
 	}
+}
+
+func ElapsedTime(since time.Time) float64 {
+	// Later versions of Go support Milliseconds directly:
+	// https://go-review.googlesource.com/c/go/+/167387/
+	return roundFloat(time.Since(since).Seconds() * 1e3)
+}
+
+func roundFloat(x float64) float64 {
+	return round(x, 0.001)
+}
 
-	bootstrapLogger.Print(ProgName+":", msg+":", err)
+func round(x, unit float64) float64 {
+	return math.Round(x/unit) * unit
 }
diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go
new file mode 100644
index 0000000..e14d01c
--- /dev/null
+++ b/internal/logger/logger_test.go
@@ -0,0 +1,42 @@
+package logger
+
+import (
+	"io/ioutil"
+	"os"
+	"strings"
+	"testing"
+	"time"
+
+	log "github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/require"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
+)
+
+func TestConfigure(t *testing.T) {
+	tmpFile, err := ioutil.TempFile(os.TempDir(), "logtest-")
+	require.NoError(t, err)
+	defer tmpFile.Close()
+
+	config := config.Config{
+		LogFile:   tmpFile.Name(),
+		LogFormat: "json",
+	}
+
+	err = Configure(&config)
+
+	require.NoError(t, err)
+
+	log.Info("this is a test")
+
+	tmpFile.Close()
+
+	data, err := ioutil.ReadFile(tmpFile.Name())
+	require.NoError(t, err)
+	require.True(t, strings.Contains(string(data), `msg":"this is a test"`))
+}
+
+func TestElapsedTime(t *testing.T) {
+	start := time.Now()
+	start = start.Add(1234567800 * time.Nanosecond)
+	require.InDelta(t, -1234.568, ElapsedTime(start), 0.01)
+}