From 7f98384fcde3db903629ef3828978bab0e0e2b41 Mon Sep 17 00:00:00 2001 From: Andrew Wang Date: Sun, 21 Nov 2021 00:39:15 -0500 Subject: [PATCH] logging --- merlin/common/common.go | 18 ++++-------- merlin/common/logger.go | 49 ++++++++++++++++++++++---------- merlin/common/process_manager.go | 10 ++++--- merlin/common/sync.go | 2 +- merlin/merlin.go | 16 +++++++---- 5 files changed, 57 insertions(+), 38 deletions(-) diff --git a/merlin/common/common.go b/merlin/common/common.go index 0edacc9..8b45bf0 100644 --- a/merlin/common/common.go +++ b/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) diff --git a/merlin/common/logger.go b/merlin/common/logger.go index b728a09..53f2a7f 100644 --- a/merlin/common/logger.go +++ b/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{}) { diff --git a/merlin/common/process_manager.go b/merlin/common/process_manager.go index ba14333..4455418 100644 --- a/merlin/common/process_manager.go +++ b/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): diff --git a/merlin/common/sync.go b/merlin/common/sync.go index 1a38790..846b2a0 100644 --- a/merlin/common/sync.go +++ b/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 diff --git a/merlin/merlin.go b/merlin/merlin.go index 50eb349..38fa7d9 100644 --- a/merlin/merlin.go +++ b/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 {