From d857907cfa74f6c3dd394cd626d235256e54b183 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 16 Feb 2017 14:45:48 -0800 Subject: [PATCH 01/13] Add zap 1.0.0-rc.1 to Glide manifest This necessarily updates all the other dependencies, too. --- glide.lock | 20 ++++++++++++-------- glide.yaml | 5 ++--- 2 files changed, 14 insertions(+), 11 deletions(-) diff --git a/glide.lock b/glide.lock index 47eddc718..f71a5a14d 100644 --- a/glide.lock +++ b/glide.lock @@ -1,12 +1,10 @@ -hash: 62f71321007123913c74ecafdef1501b8407cc0a0572d02111e39ef0e22ae7cd -updated: 2017-02-15T11:44:42.670193638-08:00 +hash: f4a033e6af47e10391f8b22f93a319ab1becad7c4c6035665f0def36d18d76ed +updated: 2017-02-16T00:35:29.71174199-08:00 imports: - name: github.com/apache/thrift version: 9549b25c77587b29be4e0b5c258221a4ed85d37a subpackages: - lib/go/thrift -- name: github.com/certifi/gocertifi - version: 03be5e6bb9874570ea7fb0961225d193cbc374c5 - name: github.com/davecgh/go-spew version: 04cdfd42973bb9c8589fd6a731800cf222fde1a9 subpackages: @@ -46,9 +44,7 @@ imports: - name: github.com/uber-go/tally version: 43c1379c0577ac1eb74f9f3869cea07191c9992b - name: github.com/uber-go/zap - version: c064b5c44b285a7e2fd5c9b26e8c38228ce2bccb - subpackages: - - spy + version: 72313cde80537dd4dc9b7b80eda6d7ed796c4232 - name: github.com/uber/jaeger-client-go version: e39d0f1b622558cae3d9db0062a739cc6ffa700f subpackages: @@ -111,8 +107,16 @@ imports: - transport/http - transport/tchannel - transport/tchannel/internal +- name: go.uber.org/zap + version: 72313cde80537dd4dc9b7b80eda6d7ed796c4232 + subpackages: + - buffer + - internal/bufferpool + - internal/exit + - internal/multierror + - zapcore - name: golang.org/x/net - version: 61557ac0112b576429a0df080e1c2cef5dfbb642 + version: b4690f45fa1cafc47b1c280c2e75116efe40cc13 subpackages: - context - context/ctxhttp diff --git a/glide.yaml b/glide.yaml index e1a0e18d3..4a8d8b050 100644 --- a/glide.yaml +++ b/glide.yaml @@ -1,8 +1,7 @@ package: go.uber.org/fx import: -- package: github.com/uber-go/zap - # Pinned temporarily while zap reaches 1.0 (https://github.com/uber-go/fx/pull/243) - version: c064b5c44b285a7e2fd5c9b26e8c38228ce2bccb +- package: go.uber.org/zap + version: v1.0.0-rc.1 - package: github.com/uber-go/tally version: ^1.1.0 - package: github.com/gorilla/mux From c877139835c9d24c7271f7fddc54c2a786a469f5 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Fri, 17 Feb 2017 23:36:14 -0800 Subject: [PATCH 02/13] Update ulog to the latest zap Remove most of ulog, since it's either unnecessary or subsumed by zap. The only lost functionality here is Sentry integration, which we can bring back next week (either as an UberFX-specific encoder wrapper, or as a Filebeat plugin). --- glide.yaml | 4 +- ulog/README.md | 2 +- ulog/builder.go | 206 -------------------- ulog/builder_test.go | 209 -------------------- ulog/context.go | 81 ++++++++ ulog/context_test.go | 98 ++++++++++ ulog/doc.go | 13 -- ulog/log.go | 267 +++----------------------- ulog/log_benchmark_test.go | 145 -------------- ulog/log_test.go | 234 ----------------------- ulog/metrics.go | 66 +++++++ ulog/metrics/metrics.go | 48 ----- ulog/{metrics => }/metrics_test.go | 51 ++--- ulog/nop_logger.go | 32 ---- ulog/sentry/capturer.go | 56 ------ ulog/sentry/sentry.go | 264 -------------------------- ulog/sentry/sentry_test.go | 294 ----------------------------- 17 files changed, 297 insertions(+), 1773 deletions(-) delete mode 100644 ulog/builder.go delete mode 100644 ulog/builder_test.go create mode 100644 ulog/context.go create mode 100644 ulog/context_test.go delete mode 100644 ulog/log_benchmark_test.go delete mode 100644 ulog/log_test.go create mode 100644 ulog/metrics.go delete mode 100644 ulog/metrics/metrics.go rename ulog/{metrics => }/metrics_test.go (55%) delete mode 100644 ulog/nop_logger.go delete mode 100644 ulog/sentry/capturer.go delete mode 100644 ulog/sentry/sentry.go delete mode 100644 ulog/sentry/sentry_test.go diff --git a/glide.yaml b/glide.yaml index 4a8d8b050..108cb1b67 100644 --- a/glide.yaml +++ b/glide.yaml @@ -1,7 +1,9 @@ package: go.uber.org/fx import: - package: go.uber.org/zap - version: v1.0.0-rc.1 + version: a6ddd813074ca930e15d768c0f2a941afcc36b27 + # Waiting on https://github.com/uber-go/zap/pull/329 + # version: v1.0.0-rc.1 - package: github.com/uber-go/tally version: ^1.1.0 - package: github.com/gorilla/mux diff --git a/ulog/README.md b/ulog/README.md index eda9d7364..e4444d0a0 100644 --- a/ulog/README.md +++ b/ulog/README.md @@ -138,7 +138,7 @@ To set up Sentry in code use `sentry.Hook`. For example: ```go import ( - "github.com/uber-go/zap" + "go.uber.org/zap" "go.uber.org/fx/ulog/ulog" "go.uber.org/fx/ulog/sentry" "go.uber.org/fx/service" diff --git a/ulog/builder.go b/ulog/builder.go deleted file mode 100644 index 84b4dbdfe..000000000 --- a/ulog/builder.go +++ /dev/null @@ -1,206 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package ulog - -import ( - "io" - "os" - "path" - - "go.uber.org/fx/config" - "go.uber.org/fx/ulog/metrics" - "go.uber.org/fx/ulog/sentry" - - "github.com/uber-go/tally" - "github.com/uber-go/zap" -) - -// Configuration for logging with UberFx -type Configuration struct { - Level string - File *FileConfiguration - Stdout bool - Verbose bool - - // Do not automatically emit metrics for logging counts - DisableMetrics bool - - Sentry *sentry.Configuration - - prefixWithFileLine *bool `yaml:"prefix_with_fileline"` - TextFormatter *bool // use TextFormatter (default json) -} - -// FileConfiguration describes the properties needed to log to a file -type FileConfiguration struct { - Enabled bool - Directory string - FileName string -} - -// LogBuilder is the struct containing logger -type LogBuilder struct { - log zap.Logger - logConfig Configuration - sentryHook *sentry.Hook - scope tally.Scope -} - -// Builder creates an empty builder for building ulog.Log object -func Builder() *LogBuilder { - return &LogBuilder{} -} - -// New instance of ulog.Log is returned with the default setup -func New() Log { - return Builder().Build() -} - -// WithConfiguration sets up configuration for the log builder -func (lb *LogBuilder) WithConfiguration(logConfig Configuration) *LogBuilder { - lb.logConfig = logConfig - return lb -} - -// WithScope sets up configuration for the log builder -func (lb *LogBuilder) WithScope(s tally.Scope) *LogBuilder { - lb.scope = s - return lb -} - -// SetLogger allows users to set their own initialized logger to work with ulog APIs -func (lb *LogBuilder) SetLogger(zap zap.Logger) *LogBuilder { - lb.log = zap - return lb -} - -// WithSentryHook allows users to manually configure the sentry hook -func (lb *LogBuilder) WithSentryHook(hook *sentry.Hook) *LogBuilder { - lb.sentryHook = hook - return lb -} - -// Build the ulog logger for use -// TODO: build should return `(Log, error)` in case we can't properly instantiate -func (lb *LogBuilder) Build() Log { - var log zap.Logger - - // When setLogger is called, we will always use logger that has been set - if lb.log != nil { - return &baseLogger{ - log: lb.log, - } - } - - if config.IsDevelopmentEnv() { - log = lb.devLogger() - } else { - log = lb.Configure() - } - - // TODO(glib): document that yaml configuration takes precedence or - // make the situation better so yaml overrides only the DSN - if lb.logConfig.Sentry != nil { - if len(lb.logConfig.Sentry.DSN) > 0 { - hook, err := sentry.Configure(*lb.logConfig.Sentry) - if err == nil { - lb.sentryHook = hook - } else { - log.Warn("Sentry creation failed with error", zap.Error(err)) - } - } - } - - return &baseLogger{ - log: log, - sh: lb.sentryHook, - } -} - -func (lb *LogBuilder) devLogger() zap.Logger { - return zap.New(zap.NewTextEncoder(), zap.DebugLevel) -} - -func (lb *LogBuilder) defaultLogger() zap.Logger { - return zap.New(zap.NewJSONEncoder(), zap.InfoLevel, zap.Output(zap.AddSync(os.Stdout))) -} - -// Configure Log object with the provided log.Configuration -func (lb *LogBuilder) Configure() zap.Logger { - lb.log = lb.defaultLogger() - options := lb.zapOptions() - - if lb.logConfig.TextFormatter != nil && *lb.logConfig.TextFormatter { - return zap.New(zap.NewTextEncoder(), options...) - } - return zap.New(zap.NewJSONEncoder(), options...) -} - -// Return the list of zap options based on the logger configuration -func (lb *LogBuilder) zapOptions() []zap.Option { - var options []zap.Option - if lb.logConfig.Verbose { - options = append(options, zap.DebugLevel) - } else { - lb.log.Info("Setting log level", zap.String("level", lb.logConfig.Level)) - var lv zap.Level - err := lv.UnmarshalText([]byte(lb.logConfig.Level)) - if err != nil { - lb.log.Debug( - "Cannot parse log level. Setting to Debug as default", - zap.String("level", lb.logConfig.Level), - ) - } else { - options = append(options, lv) - } - } - - if lb.scope != nil && !lb.logConfig.DisableMetrics { - sub := lb.scope.SubScope("logging") - options = append(options, metrics.Hook(sub)) - } - - if lb.logConfig.File == nil || !lb.logConfig.File.Enabled { - options = append(options, zap.Output(zap.AddSync(os.Stdout))) - } else { - options = append(options, zap.Output(lb.fileOutput(lb.logConfig.File, lb.logConfig.Stdout, lb.logConfig.Verbose))) - } - - return options -} - -func (lb *LogBuilder) fileOutput(cfg *FileConfiguration, stdout bool, verbose bool) zap.WriteSyncer { - fileLoc := path.Join(cfg.Directory, cfg.FileName) - lb.log.Debug("adding log file output to zap") - err := os.MkdirAll(cfg.Directory, os.FileMode(0755)) - if err != nil { - lb.log.Fatal("Failed to create log directory: ", zap.Error(err)) - } - file, err := os.OpenFile(fileLoc, os.O_WRONLY|os.O_APPEND|os.O_CREATE, os.FileMode(0755)) - if err != nil { - lb.log.Fatal("Failed to open log file for writing.", zap.Error(err)) - } - lb.log.Debug("Logfile created successfully", zap.String("filename", fileLoc)) - if verbose || stdout { - return zap.AddSync(io.MultiWriter(os.Stdout, file)) - } - return zap.AddSync(file) -} diff --git a/ulog/builder_test.go b/ulog/builder_test.go deleted file mode 100644 index 0e7e492e9..000000000 --- a/ulog/builder_test.go +++ /dev/null @@ -1,209 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package ulog - -import ( - "io/ioutil" - "os" - "path/filepath" - "testing" - - "go.uber.org/fx/config" - "go.uber.org/fx/testutils/env" - "go.uber.org/fx/ulog/sentry" - - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - "github.com/uber-go/tally" - "github.com/uber-go/zap" - "go.uber.org/fx/testutils/metrics" -) - -func TestConfiguredLogger(t *testing.T) { - withLogger(t, func(builder *LogBuilder, tmpDir string, logFile string) { - txt := false - cfg := Configuration{ - Level: "debug", - Stdout: false, - TextFormatter: &txt, - Verbose: false, - } - log := builder.WithConfiguration(cfg).Build() - zapLogger := log.Typed() - assert.True(t, zapLogger.Check(zap.DebugLevel, "").OK()) - }) -} - -func TestConfiguredLoggerWithTextFormatter(t *testing.T) { - withLogger(t, func(builder *LogBuilder, tmpDir string, logFile string) { - txt := true - cfg := Configuration{ - Level: "debug", - Stdout: false, - TextFormatter: &txt, - Verbose: false, - File: &FileConfiguration{ - Directory: tmpDir, - FileName: logFile, - Enabled: true, - }, - } - log := Builder().WithConfiguration(cfg).Build() - zapLogger := log.Typed() - assert.True(t, zapLogger.Check(zap.DebugLevel, "").OK()) - }) -} - -func TestConfiguredLoggerWithTextFormatter_NonDev(t *testing.T) { - withLogger(t, func(builder *LogBuilder, tmpDir string, logFile string) { - txt := true - log := Builder().WithConfiguration(Configuration{ - Level: "debug", - TextFormatter: &txt, - }).Build() - zapLogger := log.Typed() - assert.True(t, zapLogger.Check(zap.DebugLevel, "").OK()) - }) -} - -func TestConfiguredLoggerWithStdout(t *testing.T) { - withLogger(t, func(builder *LogBuilder, tmpDir string, logFile string) { - txt := false - cfg := Configuration{ - Stdout: true, - TextFormatter: &txt, - Verbose: true, - File: &FileConfiguration{ - Enabled: true, - Directory: tmpDir, - FileName: logFile, - }, - } - log := Builder().WithConfiguration(cfg).Build() - zapLogger := log.Typed() - assert.True(t, zapLogger.Check(zap.DebugLevel, "").OK()) - }) -} - -func withLogger(t *testing.T, f func(*LogBuilder, string, string)) { - defer env.Override(t, config.EnvironmentKey(), "madeup")() - tmpDir, err := ioutil.TempDir("", "default_log") - defer func() { - assert.NoError(t, os.RemoveAll(tmpDir), "should be able to delete tempdir") - }() - require.NoError(t, err) - - tmpFile, err := ioutil.TempFile(tmpDir, "temp_log.txt") - require.NoError(t, err) - logFile, err := filepath.Rel(tmpDir, tmpFile.Name()) - require.NoError(t, err) - txt := false - cfg := Configuration{ - Level: "error", - Stdout: false, - TextFormatter: &txt, - Verbose: false, - File: &FileConfiguration{ - Enabled: true, - Directory: tmpDir, - FileName: logFile, - }, - } - builder := Builder().WithConfiguration(cfg) - f(builder, tmpDir, logFile) -} - -func TestDefaultPackageLogger(t *testing.T) { - withLogger(t, func(builder *LogBuilder, tmpDir string, logFile string) { - defer env.Override(t, config.EnvironmentKey(), "development")() - log := New() - zapLogger := log.Typed() - assert.True(t, zapLogger.Check(zap.DebugLevel, "").OK()) - }) -} - -func TestConfiguredLoggerWithSentrySuccessful(t *testing.T) { - testSentry(t, "https://u:p@example.com/sentry/1", true) -} - -func TestConfiguredLoggerWithSentryError(t *testing.T) { - testSentry(t, "", false) - testSentry(t, "invalid_dsn", false) -} - -func TestMetricsHook(t *testing.T) { - // TODO(glib): logging init needs to be fixed - // Any tests that run in development environment can't configure the logger, - // it just creates the default one... - defer env.Override(t, config.EnvironmentKey(), "wat?")() - - s, r := metrics.NewTestScope() - l := Builder().WithScope(s).Build() - - r.CountersWG.Add(1) - l.Warn("Warning log!") - r.CountersWG.Wait() - - assert.Equal(t, 1, len(r.Counters)) -} - -func TestLoggingMetricsDisabled(t *testing.T) { - testCases := []struct { - name string - disableMetrics bool - optsLen int - }{ - {"Disabled", true, 1}, - {"Enabled", false, 2}, - } - - for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - logCfg := Configuration{DisableMetrics: tc.disableMetrics} - builder := Builder().WithConfiguration(logCfg).WithScope(tally.NoopScope) - builder.log = builder.defaultLogger() - opts := builder.zapOptions() - assert.Equal(t, tc.optsLen, len(opts)) - }) - } -} - -func testSentry(t *testing.T, dsn string, isValid bool) { - withLogger(t, func(builder *LogBuilder, tmpDir string, logFile string) { - txt := false - cfg := Configuration{ - Level: "debug", - Stdout: false, - TextFormatter: &txt, - Verbose: false, - Sentry: &sentry.Configuration{DSN: dsn}, - } - logBuilder := builder.WithConfiguration(cfg) - log := logBuilder.Build() - zapLogger := log.Typed() - assert.True(t, zapLogger.Check(zap.DebugLevel, "").OK()) - if isValid { - assert.NotNil(t, logBuilder.sentryHook) - } else { - assert.Nil(t, logBuilder.sentryHook) - } - }) -} diff --git a/ulog/context.go b/ulog/context.go new file mode 100644 index 000000000..61c152c62 --- /dev/null +++ b/ulog/context.go @@ -0,0 +1,81 @@ +// Copyright (c) 2017 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package ulog + +import ( + "context" + "fmt" + + opentracing "github.com/opentracing/opentracing-go" + jaeger "github.com/uber/jaeger-client-go" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// Logger returns a *zap.Logger that's pre-seeded with tracing information from +// the provided context. +func Logger(ctx context.Context) *zap.Logger { + if ctx == nil { + return zap.L() + } + return zap.L().With(Trace(ctx)) +} + +// Sugar retrieves a loosely-typed zap.SugaredLogger from the provided context. +func Sugar(ctx context.Context) *zap.SugaredLogger { + return Logger(ctx).Sugar() +} + +// Trace creates a field that extracts tracing information from a context +// (including trace, span, and parent IDs) and includes it under the "trace" +// key. +// +// Because the opentracing APIs don't expose this information, the returned +// zap.Field is a no-op for contexts that don't contain a span or contain a +// non-Jaeger span. +func Trace(ctx context.Context) zapcore.Field { + if ctx == nil { + return zap.Skip() + } + return zap.Object("trace", trace{ctx}) +} + +type trace struct { + ctx context.Context +} + +func (t trace) MarshalLogObject(enc zapcore.ObjectEncoder) error { + span := opentracing.SpanFromContext(t.ctx) + if span == nil { + return nil + } + j, ok := span.Context().(jaeger.SpanContext) + if !ok { + return nil + } + if !j.IsValid() { + return fmt.Errorf("invalid span: %v", j.SpanID()) + } + enc.AddUint64("span", j.SpanID()) + enc.AddUint64("trace", j.TraceID()) + enc.AddUint64("parent", j.ParentID()) + return nil +} diff --git a/ulog/context_test.go b/ulog/context_test.go new file mode 100644 index 000000000..14fc16c7c --- /dev/null +++ b/ulog/context_test.go @@ -0,0 +1,98 @@ +// Copyright (c) 2017 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package ulog + +import ( + "context" + "testing" + + "go.uber.org/fx/testutils" + + opentracing "github.com/opentracing/opentracing-go" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + jaeger "github.com/uber/jaeger-client-go" + "go.uber.org/zap" + ztest "go.uber.org/zap/testutils" + "go.uber.org/zap/zapcore" +) + +func TestLogger(t *testing.T) { + t.Run("Nil context", func(t *testing.T) { + assert.Equal(t, zap.L(), Logger(nil), "Expected to fall back to global Logger.") + assert.Equal(t, zap.S(), Sugar(nil), "Expected to fall back to global SugaredLogger.") + }) + + t.Run("Non-nil context", func(t *testing.T) { + testutils.WithInMemoryLogger(t, nil, func(logger *zap.Logger, buf *ztest.Buffer) { + defer zap.ReplaceGlobals(logger)() + withTracedContext(func(ctx context.Context) { + Logger(ctx).Info("") + Sugar(ctx).Info("") + }) + output := buf.Lines() + assert.Equal(t, 2, len(output)) + for _, line := range output { + assert.Regexp( + t, + `{"level":"info","msg":"","trace":{"span":\d+,"trace":\d+,"parent":\d+}}`, + line, + "Expected output to contain tracing info.", + ) + } + }) + }) +} + +func TestTraceField(t *testing.T) { + assert.Equal(t, zap.Skip(), Trace(nil), "Expected Trace of a nil context to be a no-op.") + + withTracedContext(func(ctx context.Context) { + enc := zapcore.NewMapObjectEncoder() + Trace(ctx).AddTo(enc) + + logged, ok := enc.Fields["trace"].(map[string]interface{}) + require.True(t, ok, "Expected trace to be a map.") + keys := make(map[string]struct{}, len(logged)) + for k := range logged { + keys[k] = struct{}{} + } + + // We could extract the span from the context and assert specific IDs, + // but that just copies the production code. + assert.Equal( + t, + map[string]struct{}{"span": struct{}{}, "trace": struct{}{}, "parent": struct{}{}}, + keys, + "Expected to log span and trace IDs.", + ) + }) +} + +func withTracedContext(f func(ctx context.Context)) { + tracer, closer := jaeger.NewTracer( + "serviceName", jaeger.NewConstSampler(true), jaeger.NewNullReporter(), + ) + defer closer.Close() + + ctx := opentracing.ContextWithSpan(context.Background(), tracer.StartSpan("test")) + f(ctx) +} diff --git a/ulog/doc.go b/ulog/doc.go index 1d37d1fde..5bc12ab8c 100644 --- a/ulog/doc.go +++ b/ulog/doc.go @@ -112,19 +112,6 @@ // stdout: true // level: debug // -// Benchmarks -// -// Current performance benchmark data with ulog interface, -// ulog baseLogger struct, and zap.Logger -// -// BenchmarkUlogWithoutFields-8 10000000 223 ns/op 0 B/op 0 allocs/op -// BenchmarkUlogWithFieldsLogIFace-8 1000000 1237 ns/op 1005 B/op 18 allocs/op -// BenchmarkUlogWithFieldsBaseLoggerStruct-8 1000000 1096 ns/op 748 B/op 17 allocs/op -// BenchmarkUlogWithFieldsZapLogger-8 2000000 664 ns/op 514 B/op 1 allocs/op -// BenchmarkUlogLiteWithFields-8 3000000 489 ns/op 249 B/op 6 allocs/op -// BenchmarkUlogSentry-8 3000000 407 ns/op 128 B/op 4 allocs/op -// BenchmarkUlogSentryWith-8 1000000 1535 ns/op 1460 B/op 12 allocs/op -// // Sentry // // ulog has a seamless integration with Sentry. For out-of-the-box usage diff --git a/ulog/log.go b/ulog/log.go index 401350a4f..846e4ebcd 100644 --- a/ulog/log.go +++ b/ulog/log.go @@ -20,258 +20,33 @@ package ulog -import ( - "context" - stderr "errors" - "fmt" - "sync" - "time" +import "go.uber.org/zap" - "go.uber.org/fx/internal" - "go.uber.org/fx/ulog/sentry" - - "github.com/opentracing/opentracing-go" - "github.com/pkg/errors" - "github.com/uber-go/zap" - "github.com/uber-go/zap/spy" - "github.com/uber/jaeger-client-go" -) - -type baseLogger struct { - sh *sentry.Hook - log zap.Logger -} - -// Log is the UberFx wrapper for underlying logging service -type Log interface { - // With creates a child logger with the provided parameters as key value pairs - // ulog uses uber-go/zap library as its child logger which needs pairs of key value objects - // in the form of zap.Fields(key, value). ulog performs field conversion from - // supplied keyVals pair to zap.Fields format. - // - // **IMPORTANT**: With should never be used if the resulting logger - // object is not being retained. If you need to add some context to - // a logging message, use the Error, Info, etc. functions - // and pass in additional interface{} pairs for logging. - With(keyVals ...interface{}) Log - - // Check returns a zap.CheckedMessage if logging a message at the specified level is enabled. - Check(level zap.Level, message string) *zap.CheckedMessage - - // Typed returns underlying logger implementation (zap.Logger) to get around the ulog.Log interface - Typed() zap.Logger - - // Log at the provided zap.Level with message, and a sequence of parameters as key value pairs - Log(level zap.Level, message string, keyVals ...interface{}) - - // Debug logs at Debug level with message, and parameters as key value pairs - Debug(message string, keyVals ...interface{}) - - // Info logs at Info level with message, and parameters as key value pairs - Info(message string, keyVals ...interface{}) - - // Warn ogs at Warn level with message, and parameters as key value pairs - Warn(message string, keyVals ...interface{}) - - // Error logs at Error level with message, and parameters as key value pairs - Error(message string, keyVals ...interface{}) - - // Panic logs at Panic level with message, and parameters as key value pairs - Panic(message string, keyVals ...interface{}) - - // Fatal logs at Fatal level with message, and parameters as key value pairs - Fatal(message string, keyVals ...interface{}) - - // DPanic logs at Debug level (Fatal for development) with message, and parameters as key value pairs - DPanic(message string, keyVals ...interface{}) -} - -var ( - _setupMu sync.RWMutex - _once sync.Once - _std = defaultLogger() -) - -func defaultLogger() *baseLogger { - return &baseLogger{ - log: zap.New(zap.NewJSONEncoder()), - } -} - -// TestingLogger returns basic logger and underlying sink for testing the messages -// WithInMemoryLogger testing helper can also be used to test actual outputted -// JSON bytes -func TestingLogger() (Log, *spy.Sink) { - log, sink := spy.New() - return &baseLogger{ - log: log, - }, sink -} - -func logger() Log { - _setupMu.RLock() - defer _setupMu.RUnlock() - - return &baseLogger{ - log: _std.log, - } -} - -// SetLogger sets configured logger at the start of the service -func SetLogger(log Log) { - _setupMu.Lock() - defer _setupMu.Unlock() - _once.Do(func() { - // Log and _std log implements zap.Logger with set of predefined fields, - // so we require users to use the configured logger. The Zap implementation however - // can be overridden by log.SetLogger(zap.Logger) - _std = log.(*baseLogger) - }) -} - -// Logger is the context based logger -func Logger(ctx context.Context) Log { - if ctx == nil { - panic("logger requires a context that cannot be nil") - } - log := ctx.Value(internal.ContextLogger) - if log != nil { - return log.(Log) - } - return logger() -} - -// ContextWithLogger sets the context with the context aware logger -func ContextWithLogger(ctx context.Context, log Log) context.Context { - if ctx == nil { - ctx = context.Background() - } - if log != nil { - return context.WithValue(ctx, internal.ContextLogger, log) - } - return context.WithValue(ctx, internal.ContextLogger, logger()) -} - -// ContextWithTraceLogger returns a new context with a context-aware logger -func ContextWithTraceLogger(ctx context.Context, span opentracing.Span) context.Context { - // Note that opentracing.Tracer does not expose the tracer id - // We only inject tracing information for jaeger.Tracer - logger := Logger(ctx) - if jSpanCtx, ok := span.Context().(jaeger.SpanContext); ok { - logger = logger.With( - "traceID", jSpanCtx.TraceID(), "spanID", jSpanCtx.SpanID(), - ) - } - return context.WithValue(ctx, internal.ContextLogger, logger) -} - -// Typed returns underneath zap implementation for use -func (l *baseLogger) Typed() zap.Logger { - return l.log -} - -func (l *baseLogger) With(keyVals ...interface{}) Log { - var sh *sentry.Hook - if l.sh != nil { - sh = l.sh.Copy() - sh.AppendFields(keyVals...) - } - - return &baseLogger{ - log: l.log.With(l.fieldsConversion(keyVals...)...), - sh: sh, - } -} - -func (l *baseLogger) Check(level zap.Level, expr string) *zap.CheckedMessage { - return l.log.Check(level, expr) -} - -func (l *baseLogger) Debug(message string, keyVals ...interface{}) { - l.Log(zap.DebugLevel, message, keyVals...) +// Configuration defines the desired logging options. +type Configuration struct { + zap.Config + // Leave space for non-core config, like Sentry. } -func (l *baseLogger) Info(message string, keyVals ...interface{}) { - l.Log(zap.InfoLevel, message, keyVals...) -} - -func (l *baseLogger) Warn(message string, keyVals ...interface{}) { - l.Log(zap.WarnLevel, message, keyVals...) -} - -func (l *baseLogger) Error(message string, keyVals ...interface{}) { - l.Log(zap.ErrorLevel, message, keyVals...) -} - -func (l *baseLogger) Panic(message string, keyVals ...interface{}) { - l.Log(zap.PanicLevel, message, keyVals...) -} - -func (l *baseLogger) Fatal(message string, keyVals ...interface{}) { - l.Log(zap.FatalLevel, message, keyVals...) -} - -func (l *baseLogger) DPanic(message string, keyVals ...interface{}) { - l.log.DPanic(message, l.fieldsConversion(keyVals...)...) -} +// DefaultConfiguration returns a fallback configuration for applications that +// don't explicitly configure logging. +func DefaultConfiguration() Configuration { + cfg := zap.NewProductionConfig() + cfg.OutputPaths = []string{"stdout"} -func (l *baseLogger) Log(lvl zap.Level, message string, keyVals ...interface{}) { - if cm := l.Check(lvl, message); cm.OK() { - cm.Write(l.fieldsConversion(keyVals...)...) - } - if l.sh != nil { - l.sh.CheckAndFire(lvl, message, keyVals...) + return Configuration{ + Config: cfg, } } -type stackTracer interface { - error - StackTrace() errors.StackTrace -} - -func (l *baseLogger) fieldsConversion(keyVals ...interface{}) []zap.Field { - if len(keyVals)%2 != 0 { - return []zap.Field{zap.Error(stderr.New("expected even number of arguments"))} - } - - fields := make([]zap.Field, 0, len(keyVals)/2) - for idx := 0; idx < len(keyVals); idx += 2 { - if key, ok := keyVals[idx].(string); ok { - switch value := keyVals[idx+1].(type) { - case bool: - fields = append(fields, zap.Bool(key, value)) - case float64: - fields = append(fields, zap.Float64(key, value)) - case int: - fields = append(fields, zap.Int(key, value)) - case int64: - fields = append(fields, zap.Int64(key, value)) - case uint: - fields = append(fields, zap.Uint(key, value)) - case uint64: - fields = append(fields, zap.Uint64(key, value)) - case uintptr: - fields = append(fields, zap.Uintptr(key, value)) - case string: - fields = append(fields, zap.String(key, value)) - case time.Time: - fields = append(fields, zap.Time(key, value)) - case time.Duration: - fields = append(fields, zap.Duration(key, value)) - case zap.LogMarshaler: - fields = append(fields, zap.Marshaler(key, value)) - case fmt.Stringer: - fields = append(fields, zap.Stringer(key, value)) - case stackTracer: - fields = append(fields, - zap.String("stacktrace", fmt.Sprintf("%+v", value.StackTrace())), - zap.Error(value)) - case error: - fields = append(fields, zap.Error(value)) - default: - fields = append(fields, zap.Object(key, value)) - } - } +// SetLogger uses the provided logger to replace zap's global loggers and +// hijack output from the standard library's "log" package. It returns a +// function to undo these changes. +func SetLogger(log *zap.Logger) func() { + undoGlobals := zap.ReplaceGlobals(log) + undoHijack := zap.RedirectStdLog(log) + return func() { + undoGlobals() + undoHijack() } - return fields } diff --git a/ulog/log_benchmark_test.go b/ulog/log_benchmark_test.go deleted file mode 100644 index 5de8186c1..000000000 --- a/ulog/log_benchmark_test.go +++ /dev/null @@ -1,145 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package ulog - -import ( - "testing" - "time" - - "go.uber.org/fx/ulog/sentry" - - "github.com/uber-go/zap" -) - -func discardedLogger() zap.Logger { - return zap.New( - zap.NewJSONEncoder(), - zap.DiscardOutput, - ) -} - -func withDiscardedLogger(t *testing.B, f func(log Log)) { - log := Builder().SetLogger(discardedLogger()).Build() - f(log) -} - -func BenchmarkUlogWithoutFields(b *testing.B) { - withDiscardedLogger(b, func(log Log) { - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - log.Info("Ulog message") - } - }) - }) -} - -func BenchmarkUlogWithFieldsLogIFace(b *testing.B) { - withDiscardedLogger(b, func(log Log) { - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - log.Info("Ulog message", - "int", 123, - "int64", 123, - "float", 123.123, - "string", "four!", - "bool", true, - "time", time.Unix(0, 0), - "duration", time.Second, - "another string", "done!") - } - }) - }) -} - -func BenchmarkUlogWithFieldsBaseLoggerStruct(b *testing.B) { - withDiscardedLogger(b, func(log Log) { - base := log.(*baseLogger) - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - base.Info("Ulog message", - "int", 123, - "int64", 123, - "float", 123.123, - "string", "four!", - "bool", true, - "time", time.Unix(0, 0), - "duration", time.Second, - "another string", "done!") - } - }) - }) -} - -func BenchmarkUlogWithFieldsZapLogger(b *testing.B) { - withDiscardedLogger(b, func(log Log) { - zapLogger := log.Typed() - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - zapLogger.Info("Ulog message", - zap.Int("int", 123), - zap.Int64("int64", 123), - zap.Float64("float", 123.123), - zap.String("string", "four!"), - zap.Bool("bool", true), - zap.Time("time", time.Unix(0, 0)), - zap.Duration("duration", time.Second), - zap.String("another string", "done!")) - } - }) - }) -} - -func BenchmarkUlogLiteWithFields(b *testing.B) { - withDiscardedLogger(b, func(log Log) { - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - log.Info("Ulog message", "integer", 123, "string", "string") - } - }) - }) -} - -func BenchmarkUlogSentry(b *testing.B) { - h, _ := sentry.New("") - l := Builder().SetLogger(discardedLogger()).WithSentryHook(h).Build() - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - l.Error("Ulog message", "string", "string") - } - }) -} - -func BenchmarkUlogSentryWith(b *testing.B) { - h, _ := sentry.New("") - l := Builder().SetLogger(discardedLogger()).WithSentryHook(h).Build() - b.ResetTimer() - b.RunParallel(func(pb *testing.PB) { - for pb.Next() { - l.With("foo", "bar").Error("Ulog message", "string", "string") - } - }) -} diff --git a/ulog/log_test.go b/ulog/log_test.go deleted file mode 100644 index 5a10a616a..000000000 --- a/ulog/log_test.go +++ /dev/null @@ -1,234 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package ulog - -import ( - "context" - "fmt" - "net" - "path/filepath" - "strings" - "testing" - "time" - - "go.uber.org/fx/internal" - "go.uber.org/fx/testutils" - "go.uber.org/fx/ulog/sentry" - - "github.com/pkg/errors" - "github.com/stretchr/testify/assert" - "github.com/uber-go/zap" - "github.com/uber/jaeger-client-go" -) - -func TestZapSink(t *testing.T) { - l, s := TestingLogger() - l.Info("This is my message", "And this is", "My field") - assert.Equal(t, 1, len(s.Logs())) - - e := s.Logs()[0] - assert.Equal(t, "This is my message", e.Msg) - assert.Contains(t, e.Fields, zap.String("And this is", "My field")) -} - -func TestLogger_SetLogger(t *testing.T) { - SetLogger(logger()) - assert.NotNil(t, _std) - SetLogger(nil) - assert.NotNil(t, _std) -} - -func TestContext_LoggerAccess(t *testing.T) { - ctx := ContextWithLogger(context.Background(), nil) - assert.NotNil(t, ctx) - assert.NotNil(t, Logger(ctx)) - assert.NotNil(t, ctx.Value(internal.ContextLogger)) -} - -func TestContextWithTraceLogger(t *testing.T) { - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - // Create in-memory logger and jaeger tracer - loggerWithZap := Builder().SetLogger(zapLogger).Build() - tracer, closer := jaeger.NewTracer( - "serviceName", jaeger.NewConstSampler(true), jaeger.NewNullReporter(), - ) - defer closer.Close() - span := tracer.StartSpan("opName") - ctx := context.WithValue(context.Background(), internal.ContextLogger, loggerWithZap) - ctx = ContextWithTraceLogger(ctx, span) - Logger(ctx).Info("Testing context aware logger") - assert.True(t, len(buf.Lines()) > 0) - for _, line := range buf.Lines() { - assert.Contains(t, line, "traceID") - assert.Contains(t, line, "spanID") - } - }) -} - -func TestSimpleLogger(t *testing.T) { - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - log := Builder().SetLogger(zapLogger).Build() - - log.Debug("debug message", "a", "b") - log.Info("info message", "c", "d") - log.Warn("warn message", "e", "f") - log.Error("error message", "g", "h") - assert.Equal(t, []string{ - `{"level":"debug","msg":"debug message","a":"b"}`, - `{"level":"info","msg":"info message","c":"d"}`, - `{"level":"warn","msg":"warn message","e":"f"}`, - `{"level":"error","msg":"error message","g":"h"}`, - }, buf.Lines(), "Incorrect output from logger") - }) -} - -func TestLoggerWithInitFields(t *testing.T) { - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - log := Builder().SetLogger(zapLogger).Build().With("method", "test_method") - log.Debug("debug message", "a", "b") - log.Info("info message", "c", "d") - log.Warn("warn message", "e", "f") - log.Error("error message", "g", "h") - assert.Equal(t, []string{ - `{"level":"debug","msg":"debug message","method":"test_method","a":"b"}`, - `{"level":"info","msg":"info message","method":"test_method","c":"d"}`, - `{"level":"warn","msg":"warn message","method":"test_method","e":"f"}`, - `{"level":"error","msg":"error message","method":"test_method","g":"h"}`, - }, buf.Lines(), "Incorrect output from logger") - }) -} - -func TestLoggerWithInvalidFields(t *testing.T) { - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - log := Builder().SetLogger(zapLogger).Build() - log.Info("info message", "c") - log.Info("info message", "c", "d", "e") - log.DPanic("debug message") - assert.Equal(t, []string{ - `{"level":"info","msg":"info message","error":"expected even number of arguments"}`, - `{"level":"info","msg":"info message","error":"expected even number of arguments"}`, - `{"level":"dpanic","msg":"debug message"}`, - }, buf.Lines(), "Incorrect output from logger") - }) -} - -func TestFatalsAndPanics(t *testing.T) { - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - log := Builder().SetLogger(zapLogger).Build() - assert.Panics(t, func() { log.Panic("panic level") }, "Expected to panic") - assert.Equal(t, `{"level":"panic","msg":"panic level"}`, buf.Stripped(), "Unexpected output") - }) - -} - -type marshalObject struct { - Data string `json:"data"` -} - -func (m *marshalObject) MarshalLog(kv zap.KeyValue) error { - kv.AddString("Data", m.Data) - return nil -} - -func TestFieldConversion(t *testing.T) { - log := New() - base := log.(*baseLogger) - - assert.Equal(t, zap.Bool("a", true), base.fieldsConversion("a", true)[0]) - assert.Equal(t, zap.Float64("a", 5.5), base.fieldsConversion("a", 5.5)[0]) - assert.Equal(t, zap.Int("a", 10), base.fieldsConversion("a", 10)[0]) - assert.Equal(t, zap.Int64("a", int64(10)), base.fieldsConversion("a", int64(10))[0]) - assert.Equal(t, zap.Uint("a", uint(10)), base.fieldsConversion("a", uint(10))[0]) - assert.Equal(t, zap.Uintptr("a", uintptr(0xa)), base.fieldsConversion("a", uintptr(0xa))[0]) - assert.Equal(t, zap.Uint64("a", uint64(10)), base.fieldsConversion("a", uint64(10))[0]) - assert.Equal(t, zap.String("a", "xyz"), base.fieldsConversion("a", "xyz")[0]) - assert.Equal(t, zap.Time("a", time.Unix(0, 0)), base.fieldsConversion("a", time.Unix(0, 0))[0]) - assert.Equal(t, zap.Duration("a", time.Microsecond), base.fieldsConversion("a", time.Microsecond)[0]) - dt := &marshalObject{Data: "value"} - assert.Equal(t, zap.Marshaler("a", &marshalObject{"value"}), base.fieldsConversion("a", dt)[0]) - ip := net.ParseIP("1.2.3.4") - assert.Equal(t, zap.Stringer("ip", ip), base.fieldsConversion("ip", ip)[0]) - assert.Equal(t, zap.Object("a", []int{1, 2}), base.fieldsConversion("a", []int{1, 2})[0]) - err := fmt.Errorf("test error") - assert.Equal(t, zap.Error(err), base.fieldsConversion("error", err)[0]) -} - -func TestTyped(t *testing.T) { - log := New() - assert.NotNil(t, log.Typed()) -} - -func TestLogger(t *testing.T) { - log := logger() - assert.NotNil(t, log.Typed()) -} - -func TestSentryHook(t *testing.T) { - c := &sentry.MemCapturer{} - h, err := sentry.New("") - assert.NoError(t, err, "Need to be able to create a sentry hook") - h.Capturer = c - - l := Builder().WithSentryHook(h).Build() - - l.Error("you work, yea?", "key", 123) - l.Info("this should not be sent, right?", "key", "val") - - assert.Equal(t, 1, len(c.Packets)) - p := c.Packets[0] - assert.Equal(t, "you work, yea?", p.Message) -} - -func TestSentryHookDoesNotMutatePrevious(t *testing.T) { - h, err := sentry.New("") - defer h.Close() - assert.NoError(t, err) - - l := Builder().WithSentryHook(h).Build().(*baseLogger) - assert.Equal(t, make(map[string]interface{}), l.sh.Fields()) - - l2 := l.With("key", "value").(*baseLogger) - assert.Equal(t, map[string]interface{}{}, l.sh.Fields()) - assert.NotNil(t, l2.sh) - assert.NotNil(t, l2.sh.Fields()) - assert.Equal(t, map[string]interface{}{"key": "value"}, l2.sh.Fields()) -} - -func TestStackTraceLogger(t *testing.T) { - t.Parallel() - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - log := Builder().SetLogger(zapLogger).Build() - err1 := errors.New("for sure") - err2 := errors.Wrap(err1, "it's a trap") - log.Error("error message", "error", err2) - line := buf.Lines()[0] - assert.Contains(t, line, "TestStackTraceLogger.func1", "Missing first function") - assert.Contains(t, line, filepath.Join("ulog", "log_test.go"), "Missing source") - assert.Regexp(t, `log_test.go:\d+`, line, "Missing line numbers") - - assert.Contains(t, line, "testutils.WithInMemoryLogger", "Missing second function") - assert.Contains(t, line, filepath.Join("testutils", "in_memory_log.go"), "Missing source") - assert.True(t, strings.Index(line, "log_test.go") < strings.Index(line, "in_memory_log.go")) - - assert.Contains(t, line, "it's a trap: for sure") - assert.Equal(t, 1, len(buf.Lines())) - }) -} diff --git a/ulog/metrics.go b/ulog/metrics.go new file mode 100644 index 000000000..8726ffedc --- /dev/null +++ b/ulog/metrics.go @@ -0,0 +1,66 @@ +// Copyright (c) 2017 Uber Technologies, Inc. +// +// Permission is hereby granted, free of charge, to any person obtaining a copy +// of this software and associated documentation files (the "Software"), to deal +// in the Software without restriction, including without limitation the rights +// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +// copies of the Software, and to permit persons to whom the Software is +// furnished to do so, subject to the following conditions: +// +// The above copyright notice and this permission notice shall be included in +// all copies or substantial portions of the Software. +// +// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +// THE SOFTWARE. + +package ulog + +import ( + "fmt" + + "github.com/uber-go/tally" + "go.uber.org/zap/zapcore" +) + +// Metrics returns a function that counts the number of logs emitted by level. +// +// To register it with a zap.Logger, use zap.Hooks. +func Metrics(s tally.Scope) func(zapcore.Entry) error { + // Avoid allocating strings and maps in the request path. + debugC := s.Tagged(map[string]string{"level": "debug"}).Counter("logs") + infoC := s.Tagged(map[string]string{"level": "info"}).Counter("logs") + warnC := s.Tagged(map[string]string{"level": "warn"}).Counter("logs") + errorC := s.Tagged(map[string]string{"level": "error"}).Counter("logs") + dpanicC := s.Tagged(map[string]string{"level": "dpanic"}).Counter("logs") + panicC := s.Tagged(map[string]string{"level": "panic"}).Counter("logs") + fatalC := s.Tagged(map[string]string{"level": "fatal"}).Counter("logs") + unknownC := s.Tagged(map[string]string{"level": "unknown"}).Counter("logs") + + return func(e zapcore.Entry) error { + switch e.Level { + case zapcore.DebugLevel: + debugC.Inc(1) + case zapcore.InfoLevel: + infoC.Inc(1) + case zapcore.WarnLevel: + warnC.Inc(1) + case zapcore.ErrorLevel: + errorC.Inc(1) + case zapcore.DPanicLevel: + dpanicC.Inc(1) + case zapcore.PanicLevel: + panicC.Inc(1) + case zapcore.FatalLevel: + fatalC.Inc(1) + default: + unknownC.Inc(1) + return fmt.Errorf("unknown log level: %s", e.Level) + } + return nil + } +} diff --git a/ulog/metrics/metrics.go b/ulog/metrics/metrics.go deleted file mode 100644 index 93a07bd3b..000000000 --- a/ulog/metrics/metrics.go +++ /dev/null @@ -1,48 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package metrics - -import ( - "errors" - - "github.com/uber-go/tally" - "github.com/uber-go/zap" -) - -var ( - errHookNilEntry = errors.New("can't call a hook on a nil *Entry") -) - -// Hook counts the number of logging messages per level -func Hook(s tally.Scope) zap.Hook { - return zap.Hook(func(e *zap.Entry) error { - if e == nil { - return errHookNilEntry - } - - // TODO: `.Counter()` method is not necessary here and can be optimized - // There is a finite number of counters here: one for each logging level. - // If performance per log needs to be optimized this is one of the places - // to look. Though it won't save much (estimated ~10ns/call) - s.Counter(e.Level.String()).Inc(1) - return nil - }) -} diff --git a/ulog/metrics/metrics_test.go b/ulog/metrics_test.go similarity index 55% rename from ulog/metrics/metrics_test.go rename to ulog/metrics_test.go index fcc9a8c1d..25e808af5 100644 --- a/ulog/metrics/metrics_test.go +++ b/ulog/metrics_test.go @@ -18,7 +18,7 @@ // OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN // THE SOFTWARE. -package metrics +package ulog import ( "testing" @@ -26,31 +26,34 @@ import ( "go.uber.org/fx/testutils/metrics" "github.com/stretchr/testify/assert" - "github.com/uber-go/tally" - "github.com/uber-go/zap" + "github.com/stretchr/testify/require" + "go.uber.org/zap" ) -func hookedLogger() (zap.Logger, *metrics.TestStatsReporter) { - s, r := metrics.NewTestScope() - return zap.New(zap.NewJSONEncoder(), Hook(s)), r +func TestMetricsHook(t *testing.T) { + cfg := zap.NewDevelopmentConfig() + cfg.OutputPaths = nil + cfg.ErrorOutputPaths = nil + log, err := cfg.Build() + require.NoError(t, err, "Failed to construct a logger.") + + scope, reporter := metrics.NewTestScope() + log = log.WithOptions(zap.Hooks(Metrics(scope))) + + reporter.CountersWG.Add(6) + log.Debug("debug") + log.Info("info") + log.Warn("warn") + log.Error("error") + assert.Panics(t, func() { log.DPanic("dpanic") }, "Expected Logger.DPanic to panic in development.") + assert.Panics(t, func() { log.Panic("panic") }, "Expected Logger.Panic to panic.") + reporter.CountersWG.Wait() + + // FX's metrics spy doesn't support tags, so granular assertions aren't + // possible. + assert.Equal(t, 1, len(reporter.Counters)) + assert.Equal(t, int64(6), reporter.Counters["logs"], "Expected counts to have name:logs.") } -func TestSomething(t *testing.T) { - l, r := hookedLogger() - - r.CountersWG.Add(2) - l.Info("Info message.") - - l.Error("Error message 1.") - l.Error("Error message 2.") - r.CountersWG.Wait() - - assert.Equal(t, 2, len(r.Counters)) - assert.Equal(t, int64(1), r.Counters["info"]) - assert.Equal(t, int64(2), r.Counters["error"]) -} - -func TestNilEntryHook(t *testing.T) { - h := Hook(tally.NoopScope) - assert.Error(t, errHookNilEntry, h(nil)) +func assertConfigEqual(t testing.TB, merged, expected zap.Config) { } diff --git a/ulog/nop_logger.go b/ulog/nop_logger.go deleted file mode 100644 index 83f56424a..000000000 --- a/ulog/nop_logger.go +++ /dev/null @@ -1,32 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package ulog - -import "github.com/uber-go/zap" - -func nopLogger() Log { - return &baseLogger{ - log: zap.New(zap.NullEncoder()), - } -} - -// NopLogger should be used in tests if you wish to discard the output -var NopLogger = nopLogger() diff --git a/ulog/sentry/capturer.go b/ulog/sentry/capturer.go deleted file mode 100644 index c64942e66..000000000 --- a/ulog/sentry/capturer.go +++ /dev/null @@ -1,56 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package sentry - -import raven "github.com/getsentry/raven-go" - -// Capturer knows what to do with a Sentry packet. -type Capturer interface { - Capture(p *raven.Packet) - Close() -} - -// MemCapturer foo -type MemCapturer struct { - Packets []*raven.Packet -} - -// Close is a nop -func (m *MemCapturer) Close() {} - -// Capture remembers the would-be-sent packet in the packets array -func (m *MemCapturer) Capture(p *raven.Packet) { - m.Packets = append(m.Packets, p) -} - -type nonBlockingCapturer struct { - *raven.Client -} - -func (nb *nonBlockingCapturer) Close() { - nb.Client.Close() -} - -// Capture will fire off a packet without checking the error channel. -func (nb *nonBlockingCapturer) Capture(p *raven.Packet) { - // TODO (madhu/glib): Capture returns an error channel. Should we handle it? - nb.Client.Capture(p, nil) -} diff --git a/ulog/sentry/sentry.go b/ulog/sentry/sentry.go deleted file mode 100644 index 0f784c7c9..000000000 --- a/ulog/sentry/sentry.go +++ /dev/null @@ -1,264 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package sentry - -import ( - "time" - - "github.com/uber-go/zap" - - raven "github.com/getsentry/raven-go" - "github.com/pkg/errors" -) - -const ( - _platform = "go" - _traceContextLines = 3 - _traceSkipFrames = 2 -) - -var _zapToRavenMap = map[zap.Level]raven.Severity{ - zap.DebugLevel: raven.INFO, - zap.InfoLevel: raven.INFO, - zap.WarnLevel: raven.WARNING, - zap.ErrorLevel: raven.ERROR, - zap.PanicLevel: raven.FATAL, - zap.FatalLevel: raven.FATAL, -} - -// Configuration provides sentry DSN and other optional parameters for logging -type Configuration struct { - DSN string - MinLevel *string `yaml:"min_level"` - Fields map[string]interface{} - Trace *struct { - Disabled bool - SkipFrames *int `yaml:"skip_frames"` - ContextLines *int `yaml:"context_lines"` - } -} - -// Hook wraps the default raven-go client for some out-of-box awesomeness -// and tight integration with ulog -type Hook struct { - Capturer - - // This is pretty expensive as far as allocations go. - // No need to copy maps around, especially if they are not going to be used - // TODO(glib): make this better. We should be able to have an efficient - // marshaler of this data that won't have us copy maps around - fields map[string]interface{} - - // Minimum level threshold for sending a Sentry event - minLevel zap.Level - - // Controls if stack trace should be automatically generated, and how many frames to skip - traceEnabled bool - traceSkipFrames int - traceContextLines int - traceAppPrefixes []string -} - -// Option pattern for Hook creation. -type Option func(sh *Hook) - -// New Sentry Hook. -func New(dsn string, options ...Option) (*Hook, error) { - sh := &Hook{ - minLevel: zap.ErrorLevel, - traceEnabled: true, - traceSkipFrames: _traceSkipFrames, - traceContextLines: _traceContextLines, - fields: make(map[string]interface{}), - } - - for _, option := range options { - option(sh) - } - - client, err := raven.New(dsn) - if err != nil { - return nil, errors.Wrap(err, "failed to create sentry client") - } - - sh.Capturer = &nonBlockingCapturer{Client: client} - - return sh, nil -} - -// Configure returns a new Sentry Hook based on SentryConfiguration. -func Configure(c Configuration) (*Hook, error) { - o := make([]Option, 0, 5) - - if c.MinLevel != nil { - l := zap.ErrorLevel - if err := l.UnmarshalText([]byte(*c.MinLevel)); err != nil { - return nil, err - } - - o = append(o, MinLevel(l)) - } - - t := c.Trace - if t == nil { - return New(c.DSN, o...) - } - - if t.Disabled { - o = append(o, DisableTraces()) - } - - if t.SkipFrames != nil { - o = append(o, TraceSkipFrames(*t.SkipFrames)) - } - - if t.ContextLines != nil { - o = append(o, TraceContextLines(*t.ContextLines)) - } - - if len(c.Fields) != 0 { - o = append(o, Fields(c.Fields)) - } - - return New(c.DSN, o...) -} - -// Fields returns the currently accumulated context fields -func (sh *Hook) Fields() map[string]interface{} { - return sh.fields -} - -// MinLevel provides a minimum level threshold. -// All log messages above the set level are sent to Sentry. -func MinLevel(level zap.Level) Option { - return func(sh *Hook) { - sh.minLevel = level - } -} - -// DisableTraces allows to turn off Stacktrace for sentry packets. -func DisableTraces() Option { - return func(sh *Hook) { - sh.traceEnabled = false - } -} - -// TraceContextLines sets how many lines of code (in on direction) are sent -// with the Sentry packet. -func TraceContextLines(lines int) Option { - return func(sh *Hook) { - sh.traceContextLines = lines - } -} - -// TraceAppPrefixes sets a list of go import prefixes that are considered "in app". -func TraceAppPrefixes(prefixes []string) Option { - return func(sh *Hook) { - sh.traceAppPrefixes = prefixes - } -} - -// TraceSkipFrames sets how many stacktrace frames to skip when sending a -// sentry packet. This is very useful when helper functions are involved. -func TraceSkipFrames(skip int) Option { - return func(sh *Hook) { - sh.traceSkipFrames = skip - } -} - -// Fields stores additional information for each Sentry event. -func Fields(fields map[string]interface{}) Option { - return func(sh *Hook) { - // TODO(glib): yuck! - f := make(map[string]interface{}) - for k, v := range fields { - f[k] = v - } - sh.fields = f - } -} - -// AppendFields expands the currently stored context of the hook -func (sh *Hook) AppendFields(keyvals ...interface{}) { - for idx := 0; idx < len(keyvals); idx += 2 { - if key, ok := keyvals[idx].(string); ok { - val := keyvals[idx+1] - sh.fields[key] = val - } - } -} - -// Copy returns... well, what do you think it returns? -func (sh *Hook) Copy() *Hook { - // another map copy... - f := make(map[string]interface{}, len(sh.fields)) - for k, v := range sh.fields { - f[k] = v - } - - return &Hook{ - Capturer: sh.Capturer, - fields: f, - minLevel: sh.minLevel, - traceEnabled: sh.traceEnabled, - traceSkipFrames: sh.traceSkipFrames, - traceContextLines: sh.traceContextLines, - traceAppPrefixes: sh.traceAppPrefixes, - } -} - -// CheckAndFire check to see if logging level is above Sentry threshold -// and if so, fires off a Sentry packet -func (sh *Hook) CheckAndFire(lvl zap.Level, msg string, keyvals ...interface{}) { - if lvl < sh.minLevel { - return - } - - // append all the fields from the current log message to the stored ones - f := make(map[string]interface{}, len(sh.fields)+len(keyvals)/2) - for k, v := range sh.fields { - f[k] = v - } - - for idx := 0; idx < len(keyvals); idx += 2 { - if key, ok := keyvals[idx].(string); ok { - val := keyvals[idx+1] - f[key] = val - } - } - - packet := &raven.Packet{ - Message: msg, - Timestamp: raven.Timestamp(time.Now()), - Level: _zapToRavenMap[lvl], - Platform: _platform, - Extra: f, - } - - if sh.traceEnabled { - trace := raven.NewStacktrace(sh.traceSkipFrames, sh.traceContextLines, sh.traceAppPrefixes) - if trace != nil { - packet.Interfaces = append(packet.Interfaces, trace) - } - } - - sh.Capture(packet) -} diff --git a/ulog/sentry/sentry_test.go b/ulog/sentry/sentry_test.go deleted file mode 100644 index 0975dfa3a..000000000 --- a/ulog/sentry/sentry_test.go +++ /dev/null @@ -1,294 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package sentry - -import ( - "compress/zlib" - "encoding/base64" - "encoding/json" - "fmt" - "io" - "net/http" - "net/http/httptest" - "strings" - "testing" - - raven "github.com/getsentry/raven-go" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - "github.com/uber-go/zap" -) - -type fakeClient raven.Client - -func TestBadDSN(t *testing.T) { - t.Parallel() - _, err := New("123http://whoops") - assert.Error(t, err) - assert.Contains(t, err.Error(), "failed to create sentry client") -} - -func TestEmptyDSN(t *testing.T) { - t.Parallel() - l, err := New("") - assert.NoError(t, err) - assert.NotNil(t, l) -} - -func TestWithLevels(t *testing.T) { - t.Parallel() - l, err := New("", MinLevel(zap.InfoLevel)) - assert.NoError(t, err) - assert.NotNil(t, l) - assert.Equal(t, l.minLevel, zap.InfoLevel) -} - -func TestExtra(t *testing.T) { - t.Parallel() - f := map[string]interface{}{ - "requestID": "123h2eor2039423", - "someInt": 123, - "arrayOfManyThings": []int{1, 2, 3}, - } - s, err := New("", Fields(f)) - s.CheckAndFire(zap.ErrorLevel, "error log", "foo", "bar") - assert.NoError(t, err) - assert.Equal(t, f, s.Fields()) -} - -func TestWith(t *testing.T) { - t.Parallel() - sh, err := New("", Fields(map[string]interface{}{ - "someInt": 123, - })) - assert.NoError(t, err) - expected := map[string]interface{}{"someInt": 123, "someFloat": float64(10)} - sh.AppendFields("someFloat", float64(10)) - assert.Equal(t, expected, sh.Fields()) -} - -func TestCopy(t *testing.T) { - t.Parallel() - sh, err := New("", Fields(map[string]interface{}{ - "someInt": 123, - })) - assert.NoError(t, err) - shCopy := sh.Copy() - for k, v := range sh.Fields() { - assert.Equal(t, v, shCopy.Fields()[k]) - } - assert.Equal(t, sh.Capturer, shCopy.Capturer) - assert.Equal(t, sh.minLevel, shCopy.minLevel) - assert.Equal(t, sh.traceEnabled, shCopy.traceEnabled) - assert.Equal(t, sh.traceSkipFrames, shCopy.traceSkipFrames) - assert.Equal(t, sh.traceContextLines, shCopy.traceContextLines) - assert.Equal(t, sh.traceAppPrefixes, shCopy.traceAppPrefixes) -} - -func TestWithTraceDisabled(t *testing.T) { - t.Parallel() - _, ps := capturePackets(func(sh *Hook) { - sh.CheckAndFire(zap.ErrorLevel, "some error message", "foo", "bar") - sh.CheckAndFire(zap.ErrorLevel, "another error message") - }, DisableTraces()) - - for _, p := range ps { - assert.Empty(t, p.Interfaces) - } -} - -func TestTraceCfg(t *testing.T) { - t.Parallel() - l, err := New( - "", - TraceSkipFrames(1), - TraceContextLines(7), - TraceAppPrefixes([]string{"github.com/uber-go/unicorns"}), - ) - assert.NoError(t, err) - assert.Equal(t, l.traceSkipFrames, 1) - assert.Equal(t, l.traceContextLines, 7) - assert.Equal(t, l.traceAppPrefixes, []string{"github.com/uber-go/unicorns"}) -} - -func TestLevels(t *testing.T) { - t.Parallel() - _, ps := capturePackets(func(sh *Hook) { - sh.CheckAndFire(zap.DebugLevel, "debug level log") - sh.CheckAndFire(zap.InfoLevel, "info level log") - sh.CheckAndFire(zap.WarnLevel, "warn level log") - sh.CheckAndFire(zap.ErrorLevel, "error level log") - }, MinLevel(zap.WarnLevel)) - - assert.Equal(t, len(ps), 2, "only Warn and Error packets should be collected") -} - -func TestErrorCapture(t *testing.T) { - t.Parallel() - _, p := capturePacket(func(sh *Hook) { - sh.CheckAndFire(zap.ErrorLevel, "some error message", "foo", "bar") - }) - - assert.Equal(t, p.Message, "some error message") - assert.Equal(t, p.Extra, map[string]interface{}{"foo": "bar"}) - - trace := p.Interfaces[0].(*raven.Stacktrace) - assert.NotNil(t, trace.Frames) -} - -func TestPacketSending(t *testing.T) { - t.Parallel() - withTestSentry(func(dsn string, ch <-chan *raven.Packet) { - sh, err := New(dsn) - defer sh.Close() - assert.NoError(t, err) - - sh.CheckAndFire(zap.ErrorLevel, "my error message", "mykey1", "myvalue1") - sh.CheckAndFire(zap.ErrorLevel, "my error message", "mykey1", "myvalue1") - p := <-ch - - assert.Equal(t, p.Message, "my error message") - assert.Equal(t, map[string]interface{}{"mykey1": "myvalue1"}, p.Extra) - }) -} - -func TestConfigure(t *testing.T) { - t.Parallel() - one := 1 - two := 2 - debug := zap.DebugLevel.String() - str := "random string" - trace := struct { - Disabled bool - SkipFrames *int `yaml:"skip_frames"` - ContextLines *int `yaml:"context_lines"` - }{ - Disabled: true, - SkipFrames: &one, - ContextLines: &two, - } - - testCases := []struct { - name string - conf Configuration - res *Hook - isErr bool - }{ - {"Empty", - Configuration{}, - &Hook{ - traceEnabled: true, - minLevel: zap.ErrorLevel, - traceContextLines: _traceContextLines, - traceSkipFrames: _traceSkipFrames, - fields: map[string]interface{}{}, - }, false}, - {"SomeValues", - Configuration{ - MinLevel: &debug, - Trace: &trace, - Fields: map[string]interface{}{"mickey": "mouse"}, - }, - &Hook{ - minLevel: zap.DebugLevel, - traceEnabled: false, - traceSkipFrames: one, - traceContextLines: two, - fields: map[string]interface{}{"mickey": "mouse"}, - }, false}, - {"ParseError", Configuration{MinLevel: &str}, nil, true}, - } - - for _, tc := range testCases { - t.Run(tc.name, func(t *testing.T) { - conf, err := Configure(tc.conf) - if tc.isErr { - assert.Error(t, err) - return - } - - require.NoError(t, err) - r := tc.res - assert.Equal(t, r.traceEnabled, conf.traceEnabled) - assert.Equal(t, r.minLevel, conf.minLevel) - assert.Equal(t, r.traceContextLines, conf.traceContextLines) - assert.Equal(t, r.traceSkipFrames, conf.traceSkipFrames) - assert.Equal(t, r.fields, conf.fields) - }) - } -} - -func capturePacket(f func(sh *Hook), options ...Option) (*Hook, *raven.Packet) { - l, ps := capturePackets(f, options...) - if len(ps) != 1 { - panic("Expected to capture a packet, but didn't") - } - return l, ps[0] -} - -func capturePackets(f func(sh *Hook), options ...Option) (*Hook, []*raven.Packet) { - sh, err := New("", options...) - if err != nil { - panic("Failed to create the logger") - } - - c := &MemCapturer{} - sh.Capturer = c - - f(sh) - - return sh, c.Packets -} - -func withTestSentry(f func(string, <-chan *raven.Packet)) { - ch := make(chan *raven.Packet) - h := http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) { - defer req.Body.Close() - - contentType := req.Header.Get("Content-Type") - var bodyReader io.Reader = req.Body - // underlying client will compress and encode payload above certain size - if contentType == "application/octet-stream" { - bodyReader = base64.NewDecoder(base64.StdEncoding, bodyReader) - bodyReader, _ = zlib.NewReader(bodyReader) - } - - d := json.NewDecoder(bodyReader) - p := &raven.Packet{} - err := d.Decode(p) - if err != nil { - ch <- nil - panic(err.Error()) - } - ch <- p - }) - s := httptest.NewServer(h) - defer s.Close() - - fragments := strings.SplitN(s.URL, "://", 2) - dsn := fmt.Sprintf( - "%s://public:secret@%s/sentry/project-id", - fragments[0], - fragments[1], - ) - - f(dsn, ch) -} From 10fcdddc7f1cc964a5adf96c3a3090653756bf03 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Fri, 17 Feb 2017 23:39:02 -0800 Subject: [PATCH 03/13] Remove internal context key There's no need for this; we don't need to put loggers into the context in order to add tracing information to the context. --- internal/context.go | 26 -------------------------- 1 file changed, 26 deletions(-) delete mode 100644 internal/context.go diff --git a/internal/context.go b/internal/context.go deleted file mode 100644 index 83b797185..000000000 --- a/internal/context.go +++ /dev/null @@ -1,26 +0,0 @@ -// Copyright (c) 2017 Uber Technologies, Inc. -// -// Permission is hereby granted, free of charge, to any person obtaining a copy -// of this software and associated documentation files (the "Software"), to deal -// in the Software without restriction, including without limitation the rights -// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell -// copies of the Software, and to permit persons to whom the Software is -// furnished to do so, subject to the following conditions: -// -// The above copyright notice and this permission notice shall be included in -// all copies or substantial portions of the Software. -// -// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR -// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, -// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE -// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER -// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, -// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN -// THE SOFTWARE. - -package internal - -type contextKey int - -// ContextLogger is the context based logger -const ContextLogger contextKey = iota From 2c20ce633c41fe59b66f4bedd788da64c1242574 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Wed, 22 Feb 2017 23:47:25 -0800 Subject: [PATCH 04/13] Migrate testutils to zap RC --- testutils/in_memory_log.go | 60 +++++++++++++++++-------------------- testutils/tracing/tracer.go | 4 +-- 2 files changed, 29 insertions(+), 35 deletions(-) diff --git a/testutils/in_memory_log.go b/testutils/in_memory_log.go index e21eecc26..56c3638a1 100644 --- a/testutils/in_memory_log.go +++ b/testutils/in_memory_log.go @@ -21,41 +21,35 @@ package testutils import ( - "bytes" - "strings" + "io/ioutil" "testing" - "github.com/uber-go/zap" + "go.uber.org/zap" + "go.uber.org/zap/testutils" + "go.uber.org/zap/zapcore" ) -// TestBuffer is a buffer used to test the zap logger -type TestBuffer struct { - bytes.Buffer -} - -// Sync is a nop to conform to zap.WriteSyncer interface -func (b *TestBuffer) Sync() error { - return nil -} - -// Lines returns buffer as array of strings -func (b *TestBuffer) Lines() []string { - output := strings.Split(b.String(), "\n") - return output[:len(output)-1] -} - -// Stripped returns buffer as a string without the newline -func (b *TestBuffer) Stripped() string { - return strings.TrimRight(b.String(), "\n") -} - -// WithInMemoryLogger creates an in-memory zap logger that can be used in tests -func WithInMemoryLogger(t *testing.T, opts []zap.Option, f func(zap.Logger, *TestBuffer)) { - sink := &TestBuffer{} - errSink := &TestBuffer{} - - allOpts := make([]zap.Option, 0, 3+len(opts)) - allOpts = append(allOpts, zap.DebugLevel, zap.Output(sink), zap.ErrorOutput(errSink)) - allOpts = append(allOpts, opts...) - f(zap.New(zap.NewJSONEncoder(zap.NoTime()), allOpts...), sink) +// WithInMemoryLogger creates an in-memory *zap.Logger that can be used in +// tests. +func WithInMemoryLogger(t *testing.T, opts []zap.Option, f func(*zap.Logger, *testutils.Buffer)) { + sink := &testutils.Buffer{} + errSink := zapcore.AddSync(ioutil.Discard) + + allOpts := make([]zap.Option, 0, len(opts)+1) + allOpts = append(allOpts, zap.ErrorOutput(errSink)) + for _, o := range opts { + allOpts = append(allOpts, o) + } + encoderCfg := zapcore.EncoderConfig{ + LevelKey: "level", + MessageKey: "msg", + EncodeLevel: zapcore.LowercaseLevelEncoder, + } + log := zap.New(zapcore.NewCore( + zapcore.NewJSONEncoder(encoderCfg), + sink, + zapcore.DebugLevel, + )).WithOptions(allOpts...) + + f(log, sink) } diff --git a/testutils/tracing/tracer.go b/testutils/tracing/tracer.go index 860216e15..3bbf4ad5b 100644 --- a/testutils/tracing/tracer.go +++ b/testutils/tracing/tracer.go @@ -25,14 +25,14 @@ import ( "go.uber.org/fx/metrics" "go.uber.org/fx/tracing" - "go.uber.org/fx/ulog" "github.com/opentracing/opentracing-go" "github.com/stretchr/testify/require" + "go.uber.org/zap" ) // WithSpan is used for generating a span to be used in testing -func WithSpan(t *testing.T, log ulog.Log, f func(opentracing.Span)) { +func WithSpan(t *testing.T, log *zap.Logger, f func(opentracing.Span)) { tracer, closer, err := tracing.CreateTracer( nil, "serviceName", log, metrics.NopCachedStatsReporter, ) From 5dc31a66d7ebd9aa3b38139e3a1ad3f2e24f3654 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Wed, 22 Feb 2017 23:32:18 -0800 Subject: [PATCH 05/13] Migrate auth to zap RC --- auth/uauth_test.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/auth/uauth_test.go b/auth/uauth_test.go index 3687d55dd..fbc7c73aa 100644 --- a/auth/uauth_test.go +++ b/auth/uauth_test.go @@ -25,11 +25,11 @@ import ( "testing" "go.uber.org/fx/config" - "go.uber.org/fx/ulog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/uber-go/tally" + "go.uber.org/zap" ) func withAuthClientSetup(t *testing.T, registerFunc RegisterFunc, info CreateAuthInfo, fn func()) { @@ -86,8 +86,8 @@ func (fakeAuthInfo) Config() config.Provider { return nil } -func (fakeAuthInfo) Logger() ulog.Log { - return ulog.NopLogger +func (fakeAuthInfo) Logger() *zap.Logger { + return zap.NewNop() } func (fakeAuthInfo) Metrics() tally.Scope { From 83cbdf29ce9b719af475a26bd02666e55053dad2 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Wed, 22 Feb 2017 23:47:41 -0800 Subject: [PATCH 06/13] Migrate tracing to zap RC --- tracing/tracer.go | 25 +++++++------------------ tracing/tracer_test.go | 26 ++++++++++---------------- 2 files changed, 17 insertions(+), 34 deletions(-) diff --git a/tracing/tracer.go b/tracing/tracer.go index 6ef1f74b4..888cf36a7 100644 --- a/tracing/tracer.go +++ b/tracing/tracer.go @@ -21,22 +21,20 @@ package tracing import ( - "fmt" "io" "time" - "go.uber.org/fx/ulog" - "github.com/opentracing/opentracing-go" "github.com/uber-go/tally" "github.com/uber/jaeger-client-go/config" + "go.uber.org/zap" ) // InitGlobalTracer instantiates a new global tracer func InitGlobalTracer( cfg *config.Configuration, serviceName string, - logger ulog.Log, + logger *zap.Logger, statsReporter tally.CachedStatsReporter, ) (opentracing.Tracer, io.Closer, error) { tracer, closer, err := CreateTracer(cfg, serviceName, logger, statsReporter) @@ -50,7 +48,7 @@ func InitGlobalTracer( func CreateTracer( cfg *config.Configuration, serviceName string, - logger ulog.Log, + logger *zap.Logger, statsReporter tally.CachedStatsReporter, ) (opentracing.Tracer, io.Closer, error) { var reporter *jaegerReporter @@ -64,32 +62,23 @@ func CreateTracer( return cfg.New(serviceName, reporter) } -func loadAppConfig(cfg *config.Configuration, logger ulog.Log) *config.Configuration { +func loadAppConfig(cfg *config.Configuration, logger *zap.Logger) *config.Configuration { if cfg == nil { cfg = &config.Configuration{} } if cfg.Logger == nil { - jaegerlogger := &jaegerLogger{ - log: logger, - } - cfg.Logger = jaegerlogger + cfg.Logger = &jaegerLogger{logger.Sugar()} } return cfg } type jaegerLogger struct { - log ulog.Log + *zap.SugaredLogger } // Error logs an error message func (jl *jaegerLogger) Error(msg string) { - jl.log.Error(msg) -} - -// Infof logs an info message with args as key value pairs -func (jl *jaegerLogger) Infof(msg string, args ...interface{}) { - logMsg := fmt.Sprintf(msg, args...) - jl.log.Info(logMsg) + jl.SugaredLogger.Error(msg) } type jaegerReporter struct { diff --git a/tracing/tracer_test.go b/tracing/tracer_test.go index 6e01996e6..4ff4d52f9 100644 --- a/tracing/tracer_test.go +++ b/tracing/tracer_test.go @@ -21,17 +21,16 @@ package tracing import ( - "context" "testing" "go.uber.org/fx/metrics" "go.uber.org/fx/testutils" - "go.uber.org/fx/ulog" "github.com/stretchr/testify/assert" - "github.com/uber-go/zap" jaeger "github.com/uber/jaeger-client-go" "github.com/uber/jaeger-client-go/config" + "go.uber.org/zap" + ztest "go.uber.org/zap/testutils" ) var ( @@ -42,13 +41,9 @@ var ( _jaegerConfigWithLogger = &config.Configuration{Logger: jaeger.NullLogger} ) -func getLogger() ulog.Log { - return ulog.Logger(context.Background()) -} - func TestInitGlobalTracer_Simple(t *testing.T) { tracer, closer, err := InitGlobalTracer( - _emptyJaegerConfig, _serviceName, getLogger(), _statsReporter, + _emptyJaegerConfig, _serviceName, zap.L(), _statsReporter, ) defer closer.Close() assert.NotNil(t, tracer) @@ -58,7 +53,7 @@ func TestInitGlobalTracer_Simple(t *testing.T) { func TestInitGlobalTracer_Disabled(t *testing.T) { tracer, closer, err := InitGlobalTracer( - _disabledJaegerConfig, _serviceName, getLogger(), _statsReporter, + _disabledJaegerConfig, _serviceName, zap.L(), _statsReporter, ) defer closer.Close() assert.NotNil(t, tracer) @@ -67,34 +62,33 @@ func TestInitGlobalTracer_Disabled(t *testing.T) { } func TestInitGlobalTracer_NoServiceName(t *testing.T) { - tracer, closer, err := InitGlobalTracer(_emptyJaegerConfig, "", getLogger(), _statsReporter) + tracer, closer, err := InitGlobalTracer(_emptyJaegerConfig, "", zap.L(), _statsReporter) assert.Error(t, err) assert.Nil(t, tracer) assert.Nil(t, closer) } func TestLoadAppConfig(t *testing.T) { - jConfig := loadAppConfig(_emptyJaegerConfig, getLogger()) + jConfig := loadAppConfig(_emptyJaegerConfig, zap.L()) assert.NotNil(t, jConfig) assert.NotNil(t, jConfig.Logger) } func TestLoadAppConfig_JaegerConfigWithLogger(t *testing.T) { - jConfig := loadAppConfig(_jaegerConfigWithLogger, getLogger()) + jConfig := loadAppConfig(_jaegerConfigWithLogger, zap.L()) assert.NotNil(t, jConfig) assert.Equal(t, jaeger.NullLogger, jConfig.Logger) } func TestLoadAppConfig_NilJaegerConfig(t *testing.T) { - jConfig := loadAppConfig(nil, getLogger()) + jConfig := loadAppConfig(nil, zap.L()) assert.NotNil(t, jConfig) assert.NotNil(t, jConfig.Logger) } func TestJaegerLogger(t *testing.T) { - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - loggerWithZap := ulog.Builder().SetLogger(zapLogger).Build() - jLogger := jaegerLogger{log: loggerWithZap} + testutils.WithInMemoryLogger(t, nil, func(logger *zap.Logger, buf *ztest.Buffer) { + jLogger := jaegerLogger{logger.Sugar()} jLogger.Infof("info message") jLogger.Infof("info message: %s", "oddArg") jLogger.Infof("info message: %s %s", "value1", "value2") From abf51f5b8a6e821cee53ce985cea3fe00801eb3e Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 23 Feb 2017 01:06:28 -0800 Subject: [PATCH 07/13] Migrate service to zap RC --- service/host.go | 53 +++++++++++++++++++++++++--------------- service/host_mock.go | 8 +++--- service/service_setup.go | 21 ++++++++++------ service/service_test.go | 4 +-- 4 files changed, 52 insertions(+), 34 deletions(-) diff --git a/service/host.go b/service/host.go index 4abf33910..151964d96 100644 --- a/service/host.go +++ b/service/host.go @@ -21,7 +21,6 @@ package service import ( - "context" "fmt" "os" "os/signal" @@ -32,7 +31,7 @@ import ( "go.uber.org/fx/config" "go.uber.org/fx/internal/util" - "go.uber.org/fx/ulog" + "go.uber.org/zap" "github.com/pkg/errors" ) @@ -96,9 +95,9 @@ func (s *manager) IsRunning() bool { func (s *manager) OnCriticalError(err error) { shutdown := true if s.observer == nil { - ulog.Logger(_simpleCtx).Warn( + zap.L().Warn( "No observer set to handle lifecycle events. Shutting down.", - "event", "OnCriticalError", + zap.String("event", "OnCriticalError"), ) } else { shutdown = !s.observer.OnCriticalError(err) @@ -107,7 +106,10 @@ func (s *manager) OnCriticalError(err error) { if shutdown { if ok, err := s.shutdown(err, "", nil); !ok || err != nil { // TODO(ai) verify we flush logs - ulog.Logger(_simpleCtx).Info("Problem shutting down module", "success", ok, "error", err) + zap.L().Info("Problem shutting down module", + zap.Bool("success", ok), + zap.Error(err), + ) } } } @@ -147,7 +149,10 @@ func (s *manager) shutdown(err error, reason string, exitCode *int) (bool, error errs := s.stopModules() if len(errs) > 0 { for k, v := range errs { - ulog.Logger(_simpleCtx).Error("Failure to shut down module", "name", k.Name(), "error", v.Error()) + zap.L().Error("Failure to shut down module", + zap.String("name", k.Name()), + zap.Error(v), + ) } } @@ -159,15 +164,15 @@ func (s *manager) shutdown(err error, reason string, exitCode *int) (bool, error // Stop the metrics reporting if s.metricsCloser != nil { if err = s.metricsCloser.Close(); err != nil { - ulog.Logger(_simpleCtx).Error("Failure to close metrics", "error", err) + zap.L().Error("Failure to close metrics", zap.Error(err)) } } // Flush tracing buffers if s.tracerCloser != nil { - ulog.Logger(_simpleCtx).Debug("Closing tracer") + zap.L().Debug("Closing tracer") if err = s.tracerCloser.Close(); err != nil { - ulog.Logger(_simpleCtx).Error("Failure to close tracer", "error", err) + zap.L().Error("Failure to close tracer", zap.Error(err)) } } @@ -198,9 +203,9 @@ func (s *manager) addModules(modules ...ModuleCreateFunc) error { } if !s.supportsRole(mi.Roles...) { - ulog.Logger(_simpleCtx).Info( + zap.L().Info( "module will not be added due to selected roles", - "roles", mi.Roles, + zap.Any("roles", mi.Roles), ) } @@ -279,9 +284,13 @@ func (s *manager) start() Control { s.shutdownMu.Unlock() if _, err := s.shutdown(e, "", nil); err != nil { - ulog.Logger(_simpleCtx).Error("Unable to shut down modules", "initialError", e, "shutdownError", err) + zap.L().Error("Unable to shut down modules", + // FIXME: Migrate to zap.NamedError. + zap.Any("initialError", e), + zap.Any("shutdownError", err), + ) } - ulog.Logger(_simpleCtx).Error("Error starting the module", "error", e) + zap.L().Error("Error starting the module", zap.Error(e)) // return first service error if serviceErr == nil { serviceErr = e @@ -310,9 +319,9 @@ func (s *manager) registerSignalHandlers() { signal.Notify(ch, syscall.SIGINT, syscall.SIGTERM) go func() { sig := <-ch - ulog.Logger(_simpleCtx).Warn("Received shutdown signal", "signal", sig.String()) + zap.L().Warn("Received shutdown signal", zap.String("signal", sig.String())) if err := s.Stop("Received syscall", 0); err != nil { - ulog.Logger(_simpleCtx).Error("Error shutting down", "error", err.Error()) + zap.L().Error("Error shutting down", zap.Error(err)) } }() } @@ -339,13 +348,13 @@ func (s *manager) startModules() map[Module]error { select { case <-readyCh: - ulog.Logger(_simpleCtx).Info("Module started up cleanly", "module", m.Name()) + zap.L().Info("Module started up cleanly", zap.String("module", m.Name())) case <-time.After(defaultStartupWait): results[m] = fmt.Errorf("module didn't start after %v", defaultStartupWait) } if startError := <-startResult; startError != nil { - ulog.Logger(_simpleCtx).Error("Error received while starting module", "module", m.Name(), "error", startError) + zap.L().Error("Error received while starting module", zap.String("module", m.Name()), zap.Error(startError)) results[m] = startError } } @@ -384,7 +393,7 @@ type ExitCallback func(shutdown Exit) int func (s *manager) WaitForShutdown(exitCallback ExitCallback) { shutdown := <-s.closeChan - ulog.Logger(_simpleCtx).Info("Shutting down", "reason", shutdown.Reason) + zap.L().Info("Shutting down", zap.String("reason", shutdown.Reason)) exit := 0 if exitCallback != nil { @@ -401,7 +410,11 @@ func (s *manager) transitionState(to State) { // TODO(ai) this isn't used yet if to < s.state { - ulog.Logger(_simpleCtx).Fatal("Can't down from state", "from", s.state, "to", to, "service", s.Name()) + zap.L().Fatal("Can't down from state", + zap.Any("from", s.state), + zap.Any("to", to), + zap.String("service", s.Name()), + ) } for s.state < to { @@ -438,7 +451,7 @@ func loadInstanceConfig(cfg config.Provider, key string, instance interface{}) b // Try to load the service config err := cfg.Get(key).PopulateStruct(configValue.Interface()) if err != nil { - ulog.Logger(context.Background()).Error("Unable to load instance config", "error", err) + zap.L().Error("Unable to load instance config", zap.Error(err)) return false } instanceValue := reflect.ValueOf(instance).Elem() diff --git a/service/host_mock.go b/service/host_mock.go index 34fbcef9f..12a004cd4 100644 --- a/service/host_mock.go +++ b/service/host_mock.go @@ -24,15 +24,15 @@ import ( "go.uber.org/fx/auth" "go.uber.org/fx/config" "go.uber.org/fx/metrics" - "go.uber.org/fx/ulog" "github.com/opentracing/opentracing-go" "github.com/uber-go/tally" + "go.uber.org/zap" ) // NopHost is to be used in tests func NopHost() Host { - return NopHostConfigured(auth.NopClient, ulog.NopLogger, opentracing.NoopTracer{}) + return NopHostConfigured(auth.NopClient, zap.NewNop(), opentracing.NoopTracer{}) } // NopHostAuthFailure is nop manager with failure auth client @@ -40,11 +40,11 @@ func NopHostAuthFailure() Host { auth.UnregisterClient() defer auth.UnregisterClient() auth.RegisterClient(auth.FakeFailureClient) - return NopHostConfigured(auth.Load(nil), ulog.NopLogger, opentracing.NoopTracer{}) + return NopHostConfigured(auth.Load(nil), zap.NewNop(), opentracing.NoopTracer{}) } // NopHostConfigured is a nop manager with set logger and tracer for tests -func NopHostConfigured(client auth.Client, logger ulog.Log, tracer opentracing.Tracer) Host { +func NopHostConfigured(client auth.Client, logger *zap.Logger, tracer opentracing.Tracer) Host { return &serviceCore{ authClient: client, configProvider: config.NewStaticProvider(nil), diff --git a/service/service_setup.go b/service/service_setup.go index b997b24d1..efcbe733d 100644 --- a/service/service_setup.go +++ b/service/service_setup.go @@ -21,7 +21,6 @@ package service import ( - "context" "time" "go.uber.org/fx/auth" @@ -32,18 +31,24 @@ import ( "github.com/go-validator/validator" "github.com/pkg/errors" + "go.uber.org/zap" ) -var _simpleCtx = context.Background() - func (svc *serviceCore) setupLogging() { err := svc.configProvider.Get("logging").PopulateStruct(&svc.logConfig) if err != nil { - ulog.Logger(_simpleCtx).Info("Logging configuration is not provided, setting to default logger", "error", err) + zap.L().Info("Logging configuration is not provided, using UberFX defaults", zap.Error(err)) + svc.logConfig = ulog.DefaultConfiguration() } - logBuilder := ulog.Builder().WithScope(svc.metrics) - ulog.SetLogger(logBuilder.WithConfiguration(svc.logConfig).Build()) + logger, err := svc.logConfig.Build(zap.Hooks(ulog.Metrics(svc.metrics))) + if err != nil { + // Typically, this means that we're trying to log to files that don't + // exist or don't have appropriate permissions set. + zap.L().Info("Failed to configure logger", zap.Error(err)) + return + } + ulog.SetLogger(logger) } func (svc *serviceCore) setupStandardConfig() error { @@ -52,7 +57,7 @@ func (svc *serviceCore) setupStandardConfig() error { } if errs := validator.Validate(svc.standardConfig); errs != nil { - ulog.Logger(_simpleCtx).Error("Invalid service configuration", "error", errs) + zap.L().Error("Invalid service configuration", zap.Error(errs)) return errors.Wrap(errs, "service configuration failed validation") } return nil @@ -91,7 +96,7 @@ func (svc *serviceCore) setupTracer() error { tracer, closer, err := tracing.InitGlobalTracer( &svc.tracerConfig, svc.standardConfig.Name, - ulog.Logger(_simpleCtx), + zap.L(), svc.statsReporter, ) if err != nil { diff --git a/service/service_test.go b/service/service_test.go index ebda8b0e2..f6331c408 100644 --- a/service/service_test.go +++ b/service/service_test.go @@ -28,7 +28,7 @@ import ( "go.uber.org/fx/config" "go.uber.org/fx/testutils/metrics" - "go.uber.org/fx/ulog" + "go.uber.org/zap" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -113,7 +113,7 @@ logging: require.NoError(t, err) // Note: Sentry is not accessible so we cannot directly test it here. Just invoking the code // path to make sure there is no panic - ulog.Logger(_simpleCtx).Info("Testing sentry call") + zap.L().Info("Testing sentry call") } func TestBadOption_Panics(t *testing.T) { From d19b759aee6883e12bfa9d5f2b57d8714c789a73 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 23 Feb 2017 01:29:17 -0800 Subject: [PATCH 08/13] Migrate modules/rpc to zap RC --- modules/rpc/handler.go | 17 +++++------------ modules/rpc/handler_test.go | 23 +++++++++++------------ modules/rpc/yarpc.go | 9 ++++----- 3 files changed, 20 insertions(+), 29 deletions(-) diff --git a/modules/rpc/handler.go b/modules/rpc/handler.go index 4f5f57d14..af99db710 100644 --- a/modules/rpc/handler.go +++ b/modules/rpc/handler.go @@ -26,8 +26,8 @@ import ( "go.uber.org/fx/auth" "go.uber.org/fx/service" "go.uber.org/fx/ulog" + "go.uber.org/zap" - "github.com/opentracing/opentracing-go" "github.com/pkg/errors" "go.uber.org/yarpc/api/transport" ) @@ -50,10 +50,7 @@ func (f contextInboundMiddleware) Handle( Timer(req.Procedure). Start() defer stopwatch.Stop() - // Span is populated by YARPC, we just extract and use it - if span := opentracing.SpanFromContext(ctx); span != nil { - ctx = ulog.ContextWithTraceLogger(ctx, span) - } + return handler.Handle(ctx, req, resw) } @@ -66,10 +63,6 @@ func (f contextOnewayInboundMiddleware) HandleOneway( req *transport.Request, handler transport.OnewayHandler, ) error { - // Span is populated by YARPC, we just extract and use it - if span := opentracing.SpanFromContext(ctx); span != nil { - ctx = ulog.ContextWithTraceLogger(ctx, span) - } return handler.HandleOneway(ctx, req) } @@ -111,7 +104,7 @@ func (a authOnewayInboundMiddleware) HandleOneway( func authorize(ctx context.Context, host service.Host, statsClient *statsClient) (context.Context, error) { if err := host.AuthClient().Authorize(ctx); err != nil { statsClient.RPCAuthFailCounter().Inc(1) - ulog.Logger(ctx).Error(auth.ErrAuthorization, "error", err) + ulog.Logger(ctx).Error(auth.ErrAuthorization, zap.Error(err)) // TODO(anup): GFM-255 update returned error to transport.BadRequestError (user error than server error) // https://github.com/yarpc/yarpc-go/issues/687 return nil, err @@ -149,8 +142,8 @@ func (p panicOnewayInboundMiddleware) HandleOneway( func panicRecovery(ctx context.Context, statsClient *statsClient) { if err := recover(); err != nil { statsClient.RPCPanicCounter().Inc(1) - ulog.Logger(ctx).Error( - "Panic recovered serving request", "error", errors.Errorf("panic in handler: %+v", err), + ulog.Logger(ctx).Error("Panic recovered serving request", + zap.Error(errors.Errorf("panic in handler: %+v", err)), ) // rethrow panic back to yarpc // before https://github.com/yarpc/yarpc-go/issues/734 fixed, throw a generic error. diff --git a/modules/rpc/handler_test.go b/modules/rpc/handler_test.go index edc9a9dd3..86c84086d 100644 --- a/modules/rpc/handler_test.go +++ b/modules/rpc/handler_test.go @@ -36,7 +36,8 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/uber-go/tally" - "github.com/uber-go/zap" + "go.uber.org/zap" + ztest "go.uber.org/zap/testutils" ) type fakeEnveloper struct { @@ -58,11 +59,10 @@ func (f fakeEnveloper) ToWire() (wire.Value, error) { func TestInboundMiddleware_Context(t *testing.T) { host := service.NopHost() unary := contextInboundMiddleware{host, newStatsClient(host.Metrics())} - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - loggerWithZap := ulog.Builder().SetLogger(zapLogger).Build() + testutils.WithInMemoryLogger(t, nil, func(loggerWithZap *zap.Logger, buf *ztest.Buffer) { + defer ulog.SetLogger(loggerWithZap)() tracing.WithSpan(t, loggerWithZap, func(span opentracing.Span) { - ctx := ulog.ContextWithLogger(context.Background(), loggerWithZap) - ctx = opentracing.ContextWithSpan(ctx, span) + ctx := opentracing.ContextWithSpan(context.Background(), span) err := unary.Handle(ctx, &transport.Request{}, nil, &fakeUnary{t: t}) require.Contains(t, err.Error(), "handle") checkLogForTrace(t, buf) @@ -74,11 +74,10 @@ func TestOnewayInboundMiddleware_Context(t *testing.T) { oneway := contextOnewayInboundMiddleware{ Host: service.NopHost(), } - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - loggerWithZap := ulog.Builder().SetLogger(zapLogger).Build() + testutils.WithInMemoryLogger(t, nil, func(loggerWithZap *zap.Logger, buf *ztest.Buffer) { + defer ulog.SetLogger(loggerWithZap)() tracing.WithSpan(t, loggerWithZap, func(span opentracing.Span) { - ctx := ulog.ContextWithLogger(context.Background(), loggerWithZap) - ctx = opentracing.ContextWithSpan(ctx, span) + ctx := opentracing.ContextWithSpan(context.Background(), span) err := oneway.HandleOneway(ctx, &transport.Request{}, &fakeOneway{t: t}) require.Contains(t, err.Error(), "oneway handle") checkLogForTrace(t, buf) @@ -86,11 +85,11 @@ func TestOnewayInboundMiddleware_Context(t *testing.T) { }) } -func checkLogForTrace(t *testing.T, buf *testutils.TestBuffer) { +func checkLogForTrace(t *testing.T, buf *ztest.Buffer) { require.True(t, len(buf.Lines()) > 0) for _, line := range buf.Lines() { - assert.Contains(t, line, "traceID") - assert.Contains(t, line, "spanID") + assert.Contains(t, line, "trace") + assert.Contains(t, line, "span") } } diff --git a/modules/rpc/yarpc.go b/modules/rpc/yarpc.go index 9faa4d368..f836cd4da 100644 --- a/modules/rpc/yarpc.go +++ b/modules/rpc/yarpc.go @@ -21,7 +21,6 @@ package rpc import ( - "context" "errors" "fmt" "strconv" @@ -29,7 +28,6 @@ import ( "go.uber.org/fx/modules" "go.uber.org/fx/service" - "go.uber.org/fx/ulog" errs "github.com/pkg/errors" "go.uber.org/fx/dig" @@ -38,6 +36,7 @@ import ( "go.uber.org/yarpc/api/transport" "go.uber.org/yarpc/transport/http" tch "go.uber.org/yarpc/transport/tchannel" + "go.uber.org/zap" ) // YARPCModule is an implementation of a core RPC module using YARPC. @@ -50,7 +49,7 @@ type YARPCModule struct { modules.ModuleBase register registerServiceFunc config yarpcConfig - log ulog.Log + log *zap.Logger statsClient *statsClient stateMu sync.RWMutex isRunning bool @@ -246,7 +245,7 @@ func newYARPCModule( statsClient: newStatsClient(mi.Host.Metrics()), } - module.log = ulog.Logger(context.Background()).With("moduleName", name) + module.log = zap.L().With(zap.String("moduleName", name)) for _, opt := range options { if err := opt(&mi); err != nil { return module, errs.Wrap(err, "unable to apply option to YARPC module") @@ -287,7 +286,7 @@ func newYARPCModule( module.controller.addConfig(module.config) - module.log.Info("Module successfuly created", "inbounds", module.config.Inbounds) + module.log.Info("Module successfuly created", zap.Any("inbounds", module.config.Inbounds)) return module, nil } From 7afb03bbd7377fb71d78dd1b788ea8ab6686c392 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 23 Feb 2017 01:45:55 -0800 Subject: [PATCH 09/13] Migrate modules/uhttp to zap RC --- modules/uhttp/client/client_middleware.go | 5 +++-- .../client/client_middleware_benchmark_test.go | 4 ++-- modules/uhttp/client/client_middleware_test.go | 8 ++++---- modules/uhttp/http.go | 13 +++++++------ modules/uhttp/middleware.go | 18 +++++++++--------- modules/uhttp/middleware_test.go | 15 ++++++++------- modules/uhttp/middlewarechain_builder.go | 5 +++-- 7 files changed, 36 insertions(+), 32 deletions(-) diff --git a/modules/uhttp/client/client_middleware.go b/modules/uhttp/client/client_middleware.go index ac8d34fc6..f11a1fecf 100644 --- a/modules/uhttp/client/client_middleware.go +++ b/modules/uhttp/client/client_middleware.go @@ -26,6 +26,7 @@ import ( "go.uber.org/fx/auth" "go.uber.org/fx/config" "go.uber.org/fx/ulog" + "go.uber.org/zap" "github.com/opentracing/opentracing-go" "github.com/opentracing/opentracing-go/ext" @@ -95,13 +96,13 @@ func authenticationOutbound(info auth.CreateAuthInfo) OutboundMiddlewareFunc { authCtx, err = authClient.Authenticate(authCtx) if err != nil { - ulog.Logger(ctx).Error(auth.ErrAuthentication, "error", err) + ulog.Logger(ctx).Error(auth.ErrAuthentication, zap.Error(err)) return nil, err } span := opentracing.SpanFromContext(authCtx) if err := injectSpanIntoHeaders(req.Header, span); err != nil { - ulog.Logger(authCtx).Error("Error injecting auth context", "error", err) + ulog.Logger(authCtx).Error("Error injecting auth context", zap.Error(err)) return nil, err } diff --git a/modules/uhttp/client/client_middleware_benchmark_test.go b/modules/uhttp/client/client_middleware_benchmark_test.go index d60347061..a4793eee2 100644 --- a/modules/uhttp/client/client_middleware_benchmark_test.go +++ b/modules/uhttp/client/client_middleware_benchmark_test.go @@ -28,10 +28,10 @@ import ( "go.uber.org/fx/auth" "go.uber.org/fx/metrics" "go.uber.org/fx/tracing" - "go.uber.org/fx/ulog" "github.com/opentracing/opentracing-go" jconfig "github.com/uber/jaeger-client-go/config" + "go.uber.org/zap" ) // BenchmarkClientMiddleware/empty-8 100000000 10.8 ns/op 0 B/op 0 allocs/op @@ -39,7 +39,7 @@ import ( // BenchmarkClientMiddleware/auth-8 1000000 1866 ns/op 719 B/op 14 allocs/op // BenchmarkClientMiddleware/default-8 300000 5604 ns/op 2477 B/op 41 allocs/op func BenchmarkClientMiddleware(b *testing.B) { - tracer, closer, err := tracing.InitGlobalTracer(&jconfig.Configuration{}, "Test", ulog.NopLogger, metrics.NopCachedStatsReporter) + tracer, closer, err := tracing.InitGlobalTracer(&jconfig.Configuration{}, "Test", zap.NewNop(), metrics.NopCachedStatsReporter) if err != nil { b.Error(err) } diff --git a/modules/uhttp/client/client_middleware_test.go b/modules/uhttp/client/client_middleware_test.go index 5f494a6e4..01f86db1e 100644 --- a/modules/uhttp/client/client_middleware_test.go +++ b/modules/uhttp/client/client_middleware_test.go @@ -31,13 +31,13 @@ import ( "go.uber.org/fx/config" "go.uber.org/fx/metrics" "go.uber.org/fx/tracing" - "go.uber.org/fx/ulog" "github.com/opentracing/opentracing-go" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "github.com/uber-go/tally" jconfig "github.com/uber/jaeger-client-go/config" + "go.uber.org/zap" ) var ( @@ -74,7 +74,7 @@ func TestExecutionChainOutboundMiddlewareError(t *testing.T) { } func withOpentracingSetup(t *testing.T, registerFunc auth.RegisterFunc, fn func(tracer opentracing.Tracer)) { - tracer, closer, err := tracing.InitGlobalTracer(&jconfig.Configuration{}, "Test", ulog.NopLogger, metrics.NopCachedStatsReporter) + tracer, closer, err := tracing.InitGlobalTracer(&jconfig.Configuration{}, "Test", zap.NewNop(), metrics.NopCachedStatsReporter) defer closer.Close() assert.NotNil(t, closer) require.NoError(t, err) @@ -158,8 +158,8 @@ func (f fakeAuthInfo) Config() config.Provider { return config.NewYAMLProviderFromBytes(f.yaml) } -func (f fakeAuthInfo) Logger() ulog.Log { - return ulog.NopLogger +func (f fakeAuthInfo) Logger() *zap.Logger { + return zap.NewNop() } func (f fakeAuthInfo) Metrics() tally.Scope { diff --git a/modules/uhttp/http.go b/modules/uhttp/http.go index 0148c95bb..d5940943c 100644 --- a/modules/uhttp/http.go +++ b/modules/uhttp/http.go @@ -34,6 +34,7 @@ import ( "go.uber.org/fx/ulog" "github.com/pkg/errors" + "go.uber.org/zap" ) const ( @@ -63,7 +64,7 @@ var _ service.Module = &Module{} type Module struct { modules.ModuleBase config Config - log ulog.Log + log *zap.Logger srv *http.Server listener net.Listener handlers []RouteHandler @@ -112,7 +113,7 @@ func newModule( handlers := addHealth(getHandlers(mi.Host)) - log := ulog.Logger(context.Background()).With("moduleName", mi.Name) + log := ulog.Logger(context.Background()).With(zap.String("moduleName", mi.Name)) // TODO (madhu): Add other middleware - logging, metrics. module := &Module{ @@ -123,7 +124,7 @@ func newModule( err := module.Host().Config().Get(getConfigKey(mi.Name)).PopulateStruct(cfg) if err != nil { - log.Error("Error loading http module configuration", "error", err) + log.Error("Error loading http module configuration", zap.Error(err)) } module.config = *cfg @@ -131,7 +132,7 @@ func newModule( for _, option := range options { if err := option(&mi); err != nil { - module.log.Error("Unable to apply option", "error", err, "option", option) + module.log.Error("Unable to apply option", zap.Error(err), zap.Any("option", option)) return module, errors.Wrap(err, "unable to apply option to module") } } @@ -169,7 +170,7 @@ func (m *Module) Start(ready chan<- struct{}) <-chan error { // finally, start the http server. // TODO update log object to be accessed via http context #74 - m.log.Info("Server listening on port", "port", m.config.Port) + m.log.Info("Server listening on port", zap.Int("port", m.config.Port)) if err != nil { ret <- err @@ -188,7 +189,7 @@ func (m *Module) Start(ready chan<- struct{}) <-chan error { err := m.srv.Serve(listener) ret <- err if err != nil { - m.log.Error("HTTP Serve error", "error", err) + m.log.Error("HTTP Serve error", zap.Error(err)) } }() return ret diff --git a/modules/uhttp/middleware.go b/modules/uhttp/middleware.go index 670730a5e..315aeecaa 100644 --- a/modules/uhttp/middleware.go +++ b/modules/uhttp/middleware.go @@ -30,6 +30,7 @@ import ( "github.com/opentracing/opentracing-go" "github.com/opentracing/opentracing-go/ext" "github.com/pkg/errors" + "go.uber.org/zap" ) const _panicResponse = "Server Error" @@ -49,12 +50,11 @@ func (f InboundMiddlewareFunc) Handle(w http.ResponseWriter, r *http.Request, ne } type contextInbound struct { - log ulog.Log + log *zap.Logger } func (f contextInbound) Handle(w http.ResponseWriter, r *http.Request, next http.Handler) { - ctx := ulog.ContextWithLogger(r.Context(), f.log) - next.ServeHTTP(w, r.WithContext(ctx)) + next.ServeHTTP(w, r.WithContext(r.Context())) } type tracingInbound struct{} @@ -65,16 +65,13 @@ func (f tracingInbound) Handle(w http.ResponseWriter, r *http.Request, next http carrier := opentracing.HTTPHeadersCarrier(r.Header) spanCtx, err := opentracing.GlobalTracer().Extract(opentracing.HTTPHeaders, carrier) if err != nil && err != opentracing.ErrSpanContextNotFound { - ulog.Logger(ctx).Warn("Malformed inbound tracing context: ", "error", err.Error()) + ulog.Logger(ctx).Warn("Malformed inbound tracing context: ", zap.Error(err)) } span := opentracing.GlobalTracer().StartSpan(operationName, ext.RPCServerOption(spanCtx)) ext.HTTPUrl.Set(span, r.URL.String()) defer span.Finish() ctx = opentracing.ContextWithSpan(ctx, span) - - ctx = ulog.ContextWithTraceLogger(ctx, span) - next.ServeHTTP(w, r.WithContext(ctx)) } @@ -87,7 +84,7 @@ type authorizationInbound struct { func (f authorizationInbound) Handle(w http.ResponseWriter, r *http.Request, next http.Handler) { if err := f.authClient.Authorize(r.Context()); err != nil { f.statsClient.HTTPAuthFailCounter().Inc(1) - ulog.Logger(r.Context()).Error(auth.ErrAuthorization, "error", err) + ulog.Logger(r.Context()).Error(auth.ErrAuthorization, zap.Error(err)) http.Error(w, fmt.Sprintf("Unauthorized access: %+v", err), http.StatusUnauthorized) return } @@ -104,7 +101,10 @@ func (f panicInbound) Handle(w http.ResponseWriter, r *http.Request, next http.H ctx := r.Context() defer func() { if err := recover(); err != nil { - ulog.Logger(ctx).Error("Panic recovered serving request", "error", errors.Errorf("panic in handler: %+v", err), "url", r.URL) + ulog.Logger(ctx).Error("Panic recovered serving request", + zap.Error(errors.Errorf("panic in handler: %+v", err)), + zap.Stringer("url", r.URL), + ) f.statsClient.HTTPPanicCounter().Inc(1) http.Error(w, _panicResponse, http.StatusInternalServerError) } diff --git a/modules/uhttp/middleware_test.go b/modules/uhttp/middleware_test.go index 202fd5a47..cceb69177 100644 --- a/modules/uhttp/middleware_test.go +++ b/modules/uhttp/middleware_test.go @@ -36,8 +36,9 @@ import ( "github.com/opentracing/opentracing-go" "github.com/stretchr/testify/assert" "github.com/uber-go/tally" - "github.com/uber-go/zap" "github.com/uber/jaeger-client-go/config" + "go.uber.org/zap" + ztest "go.uber.org/zap/testutils" ) func TestDefaultInboundMiddlewareWithNopHost(t *testing.T) { @@ -127,9 +128,9 @@ func testInboundMiddlewareChain(t *testing.T, host service.Host) { } func testTracingInboundWithLogs(t *testing.T) { - testutils.WithInMemoryLogger(t, nil, func(zapLogger zap.Logger, buf *testutils.TestBuffer) { - // Create in-memory logger and jaeger tracer - loggerWithZap := ulog.Builder().SetLogger(zapLogger).Build() + testutils.WithInMemoryLogger(t, nil, func(loggerWithZap *zap.Logger, buf *ztest.Buffer) { + defer ulog.SetLogger(loggerWithZap)() + // Create a Jaeger tracer. jConfig := &config.Configuration{ Sampler: &config.SamplerConfig{Type: "const", Param: 1.0}, Reporter: &config.ReporterConfig{LogSpans: true}, @@ -142,18 +143,18 @@ func testTracingInboundWithLogs(t *testing.T) { opentracing.InitGlobalTracer(tracer) defer opentracing.InitGlobalTracer(opentracing.NoopTracer{}) - ulog.SetLogger(loggerWithZap) chain := newInboundMiddlewareChainBuilder().AddMiddleware([]InboundMiddleware{contextInbound{loggerWithZap}, tracingInbound{}}...).Build(getNopHandler()) response := testServeHTTP(chain) assert.Contains(t, response.Body.String(), "inbound middleware ok") assert.True(t, len(buf.Lines()) > 0) var tracecount = 0 var spancount = 0 + t.Log(buf.Lines()) for _, line := range buf.Lines() { - if strings.Contains(line, "traceID") { + if strings.Contains(line, `"trace":`) { tracecount++ } - if strings.Contains(line, "spanID") { + if strings.Contains(line, `"span":`) { spancount++ } } diff --git a/modules/uhttp/middlewarechain_builder.go b/modules/uhttp/middlewarechain_builder.go index bdbcfe307..17bb1600f 100644 --- a/modules/uhttp/middlewarechain_builder.go +++ b/modules/uhttp/middlewarechain_builder.go @@ -24,7 +24,8 @@ import ( "net/http" "go.uber.org/fx/auth" - "go.uber.org/fx/ulog" + + "go.uber.org/zap" ) type inboundMiddlewareChain struct { @@ -48,7 +49,7 @@ type inboundMiddlewareChainBuilder struct { middleware []InboundMiddleware } -func defaultInboundMiddlewareChainBuilder(log ulog.Log, authClient auth.Client, statsClient *statsClient) inboundMiddlewareChainBuilder { +func defaultInboundMiddlewareChainBuilder(log *zap.Logger, authClient auth.Client, statsClient *statsClient) inboundMiddlewareChainBuilder { mcb := newInboundMiddlewareChainBuilder() return mcb.AddMiddleware( contextInbound{log}, From e4803b0a395b81d0ef78cf2304477291dc376650 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 23 Feb 2017 01:47:57 -0800 Subject: [PATCH 10/13] Migrate examples to zap RC --- examples/keyvalue/server/observer.go | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/examples/keyvalue/server/observer.go b/examples/keyvalue/server/observer.go index 66f9907f4..6c794068c 100644 --- a/examples/keyvalue/server/observer.go +++ b/examples/keyvalue/server/observer.go @@ -21,10 +21,8 @@ package main import ( - "context" - "go.uber.org/fx/service" - "go.uber.org/fx/ulog" + "go.uber.org/zap" ) // Observer receives callbacks during various service lifecycle events @@ -37,7 +35,7 @@ type Observer struct { // OnInit is called during service init process. Returning an error halts the init? func (o *Observer) OnInit(svc service.Host) error { - ulog.Logger(context.Background()).Info( + zap.S().Info( "Received service init callback", "service_name", o.Name(), "some_number", o.ServiceConfig.SomeNumber, From 653ac2848fe42b8152262c7c39b5d42dde1004e7 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 23 Feb 2017 14:58:39 -0800 Subject: [PATCH 11/13] Upgrade zap to v1.0.0-rc.2 Again, this necessarily upgrades all other dependencies. --- glide.lock | 13 ++++++------- glide.yaml | 4 +--- 2 files changed, 7 insertions(+), 10 deletions(-) diff --git a/glide.lock b/glide.lock index f71a5a14d..845efc0ab 100644 --- a/glide.lock +++ b/glide.lock @@ -1,5 +1,5 @@ -hash: f4a033e6af47e10391f8b22f93a319ab1becad7c4c6035665f0def36d18d76ed -updated: 2017-02-16T00:35:29.71174199-08:00 +hash: 2b2a3032c1ba22a3650890ee852545a11f4113801497cb33adde98a36f0f9cea +updated: 2017-02-23T16:04:45.370717001-08:00 imports: - name: github.com/apache/thrift version: 9549b25c77587b29be4e0b5c258221a4ed85d37a @@ -43,8 +43,6 @@ imports: version: e682c1008ac17bf26d2e4b5ad6cdd08520ed0b22 - name: github.com/uber-go/tally version: 43c1379c0577ac1eb74f9f3869cea07191c9992b -- name: github.com/uber-go/zap - version: 72313cde80537dd4dc9b7b80eda6d7ed796c4232 - name: github.com/uber/jaeger-client-go version: e39d0f1b622558cae3d9db0062a739cc6ffa700f subpackages: @@ -108,20 +106,21 @@ imports: - transport/tchannel - transport/tchannel/internal - name: go.uber.org/zap - version: 72313cde80537dd4dc9b7b80eda6d7ed796c4232 + version: a03b90bc236f3def382f17743518889a31f8187c subpackages: - buffer - internal/bufferpool - internal/exit - internal/multierror + - testutils - zapcore - name: golang.org/x/net - version: b4690f45fa1cafc47b1c280c2e75116efe40cc13 + version: dd2d9a67c97da0afa00d5726e28086007a0acce5 subpackages: - context - context/ctxhttp - name: golang.org/x/tools - version: 6e7ee5a9ec598d425ca86d6aab6e76e21baf328c + version: 219e654bb7266d3b73c4610ed24c33d12560826a subpackages: - go/ast/astutil - name: gopkg.in/yaml.v2 diff --git a/glide.yaml b/glide.yaml index 108cb1b67..76a4fc4e0 100644 --- a/glide.yaml +++ b/glide.yaml @@ -1,9 +1,7 @@ package: go.uber.org/fx import: - package: go.uber.org/zap - version: a6ddd813074ca930e15d768c0f2a941afcc36b27 - # Waiting on https://github.com/uber-go/zap/pull/329 - # version: v1.0.0-rc.1 + version: v1.0.0-rc.2 - package: github.com/uber-go/tally version: ^1.1.0 - package: github.com/gorilla/mux From 68d4547281b5ed2ff4bb8fd0076c8efe30797482 Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 23 Feb 2017 16:11:33 -0800 Subject: [PATCH 12/13] Fix service to use NamedError --- service/host.go | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/service/host.go b/service/host.go index 151964d96..f62c8db5f 100644 --- a/service/host.go +++ b/service/host.go @@ -285,9 +285,8 @@ func (s *manager) start() Control { s.shutdownMu.Unlock() if _, err := s.shutdown(e, "", nil); err != nil { zap.L().Error("Unable to shut down modules", - // FIXME: Migrate to zap.NamedError. - zap.Any("initialError", e), - zap.Any("shutdownError", err), + zap.NamedError("initialError", e), + zap.NamedError("shutdownError", err), ) } zap.L().Error("Error starting the module", zap.Error(e)) From 80c2077aa8be682ff3ce134c0be43c69bbd9979d Mon Sep 17 00:00:00 2001 From: Akshay Shah Date: Thu, 23 Feb 2017 16:25:14 -0800 Subject: [PATCH 13/13] Simplify struct literals --- ulog/context_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ulog/context_test.go b/ulog/context_test.go index 14fc16c7c..37ed859f8 100644 --- a/ulog/context_test.go +++ b/ulog/context_test.go @@ -80,7 +80,7 @@ func TestTraceField(t *testing.T) { // but that just copies the production code. assert.Equal( t, - map[string]struct{}{"span": struct{}{}, "trace": struct{}{}, "parent": struct{}{}}, + map[string]struct{}{"span": {}, "trace": {}, "parent": {}}, keys, "Expected to log span and trace IDs.", )