micropelago/pmux
3
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Refactor logging to separate stdout/stdout/system lines

Browse Source 
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).
This commit is contained in:
Brian Picciano 2022-02-27 11:12:26 -07:00
parent ea5e7c9e1c
commit 05c959eba7
4 changed files with 107 additions and 102 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

81
README.md
View File

@ -33,46 +33,47 @@ all possible configuration options.
The stdoutput from this example config looks something like this: The stdoutput from this example config looks something like this:
``` ```
2021-09-21T16:32:48.513-06:00 | stubborn-pinger | starting process stubborn-pinger ~ starting process
2021-09-21T16:32:48.513-06:00 | pinger | starting process pinger ~ starting process
2021-09-21T16:32:48.532-06:00 > pinger > PING example.com (93.184.216.34) 56(84) bytes of data. stubborn-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 stubborn-pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=9.54 ms
2021-09-21T16:32:48.532-06:00 > pinger > stubborn-pinger ›
2021-09-21T16:32:48.532-06:00 > pinger > --- example.com ping statistics --- stubborn-pinger › --- example.com ping statistics ---
2021-09-21T16:32:48.532-06:00 > pinger > 1 packets transmitted, 1 received, 0% packet loss, time 0ms stubborn-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 stubborn-pinger › rtt min/avg/max/mdev = 9.541/9.541/9.541/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. 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 pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=9.53 ms
2021-09-21T16:32:48.532-06:00 > stubborn-pinger > pinger ›
2021-09-21T16:32:48.532-06:00 > stubborn-pinger > --- example.com ping statistics --- 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 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 pinger › rtt min/avg/max/mdev = 9.533/9.533/9.533/0.000 ms
2021-09-21T16:32:49.548-06:00 > pinger > PING example.com (93.184.216.34) 56(84) bytes of data. 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 pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=11.4 ms
2021-09-21T16:32:49.548-06:00 > pinger > pinger ›
2021-09-21T16:32:49.548-06:00 > pinger > --- example.com ping statistics --- pinger › --- example.com ping statistics ---
2021-09-21T16:32:49.548-06:00 > pinger > 1 packets transmitted, 1 received, 0% packet loss, time 0ms 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 pinger › rtt min/avg/max/mdev = 11.435/11.435/11.435/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. 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 stubborn-pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=11.2 ms
2021-09-21T16:32:49.553-06:00 > stubborn-pinger > stubborn-pinger ›
2021-09-21T16:32:49.553-06:00 > stubborn-pinger > --- example.com ping statistics --- 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 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 ... Ctrl-C ...
^C2021-09-21T16:32:50.894-06:00 | pmux | interrupt signal received, killing all sub-processes 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! 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 pinger ~ exit code -1, process exited: signal: interrupt
2021-09-21T16:32:50.895-06:00 | pinger | stopped process handler 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. 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 stubborn-pinger › 64 bytes from 93.184.216.34 (93.184.216.34): icmp_seq=1 ttl=54 time=14.8 ms
2021-09-21T16:32:50.910-06:00 > stubborn-pinger > stubborn-pinger ›
2021-09-21T16:32:50.910-06:00 > stubborn-pinger > --- example.com ping statistics --- 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 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 stubborn-pinger › rtt min/avg/max/mdev = 14.793/14.793/14.793/0.000 ms
2021-09-21T16:32:51.895-06:00 | stubborn-pinger | forcefully killing process stubborn-pinger ~ forcefully killing process
2021-09-21T16:32:51.912-06:00 | stubborn-pinger | process exited: signal: killed stubborn-pinger ~ exit code -1, process exited: signal: killed
2021-09-21T16:32:51.912-06:00 | stubborn-pinger | stopped process handler stubborn-pinger ~ stopped process handler
2021-09-21T16:32:51.912-06:00 | pmux | exited gracefully, ciao! pmux ~ exited gracefully, ciao!
``` ```

82
main.go
View File

@ -25,8 +25,9 @@ const pmuxPName = "pmux"
// characters used to denote different kinds of logs // characters used to denote different kinds of logs
const ( const (
logSepProcOut = '>' logSepStdout = '›'
logSepSys = '|' logSepStderr = '»'
logSepSys = '~'
) )
type logger struct { type logger struct {
@ -39,15 +40,13 @@ type logger struct {
// maxPNameLen is a pointer because it changes when WithPrefix is called. // maxPNameLen is a pointer because it changes when WithPrefix is called.
maxPNameLen *uint64 maxPNameLen *uint64
wg *sync.WaitGroup
closeCh chan struct{}
pname string pname string
sep rune sep rune
} }
func newLogger( func newLogger(
out io.Writer, out io.Writer,
sep rune,
timeFmt string, timeFmt string,
) *logger { ) *logger {
@ -60,25 +59,22 @@ func newLogger(
l: new(sync.Mutex), l: new(sync.Mutex),
out: out, out: out,
outBuf: bufio.NewWriter(out), outBuf: bufio.NewWriter(out),
wg: new(sync.WaitGroup),
closeCh: make(chan struct{}),
pname: pname, pname: pname,
sep: logSepSys, sep: sep,
} }
l.wg.Add(1)
go func() {
defer l.wg.Done()
l.flusher()
}()
return l return l
} }
func (l *logger) WithPrefix(pname string, sep rune) *logger { func (l *logger) withSep(sep rune) *logger {
l2 := *l
l2.sep = sep
return &l2
}
func (l *logger) withPName(pname string) *logger {
l2 := *l l2 := *l
l2.pname = pname l2.pname = pname
l2.sep = sep
l2.l.Lock() l2.l.Lock()
defer l2.l.Unlock() defer l2.l.Unlock()
@ -95,9 +91,6 @@ func (l *logger) Close() {
l.l.Lock() l.l.Lock()
defer l.l.Unlock() defer l.l.Unlock()
close(l.closeCh)
l.wg.Wait()
l.outBuf.Flush() l.outBuf.Flush()
if syncer, ok := l.out.(interface{ Sync() error }); ok { if syncer, ok := l.out.(interface{ Sync() error }); ok {
@ -113,23 +106,6 @@ func (l *logger) Close() {
l.outBuf = bufio.NewWriter(l.out) 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) { func (l *logger) println(line string) {
l.l.Lock() l.l.Lock()
@ -152,6 +128,8 @@ func (l *logger) println(line string) {
l.sep, l.sep,
line, line,
) )
l.outBuf.Flush()
} }
func (l *logger) Println(line string) { func (l *logger) Println(line string) {
@ -199,9 +177,15 @@ func main() {
panic(fmt.Sprintf("initializing config: %v", err)) panic(fmt.Sprintf("initializing config: %v", err))
} }
logger := newLogger(os.Stdout, cfg.TimeFormat) stdoutLogger := newLogger(os.Stdout, logSepStdout, cfg.TimeFormat)
defer logger.Close() defer stdoutLogger.Close()
defer logger.Println("exited gracefully, ciao!")
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()) ctx, cancel := context.WithCancel(context.Background())
go func() { go func() {
@ -209,12 +193,12 @@ func main() {
signal.Notify(sigCh, os.Interrupt, syscall.SIGTERM) signal.Notify(sigCh, os.Interrupt, syscall.SIGTERM)
sig := <-sigCh sig := <-sigCh
logger.Printf("%v signal received, killing all sub-processes", sig) sysLogger.Printf("%v signal received, killing all sub-processes", sig)
cancel() cancel()
<-sigCh <-sigCh
logger.Printf("forcefully exiting pmux process, there may be zombie child processes being left behind, good luck!") sysLogger.Printf("forcefully exiting pmux process, there may be zombie child processes being left behind, good luck!")
logger.Close() sysLogger.Close()
os.Exit(1) os.Exit(1)
}() }()
@ -226,11 +210,17 @@ func main() {
go func(procCfg processConfig) { go func(procCfg processConfig) {
defer wg.Done() defer wg.Done()
logger := logger.WithPrefix(procCfg.Name, logSepProcOut) stdoutLogger := stdoutLogger.withPName(procCfg.Name)
defer logger.Printf("stopped process handler") stderrLogger := stderrLogger.withPName(procCfg.Name)
sysLogger := sysLogger.withPName(procCfg.Name)
logger.Println("starting process") defer sysLogger.Printf("stopped process handler")
pmuxproc.RunProcess(ctx, logger, procCfg.Config)
sysLogger.Println("starting process")
pmuxproc.RunProcess(
ctx, stdoutLogger, stderrLogger, sysLogger, procCfg.Config,
)
}(cfgProc) }(cfgProc)
} }
} }

4
pmux-example.yml
View File

@ -5,7 +5,7 @@
# string works. # string works.
# #
# If timeFormat isn't set then the time is not included in each log line. # 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 # processes is the only required field, it must have at least one process
# defined. # defined.
@ -42,7 +42,7 @@ processes:
args: args:
- "-c" - "-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 while ping -c1 example.com; do sleep 1; done
sigKillWait: 1s sigKillWait: 1s

42
pmuxproc/pmuxproc.go
View File

@ -73,15 +73,21 @@ func (cfg Config) withDefaults() Config {
// It returns nil if the process exits normally with a zero status. It returns // It returns nil if the process exits normally with a zero status. It returns
// an error otherwise. // an error otherwise.
// //
// The stdout and stderr of the process will be written to the given Logger, as // The stdout and stderr of the process will be written to the corresponding
// well as various runtime events. // Loggers. Various runtime events will be written to the sysLogger.
func RunProcessOnce(ctx context.Context, logger Logger, cfg Config) (int, error) { func RunProcessOnce(
ctx context.Context,
stdoutLogger, stderrLogger, sysLogger Logger,
cfg Config,
) (
int, error,
) {
cfg = cfg.withDefaults() cfg = cfg.withDefaults()
var wg sync.WaitGroup var wg sync.WaitGroup
fwdOutPipe := func(r io.Reader) { fwdOutPipe := func(logger Logger, r io.Reader) {
wg.Add(1) wg.Add(1)
go func() { go func() {
defer wg.Done() defer wg.Done()
@ -121,8 +127,8 @@ func RunProcessOnce(ctx context.Context, logger Logger, cfg Config) (int, error)
} }
defer stderr.Close() defer stderr.Close()
fwdOutPipe(stdout) fwdOutPipe(stdoutLogger, stdout)
fwdOutPipe(stderr) fwdOutPipe(stderrLogger, stderr)
if err := cmd.Start(); err != nil { if err := cmd.Start(); err != nil {
return -1, fmt.Errorf("starting process: %w", err) return -1, fmt.Errorf("starting process: %w", err)
@ -144,7 +150,7 @@ func RunProcessOnce(ctx context.Context, logger Logger, cfg Config) (int, error)
select { select {
case <-time.After(cfg.SigKillWait): case <-time.After(cfg.SigKillWait):
logger.Println("forcefully killing process") sysLogger.Println("forcefully killing process")
_ = proc.Signal(os.Kill) _ = proc.Signal(os.Kill)
case <-stopCh: case <-stopCh:
return 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 // brief wait time between each restart, with an exponential backup mechanism so
// that the wait time increases upon repeated restarts. // that the wait time increases upon repeated restarts.
// //
// The stdout and stderr of the process will be written to the given Logger, as // The stdout and stderr of the process will be written to the corresponding
// well as various runtime events. // Loggers. Various runtime events will be written to the sysLogger.
func RunProcess(ctx context.Context, logger Logger, cfg Config) { func RunProcess(
ctx context.Context,
stdoutLogger, stderrLogger, sysLogger Logger,
cfg Config,
) {
cfg = cfg.withDefaults() cfg = cfg.withDefaults()
@ -180,13 +190,17 @@ func RunProcess(ctx context.Context, logger Logger, cfg Config) {
for { for {
start := time.Now() start := time.Now()
exitCode, err := RunProcessOnce(ctx, logger, cfg) exitCode, err := RunProcessOnce(
ctx,
stdoutLogger, stderrLogger, sysLogger,
cfg,
)
took := time.Since(start) took := time.Since(start)
if err != nil { if err != nil {
logger.Printf("exit code %d, %v", exitCode, err) sysLogger.Printf("exit code %d, %v", exitCode, err)
} else { } else {
logger.Println("exit code 0") sysLogger.Println("exit code 0")
} }
if err := ctx.Err(); err != nil { if err := ctx.Err(); err != nil {
@ -207,7 +221,7 @@ func RunProcess(ctx context.Context, logger Logger, cfg Config) {
wait = cfg.MaxWait wait = cfg.MaxWait
} }
logger.Printf("will restart process in %v", wait) sysLogger.Printf("will restart process in %v", wait)
select { select {
case <-time.After(wait): case <-time.After(wait):