Merge pull request etcd-io#9729 from gyuho/log

*: fix capnslog journal writer with zap logger

CHANGELOG-3.4.md

@@ -171,8 +171,11 @@ See [security doc](https://github.com/coreos/etcd/blob/master/Documentation/op-g
   - **`etcd --logger=capnslog` will be deprecated in v3.5**.
   - Main motivation is to promote automated etcd monitoring, rather than looking back server logs when it starts breaking. Future development will make etcd log as few as possible, and make etcd easier to monitor with metrics and alerts.
   - e.g. `--logger=capnslog --log-outputs=default` is the default setting and same as previous etcd server logging format.
-  - e.g. `--logger=zap --log-outputs=default` will log server operations in [JSON-encoded format](https://godoc.org/go.uber.org/zap#NewProductionEncoderConfig) and writes logs to `os.Stderr`.
-  - e.g. If etcd parent process ID (`ppid`) is 1 (e.g. run with systemd), `--logger=zap --log-outputs=default` will [redirect server logs to local systemd journal](https://github.com/coreos/etcd/pull/9624) in [JSON-encoded format](https://godoc.org/go.uber.org/zap#NewProductionEncoderConfig). And if write to journald fails, it writes to `os.Stderr` as a fallback.
+  - e.g. `--logger=zap --log-outputs=default` is not supported when `--logger=zap`.
+    - Use `etcd --log-outputs=systemd/journal` to send logs to the local systemd journal.
+    - Previously, if etcd parent process ID (`ppid`) is 1 (e.g. run with systemd), `--logger=capnslog --log-outputs=default` redirects server logs to local systemd journal. And if write to journald fails, it writes to `os.Stderr` as a fallback.
+    - However, even with `ppid` 1, it can fail to dial systemd journal (e.g. run embedded etcd with Docker container). Then, [every single log write will fail](https://github.com/coreos/etcd/pull/9729) and fall back to `os.Stderr`, which is inefficient.
+    - To avoid this problem, systemd journal logging must be configured manually.
   - e.g. `--logger=zap --log-outputs=stderr` will log server operations in [JSON-encoded format](https://godoc.org/go.uber.org/zap#NewProductionEncoderConfig) and writes logs to `os.Stderr`. Use this to override journald log redirects.
   - e.g. `--logger=zap --log-outputs=stdout` will log server operations in [JSON-encoded format](https://godoc.org/go.uber.org/zap#NewProductionEncoderConfig) and writes logs to `os.Stdout` Use this to override journald log redirects.
   - e.g. `--logger=zap --log-outputs=a.log` will log server operations in [JSON-encoded format](https://godoc.org/go.uber.org/zap#NewProductionEncoderConfig) and writes logs to the specified file `a.log`.

CHANGELOG-3.5.md

@@ -13,7 +13,14 @@ See [code changes](https://github.com/coreos/etcd/compare/v3.4.0...v3.5.0) and [
   - Deprecated [`/v3beta`](https://github.com/coreos/etcd/pull/9298).
   - `curl -L http://localhost:2379/v3beta/kv/put -X POST -d '{"key": "Zm9v", "value": "YmFy"}'` does work in v3.5. Use `curl -L http://localhost:2379/v3/kv/put -X POST -d '{"key": "Zm9v", "value": "YmFy"}'` instead.
 - **`etcd --log-output` flag has been deprecated.** Use **`etcd --log-outputs`** instead.
-- **`etcd --logger=capnslog` flag has been deprecated.** Now, **`etcd --logger=zap`** is the default.
+- **`etcd --logger=zap`** is now the default.
+- **`etcd --logger=capnslog` flag has been deprecated.**
+- **`etcd --logger=zap --log-outputs=default` flag value is not supported.**.
+  - Use `etcd --log-outputs=systemd/journal` to send logs to the local systemd journal.
+  - Previously, if etcd parent process ID (`ppid`) is 1 (e.g. run with systemd), `--logger=capnslog --log-outputs=default` redirects server logs to local systemd journal. And if write to journald fails, it writes to `os.Stderr` as a fallback.
+  - However, even with `ppid` 1, it can fail to dial systemd journal (e.g. run embedded etcd with Docker container). Then, [every single log write will fail](https://github.com/coreos/etcd/pull/9729) and fall back to `os.Stderr`, which is inefficient.
+  - To avoid this problem, systemd journal logging must be configured manually.
+- **`etcd --log-outputs=stderr`** is now the default.
 - **`etcd --log-package-levels` flag for `capnslog` has been deprecated.** Now, **`etcd --logger=zap`** is the default.
 - **`[CLIENT-URL]/config/local/log` endpoint has been deprecated, as is `etcd --log-package-levels` flag.**
   - `curl http://127.0.0.1:2379/config/local/log -XPUT -d '{"Level":"DEBUG"}'` won't work.

embed/config.go

@@ -59,6 +59,9 @@ const (
 	DefaultListenClientURLs = "http://localhost:2379"
 
 	DefaultLogOutput = "default"
+	JournalLogOutput = "systemd/journal"
+	StdErrLogOutput  = "stderr"
+	StdOutLogOutput  = "stdout"
 
 	// DefaultStrictReconfigCheck is the default value for "--strict-reconfig-check" flag.
 	// It's enabled by default.

embed/config_logging.go

@@ -23,7 +23,6 @@ import (
 	"reflect"
 	"sort"
 	"sync"
-	"syscall"
 
 	"github.com/coreos/etcd/pkg/logutil"
 
@@ -112,13 +111,13 @@ func (cfg *Config) setupLogging() error {
 		// specify 'stdout' or 'stderr' to skip journald logging even when running under systemd
 		output := cfg.LogOutputs[0]
 		switch output {
-		case "stdout":
-			capnslog.SetFormatter(capnslog.NewPrettyFormatter(os.Stdout, cfg.Debug))
-		case "stderr":
+		case StdErrLogOutput:
 			capnslog.SetFormatter(capnslog.NewPrettyFormatter(os.Stderr, cfg.Debug))
+		case StdOutLogOutput:
+			capnslog.SetFormatter(capnslog.NewPrettyFormatter(os.Stdout, cfg.Debug))
 		case DefaultLogOutput:
 		default:
-			plog.Panicf(`unknown log-output %q (only supports %q, "stdout", "stderr")`, output, DefaultLogOutput)
+			plog.Panicf(`unknown log-output %q (only supports %q, %q, %q)`, output, DefaultLogOutput, StdErrLogOutput, StdOutLogOutput)
 		}
 
 	case "zap":
@@ -147,38 +146,32 @@ func (cfg *Config) setupLogging() error {
 			OutputPaths:      make([]string, 0),
 			ErrorOutputPaths: make([]string, 0),
 		}
+
 		outputPaths, errOutputPaths := make(map[string]struct{}), make(map[string]struct{})
-		isJournald := false
+		isJournal := false
 		for _, v := range cfg.LogOutputs {
 			switch v {
 			case DefaultLogOutput:
-				if syscall.Getppid() == 1 {
-					// capnslog initially SetFormatter(NewDefaultFormatter(os.Stderr))
-					// where "NewDefaultFormatter" returns "NewJournaldFormatter"
-					// specify 'stdout' or 'stderr' to override this redirects
-					// when syscall.Getppid() == 1
-					isJournald = true
-					break
-				}
+				return errors.New("'--log-outputs=default' is not supported for v3.4 during zap logger migraion (use 'journal', 'stderr', 'stdout', etc.)")
 
-				outputPaths["stderr"] = struct{}{}
-				errOutputPaths["stderr"] = struct{}{}
+			case JournalLogOutput:
+				isJournal = true
 
-			case "stderr":
-				outputPaths["stderr"] = struct{}{}
-				errOutputPaths["stderr"] = struct{}{}
+			case StdErrLogOutput:
+				outputPaths[StdErrLogOutput] = struct{}{}
+				errOutputPaths[StdErrLogOutput] = struct{}{}
 
-			case "stdout":
-				outputPaths["stdout"] = struct{}{}
-				errOutputPaths["stdout"] = struct{}{}
+			case StdOutLogOutput:
+				outputPaths[StdOutLogOutput] = struct{}{}
+				errOutputPaths[StdOutLogOutput] = struct{}{}
 
 			default:
 				outputPaths[v] = struct{}{}
 				errOutputPaths[v] = struct{}{}
 			}
 		}
 
-		if !isJournald {
+		if !isJournal {
 			for v := range outputPaths {
 				lcfg.OutputPaths = append(lcfg.OutputPaths, v)
 			}
@@ -219,13 +212,17 @@ func (cfg *Config) setupLogging() error {
 			if len(cfg.LogOutputs) > 1 {
 				for _, v := range cfg.LogOutputs {
 					if v != DefaultLogOutput {
-						return fmt.Errorf("running as a systemd unit but other '--log-output' values (%q) are configured with 'default'; override 'default' value with something else", cfg.LogOutputs)
+						return fmt.Errorf("running with systemd/journal but other '--log-outputs' values (%q) are configured with 'default'; override 'default' value with something else", cfg.LogOutputs)
 					}
 				}
 			}
 
 			// use stderr as fallback
-			syncer := getZapWriteSyncer()
+			syncer, lerr := getJournalWriteSyncer()
+			if lerr != nil {
+				return lerr
+			}
+
 			lvl := zap.NewAtomicLevelAt(zap.InfoLevel)
 			if cfg.Debug {
 				lvl = zap.NewAtomicLevelAt(zap.DebugLevel)

embed/config_logging_journald_unix.go → embed/config_logging_journal_unix.go

@@ -17,6 +17,7 @@
 package embed
 
 import (
+	"fmt"
 	"os"
 
 	"github.com/coreos/etcd/pkg/logutil"
@@ -25,6 +26,10 @@ import (
 )
 
 // use stderr as fallback
-func getZapWriteSyncer() zapcore.WriteSyncer {
-	return zapcore.AddSync(logutil.NewJournaldWriter(os.Stderr))
+func getJournalWriteSyncer() (zapcore.WriteSyncer, error) {
+	jw, err := logutil.NewJournalWriter(os.Stderr)
+	if err != nil {
+		return nil, fmt.Errorf("can't find journal (%v)", err)
+	}
+	return zapcore.AddSync(jw), nil
 }

embed/config_logging_journald_windows.go → embed/config_logging_journal_windows.go

@@ -22,6 +22,6 @@ import (
 	"go.uber.org/zap/zapcore"
 )
 
-func getZapWriteSyncer() zapcore.WriteSyncer {
-	return zapcore.AddSync(os.Stderr)
+func getJournalWriteSyncer() (zapcore.WriteSyncer, error) {
+	return zapcore.AddSync(os.Stderr), nil
 }

integration/embed_test.go

@@ -55,7 +55,6 @@ func TestEmbedEtcd(t *testing.T) {
 		tests[i].cfg.Logger = "zap"
 		tests[i].cfg.LogOutputs = []string{"/dev/null"}
 		tests[i].cfg.Debug = false
-
 	}
 
 	tests[0].cfg.Durl = "abc"

pkg/logutil/zap_journald.go → pkg/logutil/zap_journal.go

@@ -24,20 +24,22 @@ import (
 	"os"
 	"path/filepath"
 
+	"github.com/coreos/etcd/pkg/systemd"
+
 	"github.com/coreos/go-systemd/journal"
 	"go.uber.org/zap/zapcore"
 )
 
-// NewJournaldWriter wraps "io.Writer" to redirect log output
+// NewJournalWriter wraps "io.Writer" to redirect log output
 // to the local systemd journal. If journald send fails, it fails
 // back to writing to the original writer.
 // The decode overhead is only <30µs per write.
 // Reference: https://github.com/coreos/pkg/blob/master/capnslog/journald_formatter.go
-func NewJournaldWriter(wr io.Writer) io.Writer {
-	return &journaldWriter{Writer: wr}
+func NewJournalWriter(wr io.Writer) (io.Writer, error) {
+	return &journalWriter{Writer: wr}, systemd.DialJournal()
 }
 
-type journaldWriter struct {
+type journalWriter struct {
 	io.Writer
 }
 
@@ -48,7 +50,7 @@ type logLine struct {
 	Caller string `json:"caller"`
 }
 
-func (w *journaldWriter) Write(p []byte) (int, error) {
+func (w *journalWriter) Write(p []byte) (int, error) {
 	line := &logLine{}
 	if err := json.NewDecoder(bytes.NewReader(p)).Decode(line); err != nil {
 		return 0, err
@@ -82,6 +84,8 @@ func (w *journaldWriter) Write(p []byte) (int, error) {
 		"SYSLOG_IDENTIFIER": filepath.Base(os.Args[0]),
 	})
 	if err != nil {
+		// "journal" also falls back to stderr
+		// "fmt.Fprintln(os.Stderr, s)"
 		return w.Writer.Write(p)
 	}
 	return 0, nil

pkg/logutil/zap_journald_test.go → pkg/logutil/zap_journal_test.go

@@ -24,9 +24,15 @@ import (
 	"go.uber.org/zap/zapcore"
 )
 
-func TestNewJournaldWriter(t *testing.T) {
+func TestNewJournalWriter(t *testing.T) {
 	buf := bytes.NewBuffer(nil)
-	syncer := zapcore.AddSync(NewJournaldWriter(buf))
+	jw, err := NewJournalWriter(buf)
+	if err != nil {
+		t.Skip(err)
+	}
+
+	syncer := zapcore.AddSync(jw)
+
 	cr := zapcore.NewCore(
 		zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()),
 		syncer,
@@ -36,7 +42,7 @@ func TestNewJournaldWriter(t *testing.T) {
 	lg := zap.New(cr, zap.AddCaller(), zap.ErrorOutput(syncer))
 	defer lg.Sync()
 
-	lg.Info("TestNewJournaldWriter")
+	lg.Info("TestNewJournalWriter")
 	if buf.String() == "" {
 		// check with "journalctl -f"
 		t.Log("sent logs successfully to journald")

pkg/systemd/doc.go

@@ -0,0 +1,16 @@
+// Copyright 2018 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.
+
+// Package systemd provides utility functions for systemd.
+package systemd

pkg/systemd/journal.go

@@ -0,0 +1,29 @@
+// Copyright 2018 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.
+
+package systemd
+
+import "net"
+
+// DialJournal returns no error if the process can dial journal socket.
+// Returns an error if dial failed, whichi indicates journald is not available
+// (e.g. run embedded etcd as docker daemon).
+// Reference: https://github.com/coreos/go-systemd/blob/master/journal/journal.go.
+func DialJournal() error {
+	conn, err := net.Dial("unixgram", "/run/systemd/journal/socket")
+	if conn != nil {
+		defer conn.Close()
+	}
+	return err
+}