rs / zerolog

Zero Allocation JSON Logger
MIT License
10.62k stars 572 forks source link

add loglevel for stdout/stderr captured in sub-process sublogger? #398

Open pwntr opened 2 years ago

pwntr commented 2 years ago

My goal: I would like to add a loglevel to all outputs from my captured subprocesses stdout/stderr.

Given the following example:

func startSubprocess(pathToBinary string, args []string, subProcessID int) {
    cmd := exec.Command(pathToBinary, args...)

    cmd.Stderr = log.With().Str("subprocessID", strconv.Itoa(subProcessID)).Logger()
    cmd.Stdout = cmd.Stderr

    err := cmd.Start()
    // ...
    err = cmd.Wait()
    // ...
}   

func main() {
    // assume global logger existing
    log.Debug().Str("component", "test").Msg("lorem ipsum")
    // startSubprocess(...) a bunch of times
}

As-is: my output turns out ot be something like this, with no loglevel present for the sub-process outputs:

{"level":"debug","component":"test","time":1642768180137,"message":"lorem ipsum"}
{"subprocessID":"1","time":1642768180138,"message":"any output from my sub-process received on stdout or stderr"}

To-be: add a (fixed/given) loglevel like "level":"info" to be added to every line received from the stdout/stderr from the sub-processes:

{"level":"debug","component":"test","time":1642768180137,"message":"lorem ipsum"}
{"level":"info","subprocessID":"1","time":1642768180138,"message":"any output from my sub-process received on stdout or stderr"}

I'm revisiting this after a few months and currently try to wrap my head around the io.Writer, which might be of help here?

Any ideas or easier solutions and pointers are greatly appraciated, thanks a lot for your help :)!

pwntr commented 2 years ago

For a pure json ouput I kinda worked around my problem in a hacky way by just adding the loglevel via .Str() and checking for it manually like so:

if zerolog.GlobalLevel() <= zerolog.InfoLevel {
    cmd.Stderr = log.With().Str("level", zerolog.InfoLevel.String()).Str("subprocessID", strconv.Itoa(subProcessID)).Logger()
    cmd.Stdout = cmd.Stderr
}

However, this unfortunately breaks the pretty ConsoleWriter output, if one so desires to use it ocassionally:

...
6:43PM TRC some parent process output on trace level
6:43PM INF first line of sub-process / child output captured
second line of sub-process / child output captured
another line of sub-process / child output captured
another line of sub-process / child output captured
another line of sub-process / child output captured
another line of sub-process / child output captured subprocessID=0
...

It looks like there's some buffering ongoing, which is why the additinal tags I set are only applied at the start and end for a certain period of events?

Any ideas or suggestions on how I could improve this?