Skip to content

Commit

Permalink
Rewrite base logger internally.
Browse files Browse the repository at this point in the history
  • Loading branch information
efritz committed Oct 7, 2019
1 parent d39cce0 commit 4e537aa
Show file tree
Hide file tree
Showing 27 changed files with 788 additions and 482 deletions.
8 changes: 4 additions & 4 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -82,16 +82,16 @@ The following environment variables change the behavior of the loggers when usin
Example log output is shown below. The outputs are configure in order with: the default configuration, `LOG_ENCODING=json`, `LOG_DISPLAY_FIELDS=false`, `LOG_SHORT_TIME=true`, and `LOG_DISPLAY_MULTILINE_FIELDS=true`.

```
[I] [2019/07/24 09:15:30.806] Accepted request from 68.6.165.7 caller=derision/main.go:20 requestId=12341234-1234-1234-1234-123412341234 sequence_number=2
[I] [2019/07/24 09:15:30.806] Accepted request from 68.6.165.7 caller=derision/main.go:20 requestId=12341234-1234-1234-1234-123412341234 sequenceNumber=2
{"caller":"derision/main.go:20","level":"info","message":"Accepted request from 68.6.165.7","requestId":"12341234-1234-1234-1234-123412341234","sequence_number":2,"timestamp":"2019-07-24T09:16:55.673-0700"}
{"caller":"derision/main.go:20","level":"info","message":"Accepted request from 68.6.165.7","requestId":"12341234-1234-1234-1234-123412341234","sequenceNumber":2,"timestamp":"2019-07-24T09:16:55.673-0700"}
[I] [2019/07/24 09:15:49.517] Accepted request from 68.6.165.7
[I] [09:17:56] Accepted request from 68.6.165.7 caller=derision/main.go:20 requestId=12341234-1234-1234-1234-123412341234 sequence_number=2
[I] [09:17:56] Accepted request from 68.6.165.7 caller=derision/main.go:20 requestId=12341234-1234-1234-1234-123412341234 sequenceNumber=2
[I] [2019/07/24 09:16:38.117] Accepted request from 68.6.165.7
caller = derision/main.go:20
requestId = 12341234-1234-1234-1234-123412341234
sequence_number = 2
sequenceNumber = 2
```
87 changes: 87 additions & 0 deletions base_logger.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,87 @@
package log

import (
"fmt"
"os"
"sync/atomic"
"time"

"github.com/efritz/glock"
)

type baseLogger interface {
Log(timestamp time.Time, level LogLevel, fields LogFields, msg string) error
}

type baseWrapper struct {
logger baseLogger
level LogLevel
clock glock.Clock
exiter func()
sequence uint64
}

type baseShim struct {
wrapper *baseWrapper
fields LogFields
}

//
// Shim

func newBaseShim(logger baseLogger, level LogLevel, initialFields LogFields) Logger {
wrapper := &baseWrapper{
logger,
level,
glock.NewRealClock(),
func() { os.Exit(1) },
0,
}

return adaptShim(&baseShim{wrapper, initialFields})
}

func newTestShim(logger baseLogger, level LogLevel, initialFields LogFields, clock glock.Clock, exiter func()) Logger {
wrapper := &baseWrapper{
logger,
level,
clock,
exiter,
0,
}

return adaptShim(&baseShim{wrapper, initialFields})
}

func (s *baseShim) WithFields(fields LogFields) logShim {
if len(fields) == 0 {
return s
}

return &baseShim{s.wrapper, s.fields.concat(fields)}
}

func (s *baseShim) LogWithFields(level LogLevel, fields LogFields, format string, args ...interface{}) {
if level > s.wrapper.level {
return
}

seq := atomic.AddUint64(&s.wrapper.sequence, 1)
fields = addCaller(fields).normalizeTimeValues()
fields["sequenceNumber"] = seq

s.wrapper.logger.Log(
s.wrapper.clock.Now().UTC(),
level,
s.fields.concat(fields),
fmt.Sprintf(format, args...),
)

if level == LevelFatal {
s.wrapper.exiter()
}
}

func (s *baseShim) Sync() error {
return nil
}
160 changes: 160 additions & 0 deletions base_logger_mock_test.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

89 changes: 89 additions & 0 deletions base_logger_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,89 @@
package log

//go:generate go-mockgen -f github.com/go-nacelle/log -i baseLogger -o base_logger_mock_test.go

import (
"github.com/aphistic/sweet"
"github.com/efritz/glock"
. "github.com/efritz/go-mockgen/matchers"
. "github.com/onsi/gomega"
)

type BaseLoggerSuite struct{}

func (s *BaseLoggerSuite) TestLogFormat(t sweet.T) {
base := NewMockBaseLogger()
clock := glock.NewMockClock()
logger := newTestShim(base, LevelDebug, nil, clock, func() {})
logger.LogWithFields(LevelInfo, nil, "test %d %d %d", 1, 2, 3)

Expect(base.LogFunc).To(BeCalledOnceWith(
clock.Now().UTC(),
LevelInfo,
LogFields{
// Note: this value refers to the line number containing `LogWithFields` in
// the test setup above. If code is added before that line, this value must
// be updated.
"caller": "log/base_logger_test.go:18",
"sequenceNumber": uint64(1),
},
"test 1 2 3",
))
}

func (s *BaseLoggerSuite) TestWrappedLoggers(t sweet.T) {
base := NewMockBaseLogger()
clock := glock.NewMockClock()
logger := newTestShim(base, LevelDebug, LogFields{"init": "foo"}, clock, func() {})
wrappedLogger := logger.WithFields(LogFields{"wrapped": "bar"})
wrappedLogger.LogWithFields(LevelDebug, LogFields{"extra": "baz"}, "test %d %d %d", 1, 2, 3)
logger.LogWithFields(LevelDebug, LogFields{"extra": "bonk"}, "test %d %d %d", 1, 2, 3)

Expect(base.LogFunc).To(BeCalledOnceWith(
clock.Now().UTC(),
LevelDebug,
LogFields{
"init": "foo",
"wrapped": "bar",
"extra": "baz",
// Note: this value refers to the line number containing `LogWithFields` in
// the test setup above. If code is added before that line, this value must
// be updated.
"caller": "log/base_logger_test.go:39",
"sequenceNumber": uint64(1),
},
"test 1 2 3",
))

Expect(base.LogFunc).To(BeCalledOnceWith(
clock.Now().UTC(),
LevelDebug,
LogFields{
"init": "foo",
"extra": "bonk",
// Note: this value refers to the line number containing `LogWithFields` in
// the test setup above. If code is added before that line, this value must
// be updated.
"caller": "log/base_logger_test.go:40",
"sequenceNumber": uint64(2),
},
"test 1 2 3",
))
}

func (s *BaseLoggerSuite) TestLogLevelFilter(t sweet.T) {
base := NewMockBaseLogger()
clock := glock.NewMockClock()
logger := newTestShim(base, LevelInfo, nil, clock, func() {})
logger.LogWithFields(LevelDebug, nil, "test %d %d %d", 1, 2, 3)
Expect(base.LogFunc).NotTo(BeCalled())
}

func (s *BaseLoggerSuite) TestLogFatal(t sweet.T) {
base := NewMockBaseLogger()
clock := glock.NewMockClock()
called := false
logger := newTestShim(base, LevelInfo, nil, clock, func() { called = true })
logger.LogWithFields(LevelFatal, nil, "test %d %d %d", 1, 2, 3)
Expect(called).To(BeTrue())
}
12 changes: 6 additions & 6 deletions caller_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -171,9 +171,9 @@ func (s *CallerSuite) TestTrimPath(t sweet.T) {
Expect(trimPath("/foo/bar/baz/bonk")).To(Equal("baz/bonk"))
}

func (s *CallerSuite) TestGomol(t sweet.T) { s.testBasic(InitGomolShim) }
func (s *CallerSuite) TestGomolWithFields(t sweet.T) { s.testFields(InitGomolShim) }
func (s *CallerSuite) TestGomolWithReplayAdapter(t sweet.T) { s.testReplayAdapter(InitGomolShim) }
func (s *CallerSuite) TestGomolWithRollupAdapter(t sweet.T) { s.testRollupAdapter(InitGomolShim) }
func (s *CallerSuite) TestGomolReplay(t sweet.T) { s.testReplay(InitGomolShim) }
func (s *CallerSuite) TestGomolRollup(t sweet.T) { s.testRollup(InitGomolShim) }
func (s *CallerSuite) TestLogger(t sweet.T) { s.testBasic(InitLogger) }
func (s *CallerSuite) TestLoggerWithFields(t sweet.T) { s.testFields(InitLogger) }
func (s *CallerSuite) TestLoggerWithReplayAdapter(t sweet.T) { s.testReplayAdapter(InitLogger) }
func (s *CallerSuite) TestLoggerWithRollupAdapter(t sweet.T) { s.testRollupAdapter(InitLogger) }
func (s *CallerSuite) TestLoggerReplay(t sweet.T) { s.testReplay(InitLogger) }
func (s *CallerSuite) TestLoggerRollup(t sweet.T) { s.testRollup(InitLogger) }
4 changes: 2 additions & 2 deletions config.go
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ type Config struct {
LogLevel string `env:"log_level" file:"log_level" default:"info"`
LogEncoding string `env:"log_encoding" file:"log_encoding" default:"console"`
LogColorize bool `env:"log_colorize" file:"log_colorize" default:"true"`
LogJSONFieldNames map[string]string `env:"log_json_field_names" file:"log_json_field_names"`
LogJSONFieldNames map[string]string `env:"log_json_field_names" file:"log_json_field_names"` // TODO - not in config
LogInitialFields LogFields `env:"log_fields" file:"log_fields"`
LogShortTime bool `env:"log_short_time" file:"log_short_time" default:"false"`
LogDisplayFields bool `env:"log_display_fields" file:"log_display_fields" default:"true"`
Expand Down Expand Up @@ -47,7 +47,7 @@ func (c *Config) PostLoad() error {
}

func isLegalLevel(level string) bool {
for _, whitelisted := range []string{"debug", "info", "warning", "error", "fatal"} {
for _, whitelisted := range names {
if level == whitelisted {
return true
}
Expand Down
Loading

0 comments on commit 4e537aa

Please sign in to comment.