Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add WithFatalHook/CheckedEntry.After to replace OnFatal/CheckedEntry.Should #1088

Merged
merged 7 commits into from Apr 26, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
23 changes: 16 additions & 7 deletions internal/exit/exit.go
Expand Up @@ -24,24 +24,32 @@ package exit

import "os"

var real = func() { os.Exit(1) }
var _exit = os.Exit

// Exit normally terminates the process by calling os.Exit(1). If the package
// is stubbed, it instead records a call in the testing spy.
// Deprecated: use With() instead.
func Exit() {
real()
With(1)
}

// With terminates the process by calling os.Exit(code). If the package is
// stubbed, it instead records a call in the testing spy.
func With(code int) {
_exit(code)
}

// A StubbedExit is a testing fake for os.Exit.
type StubbedExit struct {
Exited bool
prev func()
Code int
prev func(code int)
}

// Stub substitutes a fake for the call to os.Exit(1).
func Stub() *StubbedExit {
s := &StubbedExit{prev: real}
real = s.exit
s := &StubbedExit{prev: _exit}
_exit = s.exit
return s
}

Expand All @@ -56,9 +64,10 @@ func WithStub(f func()) *StubbedExit {

// Unstub restores the previous exit function.
func (se *StubbedExit) Unstub() {
real = se.prev
_exit = se.prev
}

func (se *StubbedExit) exit() {
func (se *StubbedExit) exit(code int) {
se.Exited = true
se.Code = code
}
19 changes: 13 additions & 6 deletions internal/exit/exit_test.go
Expand Up @@ -18,25 +18,32 @@
// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
// THE SOFTWARE.

package exit
package exit_test

import (
"testing"

"github.com/stretchr/testify/assert"
"go.uber.org/zap/internal/exit"
)

func TestStub(t *testing.T) {
type want struct {
exit bool
code int
}
tests := []struct {
f func()
want bool
want want
}{
{Exit, true},
{func() {}, false},
{func() { exit.With(42) }, want{exit: true, code: 42}},
{exit.Exit, want{exit: true, code: 1}},
{func() {}, want{}},
}

for _, tt := range tests {
s := WithStub(tt.f)
assert.Equal(t, tt.want, s.Exited, "Stub captured unexpected exit value.")
s := exit.WithStub(tt.f)
assert.Equal(t, tt.want.exit, s.Exited, "Stub captured unexpected exit value.")
assert.Equal(t, tt.want.code, s.Code, "Stub captured unexpected exit value.")
}
}
8 changes: 4 additions & 4 deletions logger.go
Expand Up @@ -42,7 +42,7 @@ type Logger struct {

development bool
addCaller bool
onFatal zapcore.CheckWriteAction // default is WriteThenFatal
onFatal zapcore.CheckWriteHook // default is WriteThenFatal

name string
errorOutput zapcore.WriteSyncer
Expand Down Expand Up @@ -288,12 +288,12 @@ func (log *Logger) check(lvl zapcore.Level, msg string) *zapcore.CheckedEntry {
ce = ce.Should(ent, zapcore.WriteThenPanic)
case zapcore.FatalLevel:
onFatal := log.onFatal
// Noop is the default value for CheckWriteAction, and it leads to
// nil is the default value for CheckWriteAction, and it leads to
// continued execution after a Fatal which is unexpected.
if onFatal == zapcore.WriteThenNoop {
if onFatal == nil {
onFatal = zapcore.WriteThenFatal
}
ce = ce.Should(ent, onFatal)
ce = ce.After(ent, onFatal)
case zapcore.DPanicLevel:
if log.development {
ce = ce.Should(ent, zapcore.WriteThenPanic)
Expand Down
17 changes: 17 additions & 0 deletions logger_test.go
Expand Up @@ -579,6 +579,23 @@ func TestLoggerCustomOnFatal(t *testing.T) {
}
}

type customWriteHook struct {
called bool
}

func (h *customWriteHook) OnWrite(_ *zapcore.CheckedEntry, _ []Field) {
h.called = true
}

func TestLoggerWithFatalHook(t *testing.T) {
var h customWriteHook
withLogger(t, InfoLevel, opts(WithFatalHook(&h)), func(logger *Logger, logs *observer.ObservedLogs) {
logger.Fatal("great sadness")
assert.True(t, h.called)
assert.Equal(t, 1, logs.FilterLevelExact(FatalLevel).Len())
})
}

func TestNopLogger(t *testing.T) {
logger := NewNop()

Expand Down
8 changes: 7 additions & 1 deletion options.go
Expand Up @@ -133,9 +133,15 @@ func IncreaseLevel(lvl zapcore.LevelEnabler) Option {
}

// OnFatal sets the action to take on fatal logs.
// Deprecated: Use WithFatalHook instead.
func OnFatal(action zapcore.CheckWriteAction) Option {
return WithFatalHook(action)
}

// WithFatalHook sets a CheckWriteHook to run on fatal logs.
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The documentation should probably call out that users of the logging package expect execution to end at Fatal, and so it's recommended that this either:

  • Exits the process
  • OR exits the goroutine (more for testing) where execution of the goroutine stops, but it can be used for testing.

It's pretty common to see code like:

resp, err = [...]
if err != nil {
  logger.Fatal(err)
}

data, err := ioutil.ReadAll(resp.Body)

This code would panic, but could be other cases where data ends up getting corrupt etc. It's similar to catching panics, but a little riskier since it doesn't even half execution of the specific goroutine that calls Fatal.

Should we make it more difficult to allow execution to continue by disallowing WriteThenNoop for this case (user can still specify their own hook).

One other option is to always runtime.Goexit at minimum after an onFatal, that completely disallows execution to continue for the goroutine calling Fatal, but may be too restrictive, it could simplify testing to allow continue execution after capturing that a Fatal happened, because the test is confident that there's no other logic that would be inadvertently executed.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's fair. Taking a second look, I may have misunderstood the WriteThenNoop hook to mean that it actually allows no-op-ing the Fatal log. But after testing it out, it seems that WriteThenNoop turns into a "os.Exit" as the logic suggests.

func WithFatalHook(hook zapcore.CheckWriteHook) Option {
return optionFunc(func(log *Logger) {
log.onFatal = action
log.onFatal = hook
})
}

Expand Down
55 changes: 39 additions & 16 deletions zapcore/entry.go
Expand Up @@ -27,10 +27,9 @@ import (
"sync"
"time"

"go.uber.org/multierr"
"go.uber.org/zap/internal/bufferpool"
"go.uber.org/zap/internal/exit"

"go.uber.org/multierr"
)

var (
Expand Down Expand Up @@ -152,6 +151,13 @@ type Entry struct {
Stack string
}

// CheckWriteHook allows to customize the action to take after a Fatal log entry
// is processed.
type CheckWriteHook interface {
// OnWrite gets invoked when an entry is written
OnWrite(*CheckedEntry, []Field)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It may be useful to document that the fields here are not all fields on the logger, but just the fields specific to the message.

}

// CheckWriteAction indicates what action to take after a log entry is
// processed. Actions are ordered in increasing severity.
type CheckWriteAction uint8
Expand All @@ -164,10 +170,25 @@ const (
WriteThenGoexit
// WriteThenPanic causes a panic after Write.
WriteThenPanic
// WriteThenFatal causes a fatal os.Exit after Write.
// WriteThenFatal causes an os.Exit(1) after Write.
WriteThenFatal
)

// OnWrite implements the OnWrite method to keep CheckWriteAction compatible
// with the new CheckWriteHook interface which deprecates CheckWriteAction.
func (a CheckWriteAction) OnWrite(ce *CheckedEntry, _ []Field) {
switch a {
case WriteThenGoexit:
runtime.Goexit()
case WriteThenPanic:
panic(ce.Message)
case WriteThenFatal:
exit.Exit()
}
}

var _ CheckWriteHook = CheckWriteAction(0)

// CheckedEntry is an Entry together with a collection of Cores that have
// already agreed to log it.
//
Expand All @@ -178,15 +199,15 @@ type CheckedEntry struct {
Entry
ErrorOutput WriteSyncer
dirty bool // best-effort detection of pool misuse
should CheckWriteAction
after CheckWriteHook
cores []Core
}

func (ce *CheckedEntry) reset() {
ce.Entry = Entry{}
ce.ErrorOutput = nil
ce.dirty = false
ce.should = WriteThenNoop
ce.after = nil
for i := range ce.cores {
// don't keep references to cores
ce.cores[i] = nil
Expand Down Expand Up @@ -224,17 +245,11 @@ func (ce *CheckedEntry) Write(fields ...Field) {
ce.ErrorOutput.Sync()
}

should, msg := ce.should, ce.Message
putCheckedEntry(ce)

switch should {
case WriteThenPanic:
panic(msg)
case WriteThenFatal:
exit.Exit()
case WriteThenGoexit:
runtime.Goexit()
hook := ce.after
if hook != nil {
hook.OnWrite(ce, fields)
}
putCheckedEntry(ce)
}

// AddCore adds a Core that has agreed to log this CheckedEntry. It's intended to be
Expand All @@ -252,11 +267,19 @@ func (ce *CheckedEntry) AddCore(ent Entry, core Core) *CheckedEntry {
// Should sets this CheckedEntry's CheckWriteAction, which controls whether a
// Core will panic or fatal after writing this log entry. Like AddCore, it's
// safe to call on nil CheckedEntry references.
// Deprecated: Use After(ent Entry, after CheckWriteHook) instead.
func (ce *CheckedEntry) Should(ent Entry, should CheckWriteAction) *CheckedEntry {
return ce.After(ent, should)
}

// After sets this CheckEntry's CheckWriteHook, which will be called after this
// log entry has been written. It's safe to call this on nil CheckedEntry
// references.
func (ce *CheckedEntry) After(ent Entry, hook CheckWriteHook) *CheckedEntry {
if ce == nil {
ce = getCheckedEntry()
ce.Entry = ent
}
ce.should = should
ce.after = hook
return ce
}
19 changes: 18 additions & 1 deletion zapcore/entry_test.go
Expand Up @@ -64,7 +64,7 @@ func TestPutNilEntry(t *testing.T) {
assert.NotNil(t, ce, "Expected only non-nil CheckedEntries in pool.")
assert.False(t, ce.dirty, "Unexpected dirty bit set.")
assert.Nil(t, ce.ErrorOutput, "Non-nil ErrorOutput.")
assert.Equal(t, WriteThenNoop, ce.should, "Unexpected terminal behavior.")
assert.Nil(t, ce.after, "Unexpected terminal behavior.")
assert.Equal(t, 0, len(ce.cores), "Expected empty slice of cores.")
assert.True(t, cap(ce.cores) > 0, "Expected pooled CheckedEntries to pre-allocate slice of Cores.")
}
Expand Down Expand Up @@ -128,5 +128,22 @@ func TestCheckedEntryWrite(t *testing.T) {
ce.Write()
})
assert.True(t, stub.Exited, "Expected to exit when WriteThenFatal is set.")
assert.Equal(t, 1, stub.Code, "Expected to exit when WriteThenFatal is set.")
})

t.Run("After", func(t *testing.T) {
var ce *CheckedEntry
hook := &customHook{}
ce = ce.After(Entry{}, hook)
ce.Write()
assert.True(t, hook.called, "Expected to call custom action after Write.")
})
}

type customHook struct {
called bool
}

func (c *customHook) OnWrite(_ *CheckedEntry, _ []Field) {
c.called = true
}