From 05c959eba70a199f23bf35ba46b360be4ba97fd6 Mon Sep 17 00:00:00 2001 From: Brian Picciano Date: Sun, 27 Feb 2022 11:12:26 -0700 Subject: [PATCH] Refactor logging to separate stdout/stdout/system lines The new logging differentiates between stdout, stderr, and system log lines much better. The flushing logic has also been simplified, so lines should appear on the terminal when expected (though possibly with lower performance, will need to keep an eye on this). --- README.md | 85 ++++++++++++++++++++++---------------------- main.go | 82 +++++++++++++++++++----------------------- pmux-example.yml | 4 +-- pmuxproc/pmuxproc.go | 42 ++++++++++++++-------- 4 files changed, 109 insertions(+), 104 deletions(-) diff --git a/README.md b/README.md index 3832a5a..7d6ccd1 100644 --- a/README.md +++ b/README.md @@ -33,46 +33,47 @@ all possible configuration options. The stdoutput from this example config looks something like this: ``` -2021-09-21T16:32:48.513-06:00 | stubborn-pinger | starting process -2021-09-21T16:32:48.513-06:00 | pinger | starting process -2021-09-21T16:32:48.532-06:00 > pinger > PING example.com (93.184.216.34) 56(84) bytes of data. -2021-09-21T16:32:48.532-06:00 > pinger > 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=55 time=14.1 ms -2021-09-21T16:32:48.532-06:00 > pinger > -2021-09-21T16:32:48.532-06:00 > pinger > --- example.com ping statistics --- -2021-09-21T16:32:48.532-06:00 > pinger > 1 packets transmitted, 1 received, 0% packet loss, time 0ms -2021-09-21T16:32:48.532-06:00 > pinger > rtt min/avg/max/mdev = 14.091/14.091/14.091/0.000 ms -2021-09-21T16:32:48.532-06:00 > stubborn-pinger > PING example.com (93.184.216.34) 56(84) bytes of data. -2021-09-21T16:32:48.532-06:00 > stubborn-pinger > 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=55 time=14.2 ms -2021-09-21T16:32:48.532-06:00 > stubborn-pinger > -2021-09-21T16:32:48.532-06:00 > stubborn-pinger > --- example.com ping statistics --- -2021-09-21T16:32:48.532-06:00 > stubborn-pinger > 1 packets transmitted, 1 received, 0% packet loss, time 0ms -2021-09-21T16:32:48.532-06:00 > stubborn-pinger > rtt min/avg/max/mdev = 14.154/14.154/14.154/0.000 ms -2021-09-21T16:32:49.548-06:00 > pinger > PING example.com (93.184.216.34) 56(84) bytes of data. -2021-09-21T16:32:49.548-06:00 > pinger > 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=55 time=10.5 ms -2021-09-21T16:32:49.548-06:00 > pinger > -2021-09-21T16:32:49.548-06:00 > pinger > --- example.com ping statistics --- -2021-09-21T16:32:49.548-06:00 > pinger > 1 packets transmitted, 1 received, 0% packet loss, time 0ms -2021-09-21T16:32:49.548-06:00 > pinger > rtt min/avg/max/mdev = 10.451/10.451/10.451/0.000 ms -2021-09-21T16:32:49.553-06:00 > stubborn-pinger > PING example.com (93.184.216.34) 56(84) bytes of data. -2021-09-21T16:32:49.553-06:00 > stubborn-pinger > 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=55 time=15.3 ms -2021-09-21T16:32:49.553-06:00 > stubborn-pinger > -2021-09-21T16:32:49.553-06:00 > stubborn-pinger > --- example.com ping statistics --- -2021-09-21T16:32:49.553-06:00 > stubborn-pinger > 1 packets transmitted, 1 received, 0% packet loss, time 0ms - -... Ctrl-C - -^C2021-09-21T16:32:50.894-06:00 | pmux | interrupt signal received, killing all sub-processes -2021-09-21T16:32:50.895-06:00 > stubborn-pinger > i will never stop, you will have to SIGKILL me! -2021-09-21T16:32:50.895-06:00 | pinger | process exited: signal: interrupt -2021-09-21T16:32:50.895-06:00 | pinger | stopped process handler -2021-09-21T16:32:50.910-06:00 > stubborn-pinger > PING example.com (93.184.216.34) 56(84) bytes of data. -2021-09-21T16:32:50.910-06:00 > stubborn-pinger > 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=55 time=11.4 ms -2021-09-21T16:32:50.910-06:00 > stubborn-pinger > -2021-09-21T16:32:50.910-06:00 > stubborn-pinger > --- example.com ping statistics --- -2021-09-21T16:32:50.910-06:00 > stubborn-pinger > 1 packets transmitted, 1 received, 0% packet loss, time 0ms -2021-09-21T16:32:50.910-06:00 > stubborn-pinger > rtt min/avg/max/mdev = 11.369/11.369/11.369/0.000 ms -2021-09-21T16:32:51.895-06:00 | stubborn-pinger | forcefully killing process -2021-09-21T16:32:51.912-06:00 | stubborn-pinger | process exited: signal: killed -2021-09-21T16:32:51.912-06:00 | stubborn-pinger | stopped process handler -2021-09-21T16:32:51.912-06:00 | pmux | exited gracefully, ciao! +stubborn-pinger ~ starting process +pinger ~ starting process +stubborn-pinger › PING example.com (93.184.216.34) 56(84) bytes of data. +stubborn-pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=9.54 ms +stubborn-pinger › +stubborn-pinger › --- example.com ping statistics --- +stubborn-pinger › 1 packets transmitted, 1 received, 0% packet loss, time 0ms +stubborn-pinger › rtt min/avg/max/mdev = 9.541/9.541/9.541/0.000 ms +pinger › PING example.com (93.184.216.34) 56(84) bytes of data. +pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=9.53 ms +pinger › +pinger › --- example.com ping statistics --- +pinger › 1 packets transmitted, 1 received, 0% packet loss, time 0ms +pinger › rtt min/avg/max/mdev = 9.533/9.533/9.533/0.000 ms +pinger › PING example.com (93.184.216.34) 56(84) bytes of data. +pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=11.4 ms +pinger › +pinger › --- example.com ping statistics --- +pinger › 1 packets transmitted, 1 received, 0% packet loss, time 0ms +pinger › rtt min/avg/max/mdev = 11.435/11.435/11.435/0.000 ms +stubborn-pinger › PING example.com (93.184.216.34) 56(84) bytes of data. +stubborn-pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=11.2 ms +stubborn-pinger › +stubborn-pinger › --- example.com ping statistics --- +stubborn-pinger › 1 packets transmitted, 1 received, 0% packet loss, time 0ms +stubborn-pinger › rtt min/avg/max/mdev = 11.161/11.161/11.161/0.000 ms + +... Ctrl-C ... + +pmux ~ interrupt signal received, killing all sub-processes +stubborn-pinger » i will never stop, you will have to SIGKILL me! +pinger ~ exit code -1, process exited: signal: interrupt +pinger ~ stopped process handler +stubborn-pinger › PING example.com (93.184.216.34) 56(84) bytes of data. +stubborn-pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=14.8 ms +stubborn-pinger › +stubborn-pinger › --- example.com ping statistics --- +stubborn-pinger › 1 packets transmitted, 1 received, 0% packet loss, time 0ms +stubborn-pinger › rtt min/avg/max/mdev = 14.793/14.793/14.793/0.000 ms +stubborn-pinger ~ forcefully killing process +stubborn-pinger ~ exit code -1, process exited: signal: killed +stubborn-pinger ~ stopped process handler +pmux ~ exited gracefully, ciao! ``` diff --git a/main.go b/main.go index 8d77828..87d2a4f 100644 --- a/main.go +++ b/main.go @@ -25,8 +25,9 @@ const pmuxPName = "pmux" // characters used to denote different kinds of logs const ( - logSepProcOut = '>' - logSepSys = '|' + logSepStdout = '›' + logSepStderr = '»' + logSepSys = '~' ) type logger struct { @@ -39,15 +40,13 @@ type logger struct { // maxPNameLen is a pointer because it changes when WithPrefix is called. maxPNameLen *uint64 - wg *sync.WaitGroup - closeCh chan struct{} - pname string sep rune } func newLogger( out io.Writer, + sep rune, timeFmt string, ) *logger { @@ -60,25 +59,22 @@ func newLogger( l: new(sync.Mutex), out: out, outBuf: bufio.NewWriter(out), - wg: new(sync.WaitGroup), - closeCh: make(chan struct{}), pname: pname, - sep: logSepSys, + sep: sep, } - l.wg.Add(1) - go func() { - defer l.wg.Done() - l.flusher() - }() - return l } -func (l *logger) WithPrefix(pname string, sep rune) *logger { +func (l *logger) withSep(sep rune) *logger { l2 := *l - l2.pname = pname l2.sep = sep + return &l2 +} + +func (l *logger) withPName(pname string) *logger { + l2 := *l + l2.pname = pname l2.l.Lock() defer l2.l.Unlock() @@ -95,9 +91,6 @@ func (l *logger) Close() { l.l.Lock() defer l.l.Unlock() - close(l.closeCh) - l.wg.Wait() - l.outBuf.Flush() if syncer, ok := l.out.(interface{ Sync() error }); ok { @@ -113,23 +106,6 @@ func (l *logger) Close() { l.outBuf = bufio.NewWriter(l.out) } -func (l *logger) flusher() { - - ticker := time.NewTicker(250 * time.Millisecond) - defer ticker.Stop() - - for { - select { - case <-ticker.C: - l.l.Lock() - l.outBuf.Flush() - l.l.Unlock() - case <-l.closeCh: - return - } - } -} - func (l *logger) println(line string) { l.l.Lock() @@ -152,6 +128,8 @@ func (l *logger) println(line string) { l.sep, line, ) + + l.outBuf.Flush() } func (l *logger) Println(line string) { @@ -199,9 +177,15 @@ func main() { panic(fmt.Sprintf("initializing config: %v", err)) } - logger := newLogger(os.Stdout, cfg.TimeFormat) - defer logger.Close() - defer logger.Println("exited gracefully, ciao!") + stdoutLogger := newLogger(os.Stdout, logSepStdout, cfg.TimeFormat) + defer stdoutLogger.Close() + + stderrLogger := newLogger(os.Stderr, logSepStderr, cfg.TimeFormat) + defer stderrLogger.Close() + + sysLogger := stderrLogger.withSep(logSepSys) + + defer sysLogger.Println("exited gracefully, ciao!") ctx, cancel := context.WithCancel(context.Background()) go func() { @@ -209,12 +193,12 @@ func main() { signal.Notify(sigCh, os.Interrupt, syscall.SIGTERM) sig := <-sigCh - logger.Printf("%v signal received, killing all sub-processes", sig) + sysLogger.Printf("%v signal received, killing all sub-processes", sig) cancel() <-sigCh - logger.Printf("forcefully exiting pmux process, there may be zombie child processes being left behind, good luck!") - logger.Close() + sysLogger.Printf("forcefully exiting pmux process, there may be zombie child processes being left behind, good luck!") + sysLogger.Close() os.Exit(1) }() @@ -226,11 +210,17 @@ func main() { go func(procCfg processConfig) { defer wg.Done() - logger := logger.WithPrefix(procCfg.Name, logSepProcOut) - defer logger.Printf("stopped process handler") + stdoutLogger := stdoutLogger.withPName(procCfg.Name) + stderrLogger := stderrLogger.withPName(procCfg.Name) + sysLogger := sysLogger.withPName(procCfg.Name) + + defer sysLogger.Printf("stopped process handler") + + sysLogger.Println("starting process") - logger.Println("starting process") - pmuxproc.RunProcess(ctx, logger, procCfg.Config) + pmuxproc.RunProcess( + ctx, stdoutLogger, stderrLogger, sysLogger, procCfg.Config, + ) }(cfgProc) } } diff --git a/pmux-example.yml b/pmux-example.yml index 009ea1a..289804d 100644 --- a/pmux-example.yml +++ b/pmux-example.yml @@ -5,7 +5,7 @@ # string works. # # If timeFormat isn't set then the time is not included in each log line. -timeFormat: "2006-01-02T15:04:05.000Z07:00" +#timeFormat: "2006-01-02T15:04:05.000Z07:00" # processes is the only required field, it must have at least one process # defined. @@ -42,7 +42,7 @@ processes: args: - "-c" - | - trap "echo 'i will never stop, you will have to SIGKILL me!'" SIGINT + trap "echo 'i will never stop, you will have to SIGKILL me!' >&2" SIGINT while ping -c1 example.com; do sleep 1; done sigKillWait: 1s diff --git a/pmuxproc/pmuxproc.go b/pmuxproc/pmuxproc.go index ce1bc66..1e140dd 100644 --- a/pmuxproc/pmuxproc.go +++ b/pmuxproc/pmuxproc.go @@ -73,15 +73,21 @@ func (cfg Config) withDefaults() Config { // It returns nil if the process exits normally with a zero status. It returns // an error otherwise. // -// The stdout and stderr of the process will be written to the given Logger, as -// well as various runtime events. -func RunProcessOnce(ctx context.Context, logger Logger, cfg Config) (int, error) { +// The stdout and stderr of the process will be written to the corresponding +// Loggers. Various runtime events will be written to the sysLogger. +func RunProcessOnce( + ctx context.Context, + stdoutLogger, stderrLogger, sysLogger Logger, + cfg Config, +) ( + int, error, +) { cfg = cfg.withDefaults() var wg sync.WaitGroup - fwdOutPipe := func(r io.Reader) { + fwdOutPipe := func(logger Logger, r io.Reader) { wg.Add(1) go func() { defer wg.Done() @@ -121,8 +127,8 @@ func RunProcessOnce(ctx context.Context, logger Logger, cfg Config) (int, error) } defer stderr.Close() - fwdOutPipe(stdout) - fwdOutPipe(stderr) + fwdOutPipe(stdoutLogger, stdout) + fwdOutPipe(stderrLogger, stderr) if err := cmd.Start(); err != nil { return -1, fmt.Errorf("starting process: %w", err) @@ -144,7 +150,7 @@ func RunProcessOnce(ctx context.Context, logger Logger, cfg Config) (int, error) select { case <-time.After(cfg.SigKillWait): - logger.Println("forcefully killing process") + sysLogger.Println("forcefully killing process") _ = proc.Signal(os.Kill) case <-stopCh: return @@ -170,9 +176,13 @@ func RunProcessOnce(ctx context.Context, logger Logger, cfg Config) (int, error) // brief wait time between each restart, with an exponential backup mechanism so // that the wait time increases upon repeated restarts. // -// The stdout and stderr of the process will be written to the given Logger, as -// well as various runtime events. -func RunProcess(ctx context.Context, logger Logger, cfg Config) { +// The stdout and stderr of the process will be written to the corresponding +// Loggers. Various runtime events will be written to the sysLogger. +func RunProcess( + ctx context.Context, + stdoutLogger, stderrLogger, sysLogger Logger, + cfg Config, +) { cfg = cfg.withDefaults() @@ -180,13 +190,17 @@ func RunProcess(ctx context.Context, logger Logger, cfg Config) { for { start := time.Now() - exitCode, err := RunProcessOnce(ctx, logger, cfg) + exitCode, err := RunProcessOnce( + ctx, + stdoutLogger, stderrLogger, sysLogger, + cfg, + ) took := time.Since(start) if err != nil { - logger.Printf("exit code %d, %v", exitCode, err) + sysLogger.Printf("exit code %d, %v", exitCode, err) } else { - logger.Println("exit code 0") + sysLogger.Println("exit code 0") } if err := ctx.Err(); err != nil { @@ -207,7 +221,7 @@ func RunProcess(ctx context.Context, logger Logger, cfg Config) { wait = cfg.MaxWait } - logger.Printf("will restart process in %v", wait) + sysLogger.Printf("will restart process in %v", wait) select { case <-time.After(wait):