Merge pull request #13866 from serathius/logs-v3.5

[release-3.5] Fix inconsistent log format
This commit is contained in:
Marek Siarkowicz 2022-04-04 13:04:16 +02:00 committed by GitHub
commit 8b9ce3e150
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
25 changed files with 177 additions and 107 deletions

View File

@ -21,6 +21,17 @@ import (
"go.uber.org/zap/zapcore"
)
// CreateDefaultZapLogger creates a logger with default zap configuration
func CreateDefaultZapLogger(level zapcore.Level) (*zap.Logger, error) {
lcfg := DefaultZapLoggerConfig
lcfg.Level = zap.NewAtomicLevelAt(level)
c, err := lcfg.Build()
if err != nil {
return nil, err
}
return c, nil
}
// DefaultZapLoggerConfig defines default zap logger configuration.
var DefaultZapLoggerConfig = zap.Config{
Level: zap.NewAtomicLevelAt(ConvertToZapLevel(DefaultLogLevel)),

View File

@ -24,6 +24,7 @@ import (
"time"
"go.etcd.io/etcd/api/v3/v3rpc/rpctypes"
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.etcd.io/etcd/client/v3/credentials"
"go.etcd.io/etcd/client/v3/internal/endpoint"
"go.etcd.io/etcd/client/v3/internal/resolver"
@ -368,7 +369,10 @@ func newClient(cfg *Config) (*Client, error) {
} else if cfg.LogConfig != nil {
client.lg, err = cfg.LogConfig.Build()
} else {
client.lg, err = CreateDefaultZapLogger()
client.lg, err = logutil.CreateDefaultZapLogger(etcdClientDebugLevel())
if client.lg != nil {
client.lg = client.lg.Named("etcd-client")
}
}
if err != nil {
return nil, err

View File

@ -19,7 +19,6 @@ import (
"os"
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
"go.uber.org/zap/zapgrpc"
"google.golang.org/grpc/grpclog"
@ -29,10 +28,11 @@ func init() {
// We override grpc logger only when the environment variable is set
// in order to not interfere by default with user's code or other libraries.
if os.Getenv("ETCD_CLIENT_DEBUG") != "" {
lg, err := CreateDefaultZapLogger()
lg, err := logutil.CreateDefaultZapLogger(etcdClientDebugLevel())
if err != nil {
panic(err)
}
lg = lg.Named("etcd-client")
grpclog.SetLoggerV2(zapgrpc.NewLogger(lg))
}
}
@ -57,21 +57,3 @@ func etcdClientDebugLevel() zapcore.Level {
}
return l
}
// CreateDefaultZapLoggerConfig creates a logger config that is configurable using env variable:
// ETCD_CLIENT_DEBUG= debug|info|warn|error|dpanic|panic|fatal|true (true=info)
func CreateDefaultZapLoggerConfig() zap.Config {
lcfg := logutil.DefaultZapLoggerConfig
lcfg.Level = zap.NewAtomicLevelAt(etcdClientDebugLevel())
return lcfg
}
// CreateDefaultZapLogger creates a logger that is configurable using env variable:
// ETCD_CLIENT_DEBUG= debug|info|warn|error|dpanic|panic|fatal|true (true=info)
func CreateDefaultZapLogger() (*zap.Logger, error) {
c, err := CreateDefaultZapLoggerConfig().Build()
if err != nil {
return nil, err
}
return c.Named("etcd-client"), nil
}

View File

@ -44,9 +44,6 @@ func hasChecksum(n int64) bool {
// selected node, and saved snapshot is the point-in-time state of
// the selected node.
func Save(ctx context.Context, lg *zap.Logger, cfg clientv3.Config, dbPath string) error {
if lg == nil {
lg = zap.NewExample()
}
cfg.Logger = lg.Named("client")
if len(cfg.Endpoints) != 1 {
return fmt.Errorf("snapshot must be requested to one selected node, not multiple %v", cfg.Endpoints)

View File

@ -22,6 +22,7 @@ import (
"go.etcd.io/etcd/api/v3/etcdserverpb"
"go.etcd.io/etcd/api/v3/v3rpc/rpctypes"
"go.etcd.io/etcd/client/pkg/v3/logutil"
v3 "go.etcd.io/etcd/client/v3"
"go.etcd.io/etcd/pkg/v3/cobrautl"
"go.etcd.io/etcd/pkg/v3/flags"
@ -88,7 +89,7 @@ type epHealth struct {
// epHealthCommandFunc executes the "endpoint-health" command.
func epHealthCommandFunc(cmd *cobra.Command, args []string) {
lg, err := zap.NewProduction()
lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
cobrautl.ExitWithError(cobrautl.ExitError, err)
}

View File

@ -25,6 +25,7 @@ import (
"time"
"github.com/bgentry/speakeasy"
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.etcd.io/etcd/client/pkg/v3/srv"
"go.etcd.io/etcd/client/pkg/v3/transport"
"go.etcd.io/etcd/client/v3"
@ -114,7 +115,7 @@ func (*discardValue) Set(string) error { return nil }
func (*discardValue) Type() string { return "" }
func clientConfigFromCmd(cmd *cobra.Command) *clientConfig {
lg, err := zap.NewProduction()
lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
cobrautl.ExitWithError(cobrautl.ExitError, err)
}
@ -193,7 +194,7 @@ func newClientCfg(endpoints []string, dialTimeout, keepAliveTime, keepAliveTimeo
// set tls if any one tls option set
var cfgtls *transport.TLSInfo
tlsinfo := transport.TLSInfo{}
tlsinfo.Logger, _ = zap.NewProduction()
tlsinfo.Logger, _ = logutil.CreateDefaultZapLogger(zap.InfoLevel)
if scfg.cert != "" {
tlsinfo.CertFile = scfg.cert
cfgtls = &tlsinfo

View File

@ -20,6 +20,7 @@ import (
"os"
"github.com/spf13/cobra"
"go.etcd.io/etcd/client/pkg/v3/logutil"
snapshot "go.etcd.io/etcd/client/v3/snapshot"
"go.etcd.io/etcd/etcdutl/v3/etcdutl"
"go.etcd.io/etcd/pkg/v3/cobrautl"
@ -98,7 +99,7 @@ func snapshotSaveCommandFunc(cmd *cobra.Command, args []string) {
cobrautl.ExitWithError(cobrautl.ExitBadArgs, err)
}
lg, err := zap.NewProduction()
lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
cobrautl.ExitWithError(cobrautl.ExitError, err)
}

View File

@ -15,13 +15,14 @@
package etcdutl
import (
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.etcd.io/etcd/pkg/v3/cobrautl"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)
func GetLogger() *zap.Logger {
config := zap.NewProductionConfig()
config := logutil.DefaultZapLoggerConfig
config.Encoding = "console"
config.EncoderConfig.EncodeTime = zapcore.RFC3339TimeEncoder
lg, err := config.Build()

View File

@ -69,9 +69,6 @@ type Manager interface {
// NewV3 returns a new snapshot Manager for v3.x snapshot.
func NewV3(lg *zap.Logger) Manager {
if lg == nil {
lg = zap.NewExample()
}
return &v3Manager{lg: lg}
}

View File

@ -25,6 +25,7 @@ import (
"strings"
"sync"
"syscall"
"time"
"github.com/creack/pty"
)
@ -36,7 +37,6 @@ type ExpectProcess struct {
fpty *os.File
wg sync.WaitGroup
cond *sync.Cond // for broadcasting updates are available
mu sync.Mutex // protects lines and err
lines []string
count int // increment whenever new line gets added
@ -60,7 +60,6 @@ func NewExpectWithEnv(name string, args []string, env []string) (ep *ExpectProce
cmd: cmd,
StopSignal: syscall.SIGKILL,
}
ep.cond = sync.NewCond(&ep.mu)
ep.cmd.Stderr = ep.cmd.Stdout
ep.cmd.Stdin = nil
@ -77,52 +76,56 @@ func (ep *ExpectProcess) read() {
defer ep.wg.Done()
printDebugLines := os.Getenv("EXPECT_DEBUG") != ""
r := bufio.NewReader(ep.fpty)
for ep.err == nil {
l, rerr := r.ReadString('\n')
for {
l, err := r.ReadString('\n')
ep.mu.Lock()
ep.err = rerr
if l != "" {
if printDebugLines {
fmt.Printf("%s-%d: %s", ep.cmd.Path, ep.cmd.Process.Pid, l)
}
ep.lines = append(ep.lines, l)
ep.count++
if len(ep.lines) == 1 {
ep.cond.Signal()
}
}
if err != nil {
ep.err = err
ep.mu.Unlock()
break
}
ep.mu.Unlock()
}
ep.cond.Signal()
}
// ExpectFunc returns the first line satisfying the function f.
func (ep *ExpectProcess) ExpectFunc(f func(string) bool) (string, error) {
lastLinesBuffer := make([]string, 0)
i := 0
ep.mu.Lock()
for {
for len(ep.lines) == 0 && ep.err == nil {
ep.cond.Wait()
ep.mu.Lock()
for i < len(ep.lines) {
line := ep.lines[i]
i++
if f(line) {
ep.mu.Unlock()
return line, nil
}
}
if len(ep.lines) == 0 {
if ep.err != nil {
ep.mu.Unlock()
break
}
l := ep.lines[0]
ep.lines = ep.lines[1:]
lastLinesBuffer = append(lastLinesBuffer, l)
if l := len(lastLinesBuffer); l > DEBUG_LINES_TAIL {
lastLinesBuffer = lastLinesBuffer[l-DEBUG_LINES_TAIL : l-1]
}
if f(l) {
ep.mu.Unlock()
return l, nil
}
ep.mu.Unlock()
time.Sleep(time.Millisecond * 100)
}
ep.mu.Lock()
lastLinesIndex := len(ep.lines) - DEBUG_LINES_TAIL
if lastLinesIndex < 0 {
lastLinesIndex = 0
}
lastLines := strings.Join(ep.lines[lastLinesIndex:], "")
ep.mu.Unlock()
return "", fmt.Errorf("match not found."+
" Set EXPECT_DEBUG for more info Err: %v, last lines:\n%s",
ep.err, strings.Join(lastLinesBuffer, ""))
ep.err, lastLines)
}
// Expect returns the first line containing the given string.
@ -189,3 +192,9 @@ func (ep *ExpectProcess) ProcessError() error {
}
return ep.err
}
func (ep *ExpectProcess) Lines() []string {
ep.mu.Lock()
defer ep.mu.Unlock()
return ep.lines
}

View File

@ -190,12 +190,6 @@ func URLStringsEqual(ctx context.Context, lg *zap.Logger, a []string, b []string
}
urlsB = append(urlsB, *u)
}
if lg == nil {
lg, _ = zap.NewProduction()
if lg == nil {
lg = zap.NewExample()
}
}
return urlsEqual(ctx, lg, urlsA, urlsB)
}

View File

@ -37,17 +37,8 @@ var (
defaultDialTimeout = 3 * time.Second
defaultBufferSize = 48 * 1024
defaultRetryInterval = 10 * time.Millisecond
defaultLogger *zap.Logger
)
func init() {
var err error
defaultLogger, err = zap.NewProduction()
if err != nil {
panic(err)
}
}
// Server defines proxy server layer that simulates common network faults:
// latency spikes and packet drop or corruption. The proxy overhead is very
// small overhead (<500μs per request). Please run tests to compute actual
@ -240,9 +231,6 @@ func NewServer(cfg ServerConfig) Server {
if s.retryInterval == 0 {
s.retryInterval = defaultRetryInterval
}
if s.lg == nil {
s.lg = defaultLogger
}
close(s.pauseAcceptc)
close(s.pauseTxc)

View File

@ -355,11 +355,10 @@ func (cfg *config) parse(arguments []string) error {
func (cfg *config) configFromCmdLine() error {
// user-specified logger is not setup yet, use this logger during flag parsing
lg, err := zap.NewProduction()
lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
return err
}
verKey := "ETCD_VERSION"
if verVal := os.Getenv(verKey); verVal != "" {
// unset to avoid any possible side-effect.

View File

@ -27,6 +27,7 @@ import (
"time"
"go.etcd.io/etcd/client/pkg/v3/fileutil"
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.etcd.io/etcd/client/pkg/v3/transport"
"go.etcd.io/etcd/client/pkg/v3/types"
pkgioutil "go.etcd.io/etcd/pkg/v3/ioutil"
@ -63,7 +64,7 @@ func startEtcdOrProxyV2(args []string) {
if lg == nil {
var zapError error
// use this logger
lg, zapError = zap.NewProduction()
lg, zapError = logutil.CreateDefaultZapLogger(zap.InfoLevel)
if zapError != nil {
fmt.Printf("error creating zap logger %v", zapError)
os.Exit(1)
@ -463,6 +464,10 @@ func identifyDataDirOrDie(lg *zap.Logger, dir string) dirType {
}
func checkSupportArch() {
lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
panic(err)
}
// to add a new platform, check https://github.com/etcd-io/website/blob/main/content/en/docs/next/op-guide/supported-platform.md
if runtime.GOARCH == "amd64" ||
runtime.GOARCH == "arm64" ||
@ -474,10 +479,10 @@ func checkSupportArch() {
// so unset here to not parse through flag
defer os.Unsetenv("ETCD_UNSUPPORTED_ARCH")
if env, ok := os.LookupEnv("ETCD_UNSUPPORTED_ARCH"); ok && env == runtime.GOARCH {
fmt.Printf("running etcd on unsupported architecture %q since ETCD_UNSUPPORTED_ARCH is set\n", env)
lg.Info("running etcd on unsupported architecture since ETCD_UNSUPPORTED_ARCH is set", zap.String("arch", env))
return
}
fmt.Printf("etcd on unsupported platform without ETCD_UNSUPPORTED_ARCH=%s set\n", runtime.GOARCH)
lg.Error("running etcd on unsupported architecture since ETCD_UNSUPPORTED_ARCH is set", zap.String("arch", runtime.GOARCH))
os.Exit(1)
}

View File

@ -21,6 +21,7 @@ import (
"os"
"time"
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.etcd.io/etcd/server/v3/proxy/tcpproxy"
"github.com/spf13/cobra"
@ -92,8 +93,7 @@ func stripSchema(eps []string) []string {
}
func startGateway(cmd *cobra.Command, args []string) {
var lg *zap.Logger
lg, err := zap.NewProduction()
lg, err := logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
fmt.Fprintln(os.Stderr, err)
os.Exit(1)

View File

@ -164,16 +164,14 @@ func newGRPCProxyStartCommand() *cobra.Command {
func startGRPCProxy(cmd *cobra.Command, args []string) {
checkArgs()
lcfg := logutil.DefaultZapLoggerConfig
lvl := zap.InfoLevel
if grpcProxyDebug {
lcfg.Level = zap.NewAtomicLevelAt(zap.DebugLevel)
lvl = zap.DebugLevel
grpc.EnableTracing = true
}
lg, err := lcfg.Build()
lg, err := logutil.CreateDefaultZapLogger(lvl)
if err != nil {
log.Fatal(err)
panic(err)
}
defer lg.Sync()

View File

@ -41,9 +41,6 @@ func Main(args []string) {
}
func notifySystemd(lg *zap.Logger) {
if lg == nil {
lg = zap.NewExample()
}
lg.Info("notifying init daemon")
_, err := daemon.SdNotify(false, daemon.SdNotifyReady)
if err != nil {

View File

@ -175,6 +175,7 @@ type etcdProcessClusterConfig struct {
v2deprecation string
rollingStart bool
logLevel string
}
// newEtcdProcessCluster launches a new cluster from etcd processes, returning
@ -315,6 +316,10 @@ func (cfg *etcdProcessClusterConfig) etcdServerProcessConfigs(tb testing.TB) []*
args = append(args, "--v2-deprecation", cfg.v2deprecation)
}
if cfg.logLevel != "" {
args = append(args, "--log-level", cfg.logLevel)
}
etcdCfgs[i] = &etcdServerProcessConfig{
lg: lg,
execPath: cfg.execPath,

View File

@ -48,6 +48,8 @@ type etcdProcess interface {
type logsExpect interface {
Expect(string) (string, error)
Lines() []string
LineCount() int
}
type etcdServerProcess struct {

View File

@ -60,21 +60,15 @@ func spawnWithExpectLines(args []string, envVars map[string]string, xs ...string
// process until either stdout or stderr contains
// the expected string
var (
lines []string
lineFunc = func(txt string) bool { return true }
lines []string
)
for _, txt := range xs {
for {
l, lerr := proc.ExpectFunc(lineFunc)
if lerr != nil {
proc.Close()
return nil, fmt.Errorf("%v %v (expected %q, got %q). Try EXPECT_DEBUG=TRUE", args, lerr, txt, lines)
}
lines = append(lines, l)
if strings.Contains(l, txt) {
break
}
l, lerr := proc.Expect(txt)
if lerr != nil {
proc.Close()
return nil, fmt.Errorf("%v %v (expected %q, got %q). Try EXPECT_DEBUG=TRUE", args, lerr, txt, lines)
}
lines = append(lines, l)
}
perr := proc.Close()
l := proc.LineCount()

View File

@ -0,0 +1,76 @@
// Copyright 2022 The etcd Authors
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
//go:build !cov
// +build !cov
package e2e
import (
"encoding/json"
"testing"
"time"
)
func TestServerJsonLogging(t *testing.T) {
BeforeTest(t)
epc, err := newEtcdProcessCluster(t, &etcdProcessClusterConfig{
clusterSize: 1,
initialToken: "new",
logLevel: "debug",
})
if err != nil {
t.Fatalf("could not start etcd process cluster (%v)", err)
}
logs := epc.procs[0].Logs()
time.Sleep(time.Second)
if err = epc.Close(); err != nil {
t.Fatalf("error closing etcd processes (%v)", err)
}
var entry logEntry
lines := logs.Lines()
if len(lines) == 0 {
t.Errorf("Expected at least one log line")
}
for _, line := range lines {
err := json.Unmarshal([]byte(line), &entry)
if err != nil {
t.Errorf("Failed to parse log line as json, err: %q, line: %s", err, line)
continue
}
if entry.Level == "" {
t.Errorf(`Missing "level" key, line: %s`, line)
}
if entry.Timestamp == "" {
t.Errorf(`Missing "ts" key, line: %s`, line)
}
if _, err := time.Parse("2006-01-02T15:04:05.000Z0700", entry.Timestamp); entry.Timestamp != "" && err != nil {
t.Errorf(`Unexpected "ts" key format, err: %s`, err)
}
if entry.Caller == "" {
t.Errorf(`Missing "caller" key, line: %s`, line)
}
if entry.Message == "" {
t.Errorf(`Missing "message" key, line: %s`, line)
}
}
}
type logEntry struct {
Level string `json:"level"`
Timestamp string `json:"ts"`
Caller string `json:"caller"`
Message string `json:"msg"`
}

View File

@ -18,6 +18,7 @@ package main
import (
"flag"
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.etcd.io/etcd/tests/v3/functional/agent"
"go.uber.org/zap"
@ -27,7 +28,7 @@ var logger *zap.Logger
func init() {
var err error
logger, err = zap.NewProduction()
logger, err = logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
panic(err)
}

View File

@ -28,6 +28,7 @@ import (
"syscall"
"time"
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.etcd.io/etcd/pkg/v3/proxy"
"go.uber.org/zap"
@ -76,7 +77,11 @@ $ ./bin/etcdctl --endpoints localhost:23790 put foo bar`)
To: url.URL{Scheme: "tcp", Host: to},
}
if verbose {
cfg.Logger = zap.NewExample()
var err error
cfg.Logger, err = logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
panic(err)
}
}
p := proxy.NewServer(cfg)
<-p.Ready()

View File

@ -19,6 +19,7 @@ import (
"flag"
_ "github.com/etcd-io/gofail/runtime"
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.etcd.io/etcd/tests/v3/functional/tester"
"go.uber.org/zap"
)
@ -27,7 +28,7 @@ var logger *zap.Logger
func init() {
var err error
logger, err = zap.NewProduction()
logger, err = logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
panic(err)
}

View File

@ -19,6 +19,7 @@ import (
"sort"
"testing"
"go.etcd.io/etcd/client/pkg/v3/logutil"
"go.etcd.io/etcd/tests/v3/functional/rpcpb"
"go.uber.org/zap"
@ -256,7 +257,7 @@ func Test_read(t *testing.T) {
},
}
logger, err := zap.NewProduction()
logger, err := logutil.CreateDefaultZapLogger(zap.InfoLevel)
if err != nil {
t.Fatal(err)
}