stacktrace_ext_test.go

// Copyright (c) 2016, 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 zap_test

import (
	"bytes"
	"encoding/json"
	"io/ioutil"
	"os"
	"os/exec"
	"path/filepath"
	"runtime"
	"strings"
	"testing"

	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"

	"github.com/stretchr/testify/assert"
	"github.com/stretchr/testify/require"
)

// _zapPackages are packages that we search for in the logging output to match a
// zap stack frame. It is different from _zapStacktracePrefixes which  is only
// intended to match on the function name, while this is on the full output
// which includes filenames.
var _zapPackages = []string{
	"go.uber.org/zap.",
	"go.uber.org/zap/zapcore.",
}

func TestStacktraceFiltersZapLog(t *testing.T) {
	withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) {
		logger.Error("test log")
		logger.Sugar().Error("sugar test log")

		require.Contains(t, out.String(), "TestStacktraceFiltersZapLog", "Should not strip out non-zap import")
		verifyNoZap(t, out.String())
	})
}

func TestStacktraceFiltersZapMarshal(t *testing.T) {
	withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) {
		marshal := func(enc zapcore.ObjectEncoder) error {
			logger.Warn("marshal caused warn")
			enc.AddString("f", "v")
			return nil
		}
		logger.Error("test log", zap.Object("obj", zapcore.ObjectMarshalerFunc(marshal)))

		logs := out.String()

		// The marshal function (which will be under the test function) should not be stripped.
		const marshalFnPrefix = "TestStacktraceFiltersZapMarshal."
		require.Contains(t, logs, marshalFnPrefix, "Should not strip out marshal call")

		// There should be no zap stack traces before that point.
		marshalIndex := strings.Index(logs, marshalFnPrefix)
		verifyNoZap(t, logs[:marshalIndex])

		// After that point, there should be zap stack traces - we don't want to strip out
		// the Marshal caller information.
		for _, fnPrefix := range _zapPackages {
			require.Contains(t, logs[marshalIndex:], fnPrefix, "Missing zap caller stack for Marshal")
		}
	})
}

func TestStacktraceFiltersVendorZap(t *testing.T) {
	// We already have the dependencies downloaded so this should be
	// instant.
	deps := downloadDependencies(t)

	// We need to simulate a zap as a vendor library, so we're going to
	// create a fake GOPATH and run the above test which will contain zap
	// in the vendor directory.
	withGoPath(t, func(goPath string) {
		zapDir, err := os.Getwd()
		require.NoError(t, err, "Failed to get current directory")

		testDir := filepath.Join(goPath, "src/go.uber.org/zap_test/")
		vendorDir := filepath.Join(testDir, "vendor")
		require.NoError(t, os.MkdirAll(testDir, 0777), "Failed to create source director")

		curFile := getSelfFilename(t)
		setupSymlink(t, curFile, filepath.Join(testDir, curFile))

		// Set up symlinks for zap, and for any test dependencies.
		setupSymlink(t, zapDir, filepath.Join(vendorDir, "go.uber.org/zap"))
		for _, dep := range deps {
			setupSymlink(t, dep.Dir, filepath.Join(vendorDir, dep.ImportPath))
		}

		// Now run the above test which ensures we filter out zap
		// stacktraces, but this time zap is in a vendor
		cmd := exec.Command("go", "test", "-v", "-run", "TestStacktraceFiltersZap")
		cmd.Dir = testDir
		cmd.Env = append(os.Environ(), "GO111MODULE=off")
		out, err := cmd.CombinedOutput()
		require.NoError(t, err, "Failed to run test in vendor directory, output: %s", out)
		assert.Contains(t, string(out), "PASS")
	})
}

func TestStacktraceWithoutCallerSkip(t *testing.T) {
	withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) {
		func() {
			logger.Error("test log")
		}()

		require.Contains(t, out.String(), "TestStacktraceWithoutCallerSkip.", "Should not skip too much")
		verifyNoZap(t, out.String())
	})
}

func TestStacktraceWithCallerSkip(t *testing.T) {
	withLogger(t, func(logger *zap.Logger, out *bytes.Buffer) {
		logger = logger.WithOptions(zap.AddCallerSkip(2))
		func() {
			logger.Error("test log")
		}()

		require.NotContains(t, out.String(), "TestStacktraceWithCallerSkip.", "Should skip as requested by caller skip")
		require.Contains(t, out.String(), "TestStacktraceWithCallerSkip", "Should not skip too much")
		verifyNoZap(t, out.String())
	})
}

// withLogger sets up a logger with a real encoder set up, so that any marshal functions are called.
// The inbuilt observer does not call Marshal for objects/arrays, which we need for some tests.
func withLogger(t *testing.T, fn func(logger *zap.Logger, out *bytes.Buffer)) {
	buf := &bytes.Buffer{}
	encoder := zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig())
	core := zapcore.NewCore(encoder, zapcore.AddSync(buf), zapcore.DebugLevel)
	logger := zap.New(core, zap.AddStacktrace(zap.DebugLevel))
	fn(logger, buf)
}

func verifyNoZap(t *testing.T, logs string) {
	for _, fnPrefix := range _zapPackages {
		require.NotContains(t, logs, fnPrefix, "Should not strip out marshal call")
	}
}

func withGoPath(t *testing.T, f func(goPath string)) {
	goPath, err := ioutil.TempDir("", "gopath")
	require.NoError(t, err, "Failed to create temporary directory for GOPATH")
	//defer os.RemoveAll(goPath)

	os.Setenv("GOPATH", goPath)
	defer os.Setenv("GOPATH", os.Getenv("GOPATH"))

	f(goPath)
}

func getSelfFilename(t *testing.T) string {
	_, file, _, ok := runtime.Caller(0)
	require.True(t, ok, "Failed to get caller information to identify local file")

	return filepath.Base(file)
}

func setupSymlink(t *testing.T, src, dst string) {
	// Make sure the destination directory exists.
	os.MkdirAll(filepath.Dir(dst), 0777)

	// Get absolute path of the source for the symlink, otherwise we can create a symlink
	// that uses relative paths.
	srcAbs, err := filepath.Abs(src)
	require.NoError(t, err, "Failed to get absolute path")

	require.NoError(t, os.Symlink(srcAbs, dst), "Failed to set up symlink")
}

type dependency struct {
	ImportPath string `json:"Path"` // import path of the dependency
	Dir        string `json:"Dir"`  // location on disk
}

// Downloads all dependencies for the current Go module and reports their
// module paths and locations on disk.
func downloadDependencies(t *testing.T) []dependency {
	cmd := exec.Command("go", "mod", "download", "-json")

	stdout, err := cmd.Output()
	require.NoError(t, err, "Failed to run 'go mod download'")

	var deps []dependency
	dec := json.NewDecoder(bytes.NewBuffer(stdout))
	for dec.More() {
		var d dependency
		require.NoError(t, dec.Decode(&d), "Failed to decode dependency")
		deps = append(deps, d)
	}

	return deps
}