logging

merlin/common/common.go

@@ -124,10 +124,6 @@ type Config struct {
 	ZfssyncLogDir string `ini:"zfssync_log_dir"`
 	// the Unix socket path which arthur will use to communicate with us
 	SockPath string `ini:"sock_path"`
-	// logger that writes to stdout
-	StdoutLog *Logger `ini:"-"`
-	// logger that writes to stderr
-	StderrLog *Logger `ini:"-"`
 	// a list of all of the repos
 	Repos []*Repo `ini:"-"`
 }
@@ -173,9 +169,7 @@ func (repo *Repo) RunIfPossible() bool {
 		repo.State.IsRunning = true
 		repo.State.LastAttemptStartTime = curTime
 		repo.SaveState()
-		msg := fmt.Sprintf("Repo %s has started syncing", repo.Name)
-		repo.Logger.Info(msg)
-		repo.cfg.StdoutLog.Info(msg)
+		repo.Logger.Info(fmt.Sprintf("Repo %s has started syncing", repo.Name))
 		go repo.StartSyncJob()
 		return true
 	}
@@ -220,10 +214,9 @@ func (repo *Repo) SyncCompleted(exit int) {
 		exitStr = "failed"
 	}
 	repo.SaveState()
-	msg := fmt.Sprintf("Sync "+exitStr+" after running for %d seconds, will run again in %d seconds", syncTook, nextSync)
-	repo.Logger.Info(msg)
-	repo.cfg.StdoutLog.Info(msg)
+	repo.Logger.Info(fmt.Sprintf("Sync "+exitStr+" after running for %d seconds, will run again in %d seconds", syncTook, nextSync))
 	if exit == SUCCESS {
+		// it is possible that the zfssync from the last repo sync is still running is that fine?
 		go zfsSync(repo)
 	}
 }
@@ -245,6 +238,7 @@ func touchFile(file string) {
 	} else if fi.IsDir() {
 		panic(fmt.Errorf("%s is a directory", file))
 	} else if os.Geteuid() != 1001 {
+		// UID 1001 is the hardcoded uid for mirror
 		err := os.Chown(file, 1001, os.Getegid())
 		panicIfErr(err)
 	} else if fi.Mode().Perm() != 0644 {
@@ -277,8 +271,6 @@ func GetConfig(doneChan chan Result, stopChan chan struct{}) Config {
 		RsyncLogDir:   DEFAULT_RSYNC_LOG_DIR,
 		ZfssyncLogDir: DEFAULT_ZFSSYNC_LOG_DIR,
 		SockPath:      DEFAULT_SOCK_PATH,
-		StdoutLog:     NewLogger("STDOUT"),
-		StderrLog:     NewLogger("STDERR"),
 		Repos:         make([]*Repo, 0),
 	}
 	err = data.MapTo(&cfg)
@@ -321,7 +313,7 @@ func GetConfig(doneChan chan Result, stopChan chan struct{}) Config {
 			repo.ZfssyncLogFile,
 		)
 
-		repo.Logger = NewLogger(repo.LoggerFile)
+		repo.Logger = NewLogger(repo.Name, repo.LoggerFile)
 		repo.Frequency = frequencies[repo.FrequencyStr]
 		if repo.SyncType == "" {
 			panic("Missing sync type from " + repo.Name)

merlin/common/logger.go

@@ -1,56 +1,75 @@
 package common
 
 import (
-	"fmt"
 	"log"
 	"os"
 )
 
 type Logger struct {
 	*log.Logger
+	name string
 	file string
 }
 
+// DEBUG/WARNING will only be written to file
+// INFO/ERROR will be written to file and printed to stdout/stderr
 const (
-	INFO = iota
+	DEBUG = iota
+	INFO
 	WARNING
 	ERROR
 )
 
 var levels = map[int]string{
+	DEBUG:   "[DEBUG]",
 	INFO:    "[INFO]",
 	WARNING: "[WARNING]",
 	ERROR:   "[ERROR]",
 }
 
-func NewLogger(file string) *Logger {
+var outLogger = log.New(os.Stdout, "", log.LstdFlags)
+var errLogger = log.New(os.Stderr, "", log.LstdFlags)
+
+func OutLogger() *log.Logger {
+	return outLogger
+}
+
+func ErrLogger() *log.Logger {
+	return errLogger
+}
+
+func NewLogger(name, file string) *Logger {
 	logger := Logger{
 		Logger: log.New(os.Stderr, "", log.LstdFlags),
+		name:   name,
 		file:   file,
 	}
 	return &logger
 }
 
 func (logger *Logger) Log(level int, v ...interface{}) {
-	var f *os.File
-	if logger.file == "STDOUT" {
-		f = os.Stdout
-	} else if logger.file == "STDERR" {
-		f = os.Stderr
-	} else {
-		f, err := os.OpenFile(logger.file, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
-		if err != nil {
-			fmt.Println(err.Error())
-		}
-		defer f.Close()
+	if level == INFO {
+		outLogger.Println(append([]interface{}{"[" + logger.name + "]"}, v...))
+	} else if level == ERROR {
+		errLogger.Println(append([]interface{}{"[" + logger.name + "]"}, v...))
 	}
 
+	f, err := os.OpenFile(logger.file, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
+	if err != nil {
+		errLogger.Println(err.Error())
+	}
+	defer f.Close()
+
 	levelStr := levels[level]
 	args := []interface{}{levelStr + ":"}
 	args = append(args, v...)
 
 	logger.SetOutput(f)
-	logger.Println(args...)
+	logger.Println(v...)
+}
+
+func (logger *Logger) Debug(v ...interface{}) {
+	logger.Log(DEBUG, v...)
 }
 
 func (logger *Logger) Info(v ...interface{}) {

merlin/common/process_manager.go

@@ -16,9 +16,9 @@ func SpawnProcess(repo *Repo, args []string) (ch <-chan *exec.Cmd) {
 	// startTime and time took will be handled in common.go by SyncExit
 	cmd := exec.Command(args[0], args[1:]...)
 
-	repo.Logger.Info("Starting process")
+	repo.Logger.Debug("Starting process")
 	if err := cmd.Start(); err != nil {
-		repo.Logger.Error(fmt.Errorf("could not start process for %s: %w", repo.Name, err))
+		repo.Logger.Error(fmt.Errorf("could not start process for %s: %w", repo.Name, err).Error())
 		return
 	}
 
@@ -31,12 +31,14 @@ func SpawnProcess(repo *Repo, args []string) (ch <-chan *exec.Cmd) {
 			repo.Logger.Error("Could not send signal to process:", err)
 			return
 		}
+
 		select {
 		case <-time.After(30 * time.Second):
 			repo.Logger.Warning("Process still hasn't stopped after 30 seconds; sending SIGKILL")
 			cmd.Process.Signal(syscall.SIGKILL)
+
 		case <-cmdDoneChan:
-			repo.Logger.Info("Process has stopped.")
+			repo.Logger.Debug("Process has been stopped.")
 		}
 	}
 
@@ -56,7 +58,7 @@ func SpawnProcess(repo *Repo, args []string) (ch <-chan *exec.Cmd) {
 			}
 
 		case <-repo.StopChan:
-			repo.Logger.Info("Received signal to stop, killing process...")
+			repo.Logger.Debug("Received signal to stop, killing process...")
 			killProcess()
 
 		case <-time.After(time.Duration(repo.MaxTime) * time.Second):

merlin/common/sync.go

@@ -271,7 +271,7 @@ func (repo *Repo) StartSyncJob() {
 
 	ch := SpawnProcess(repo, args)
 	if ch == nil {
-		repo.Logger.Error("Unable to start sync process")
+		// SpawnProcess will have already logged error
 		return
 	}
 	cmd := <-ch

merlin/merlin.go

@@ -4,6 +4,7 @@ import (
 	"bytes"
 	"fmt"
 	"io"
+	"log"
 	"net"
 	"os"
 	"os/signal"
@@ -19,6 +20,8 @@ import (
 
 var (
 	cfg            common.Config
+	outLogger      *log.Logger
+	errLogger      *log.Logger
 	repoMap        map[string]*common.Repo
 	repoIdx        int
 	numJobsRunning int
@@ -30,14 +33,14 @@ func getAndRunCommand(conn net.Conn) {
 	var buf bytes.Buffer
 	_, err := io.Copy(&buf, conn)
 	if err != nil {
-		cfg.StderrLog.Error(err)
+		errLogger.Println(err.Error())
 		return
 	}
 
 	command := buf.String()
 	args := strings.Split(command, ":")
 	respondAndLogErr := func(msg string) {
-		cfg.StderrLog.Warning(msg)
+		outLogger.Println(msg)
 		conn.Write([]byte(msg))
 	}
 
@@ -62,7 +65,7 @@ func getAndRunCommand(conn net.Conn) {
 		}
 
 		if repo, inMap := repoMap[args[1]]; inMap {
-			cfg.StdoutLog.Info("Attempting to force sync of " + repo.Name)
+			outLogger.Println("Attempting to force sync of " + repo.Name)
 			if repo.RunIfPossible() {
 				conn.Write([]byte("Forced sync for " + repo.Name))
 				numJobsRunning++
@@ -97,7 +100,7 @@ func unixSockListener(connChan chan net.Conn, stopLisChan chan struct{}) {
 			// will exit when ear is closed
 			conn, err := ear.Accept()
 			if err != nil {
-				cfg.StderrLog.Error(err.Error())
+				errLogger.Println(err.Error())
 				return
 			}
 			connChan <- conn
@@ -128,6 +131,9 @@ func runAsManyAsPossible() {
 }
 
 func main() {
+	outLogger = common.OutLogger()
+	errLogger = common.ErrLogger()
+
 	// check that merlin is run as mirror user
 	// check that mirror user has pid of 1001
 
@@ -147,7 +153,7 @@ func main() {
 
 	loadConfig := func() {
 		cfg = common.GetConfig(doneChan, stopChan)
-		cfg.StdoutLog.Info("Loaded config:\n" + fmt.Sprintf("%+v\n", cfg))
+		outLogger.Println("Loaded config:\n" + fmt.Sprintf("%+v\n", cfg))
 
 		repoMap = make(map[string]*common.Repo)
 		for _, repo := range cfg.Repos {