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):