Mockery exit code is dependent on log output being enabled
It appears that there are codepaths that depend on the behavior of "fatal" logger calls calling os.Exit(1). However, this means that running mockery in "quiet" mode will cause it to exit with exit code 0 instead of 1 even on failure.
Running the following fails as expected:
➜ mockery --name="foo"; echo $?
04 Jul 20 13:46 PDT INF Starting mockery dry-run=false version=0.0.0-dev
04 Jul 20 13:46 PDT INF Walking dry-run=false version=0.0.0-dev
04 Jul 20 13:46 PDT FTL Unable to find 'foo' in any go files under this path dry-run=false version=0.0.0-dev
1
However, running the same command with --quiet results in success:
➜ mockery --name="foo" --quiet; echo $?
0
Happy to submit a PR to fix, but would need to decide on an approach first. Broadly, I think there are 2 approaches that make sense:
- If "quiet" is true, set log level to "fatal" and configure logger to not write any output
- Restructure code so that, in any place where "log.Fatal()" is currently called, an error is also returned (or os.Exit(1) is called manually after the log call)
Approach (1) is definitely less code, although it's basically just working around the fundamental issue, which is that logger behavior is currently used as part of behavior/control flow -- for example, although this will fix this specific issue, if someone runs mockery with --log-level panic, this same issue will arise (program will exit with 0 even though a "fatal" error has been encountered).
Approach (2) will require deciding on an approach for this. I think the cleanest approach would be to define an error with the logger content and then return that.
For example, the current:
log.Fatal().Msgf("No go files in package %s", r.Config.SrcPkg)
Becomes:
err = fmt.Errorf("No go files in package %s", r.Config.SrcPkg)
log.Fatal().Msg(err.Error())
return err
This will ensure that, if the logging isn't executed, the error is returned (and at the top level, that will result in a non-0 exit based on Cobra handling).
However, you could also take an approach like defining a logFatalI(log zerolog.Logger, format string, v ...interface{}) function that calls log.Fatal().Msgf(format, v...) followed by os.Exit(1) instead.
Let me know your preferred approach -- I think that approach (2) is better (since otherwise the behavior is always tied to the log output level, which seems wrong), but approach (1) will also unblock.
So really in my opinion we shouldn't be calling Fatal() except at very top-level functions. I intended this to be a port where the code called os.Exit(1), but this is really old cruft and needs to be removed.
As you already know, I really hate the --quiet flag anyway. It's actually disappointing to me that the logger won't call os.Exit(1) anyway even if logging is disabled but it is what it is. I favor more along the lines of (2), however restructuring it so that all functions are returning an error wrapped at some level with a stack trace. Basically, my error handling philosophy in go is:
- Upon encountering an error originating outside of the package (like when calling
osor whatever), wrap it witherrors.Wrapf(err, "cool message"). - Pass the error up the stack without logging it.
- For each level of the stack, pass the error without logging it UNLESS you want to handle the error. If you want to handle the error, log it with
log.Err(err).Msgf("Hello world")and decide what to do with it. - If the error makes it to the top of the stack, print the stack trace (if any) and call
log.Fatal().log.Fatal()should always be able to terminate execution, so we should remove anything that prevents that from happening.
Side note: for any cases where continuing the program is seriously dangerous (unlikely for this project), it's acceptable to call log.Fatal() further down the stack. But typically, it should be called on the top level.
Additionally, I think we should change --quiet to maybe set --log-level=fatal. That would fix the issue above by allowing Fatal to still execute. If people really really care about nothing being sent to stderr/stdout they can redirect to /dev/null.
My error handling philosophy generally aligns with this as well, except for point (4) -- I typically model logging as separate from control flow, so don't use a "fatal" level (and to be honest usually I don't use loggers for CLI programs -- I think they're better suited for long-running servers and such, and with CLIs find that having expected output as part of the API and just exposing a --quiet and --debug mode is often more user-friendly). However, I can certainly see how different views on this also have merit.
In order to do what you want in bullet point 4 (ensure that log.Fatal() should always terminate execution), the current --log-level flag parsing logic would basically have to be updated to reject blank values or any value higher than fatal (basically, "panic"), since those are valid level values where zerolog will skip execution of fatal logging.
From a code perspective, I do think it would be generally cleaner to refactor so that pretty much everything that currently calls log.Fatal or os.Exit(1) returns an error instead, have the top-level Cobra CLI execution command print the stack trace for the error and then just return an error itself (and have a single os.Exit(1) call just at that highest level). However, given the stated philosophy around logging and given that it's already implemented this way, certainly understand if this isn't an approach you would prefer to take.
and to be honest usually I don't use loggers for CLI programs
Yeah I guess that's just a difference of opinion.
have the top-level Cobra CLI execution command print the stack trace for the error and then just return an error itself (and have a single os.Exit(1) call just at that highest level).
I think that's also a fine way to go about it. I think you've convinced me not to rely on Fatal. It's really unfortunate we can't do that, however.
From Cobra's point of view, you should probably be calling os.Exit from this function:
https://github.com/vektra/mockery/blob/1941619d9142befe7b6589896c28a819157355e8/cmd/mockery.go#L31
It seems that returning errors from this function is supposed to indicate argument errors, as it prints the help page (which probably isn't what we want in general errors).