Repository: pingcap/tiflow
Pull request #3778 (2021-12-08 02:52:55)

log(ticdc): output the zap internal errors to stderr
<!--
Thank you for contributing to TiDB-CDC! Please read MD's [CONTRIBUTING](https://github.com/pingcap/tidb-cdc/blob/master/CONTRIBUTING.md) document **BEFORE** filing this PR.
-->

### What problem does this PR solve? <!--add issue link with summary if exists-->
#3362  

### What is changed and how it works?
Use a new field `ErrorOutputPath` in log.Config to output the internal errors of zap (eg. no space left on device). See https://github.com/pingcap/log/pull/24 for more detail.

Previously, the [log lib](https://github.com/pingcap/log) used in cdc outputs the log internal errors to the same log file designated in `log.FileLogConfig.Filename`. So if the underlying disk is full, those errors are silently discarded, which makes users hard to do troubleshooting.

### Check List <!--REMOVE the items that are not applicable-->

Tests <!-- At least one of them must be included. -->

 - Unit test
 - Integration test


### Release note <!-- bugfixes or new feature need a release note -->

```release-note
None
```


ti-chi-bot: @zhaoxinyu: PR needs rebase.

<details>

Instructions for interacting with me using PR comments are available [here](https://git.k8s.io/community/contributors/guide/pull-requests.md).  If you have questions or suggestions related to my behavior, please file an issue against the [kubernetes/test-infra](https://github.com/kubernetes/test-infra/issues/new?title=Prow%20issue:) repository.
</details>
hi-rustin: /merge
ti-chi-bot: This pull request has been accepted and is ready to merge. <details>Commit hash: 9b455455a651200b8f87b01f22e7ebe2470cd85a</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: Merge canceled because a new commit is pushed.
zhaoxinyu: /merge
ti-chi-bot: @zhaoxinyu: `/merge` is only allowed for the committers, you can assign this pull request to the committer in [list](https://prow.tidb.io/tichi/repos/pingcap/tiflow/pulls/3778/owners) by filling `/assign @committer` in the comment to help merge this pull request.

<details>

In response to [this](https://github.com/pingcap/tiflow/pull/3778#issuecomment-1000113556):

>/merge


Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
zhaoxinyu: /assign @hi-rustin 
zhaoxinyu: /run-dm-integration-test

hi-rustin: /merge
ti-chi-bot: This pull request has been accepted and is ready to merge. <details>Commit hash: 78b170ab526c4205bbe5d3bd466b093cb3853dde</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>
ti-chi-bot: @zhaoxinyu: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

If the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.


<details>

Instructions for interacting with me using PR comments are available [here](https://prow.tidb.io/command-help).  If you have questions or suggestions related to my behavior, please file an issue against the [ti-community-infra/tichi](https://github.com/ti-community-infra/tichi/issues/new?title=Prow%20issue:) repository.
</details>

Patch:
diff --git a/go.mod b/go.mod
index 91b0126df..cdd829a4b 100644
--- a/go.mod
+++ b/go.mod
@@ -55,7 +55,7 @@ require (
 	github.com/pingcap/errors v0.11.5-0.20211009033009-93128226aaa3
 	github.com/pingcap/failpoint v0.0.0-20210316064728-7acb0f0a3dfd
 	github.com/pingcap/kvproto v0.0.0-20211202065422-a412f7a319c3
-	github.com/pingcap/log v0.0.0-20210906054005-afc726e70354
+	github.com/pingcap/log v0.0.0-20211207084639-71a2e5860834
 	github.com/pingcap/tidb v1.1.0-beta.0.20211209055157-9f744cdf8266
 	github.com/pingcap/tidb-tools v5.2.3-0.20211105044302-2dabb6641a6e+incompatible
 	github.com/pingcap/tidb/parser v0.0.0-20211209055157-9f744cdf8266
diff --git a/go.sum b/go.sum
index 63d5d9449..cd52f8baa 100644
--- a/go.sum
+++ b/go.sum
@@ -824,8 +824,9 @@ github.com/pingcap/log v0.0.0-20200511115504-543df19646ad/go.mod h1:4rbK1p9ILyIf
 github.com/pingcap/log v0.0.0-20201112100606-8f1e84a3abc8/go.mod h1:4rbK1p9ILyIfb6hU7OG2CiWSqMXnp3JMbiaVJ6mvoY8=
 github.com/pingcap/log v0.0.0-20210317133921-96f4fcab92a4/go.mod h1:4rbK1p9ILyIfb6hU7OG2CiWSqMXnp3JMbiaVJ6mvoY8=
 github.com/pingcap/log v0.0.0-20210625125904-98ed8e2eb1c7/go.mod h1:8AanEdAHATuRurdGxZXBz0At+9avep+ub7U1AGYLIMM=
-github.com/pingcap/log v0.0.0-20210906054005-afc726e70354 h1:SvWCbCPh1YeHd9yQLksvJYAgft6wLTY1aNG81tpyscQ=
 github.com/pingcap/log v0.0.0-20210906054005-afc726e70354/go.mod h1:DWQW5jICDR7UJh4HtxXSM20Churx4CQL0fwL/SoOSA4=
+github.com/pingcap/log v0.0.0-20211207084639-71a2e5860834 h1:/wKEagMl3KDpt7758/4Z+31yY3uxQCygOZ1xSbRXCP0=
+github.com/pingcap/log v0.0.0-20211207084639-71a2e5860834/go.mod h1:DWQW5jICDR7UJh4HtxXSM20Churx4CQL0fwL/SoOSA4=
 github.com/pingcap/parser v0.0.0-20210415081931-48e7f467fd74/go.mod h1:xZC8I7bug4GJ5KtHhgAikjTfU4kBv1Sbo3Pf1MZ6lVw=
 github.com/pingcap/parser v0.0.0-20210525032559-c37778aff307/go.mod h1:xZC8I7bug4GJ5KtHhgAikjTfU4kBv1Sbo3Pf1MZ6lVw=
 github.com/pingcap/sysutil v0.0.0-20200206130906-2bfa6dc40bcd/go.mod h1:EB/852NMQ+aRKioCpToQ94Wl7fktV+FNnxf3CX/TTXI=
diff --git a/pkg/cmd/server/server.go b/pkg/cmd/server/server.go
index ed2047091..515ed5116 100644
--- a/pkg/cmd/server/server.go
+++ b/pkg/cmd/server/server.go
@@ -91,11 +91,12 @@ func (o *options) addFlags(cmd *cobra.Command) {
 // run runs the server cmd.
 func (o *options) run(cmd *cobra.Command) error {
 	cancel := util.InitCmd(cmd, &logutil.Config{
-		File:           o.serverConfig.LogFile,
-		Level:          o.serverConfig.LogLevel,
-		FileMaxSize:    o.serverConfig.Log.File.MaxSize,
-		FileMaxDays:    o.serverConfig.Log.File.MaxDays,
-		FileMaxBackups: o.serverConfig.Log.File.MaxBackups,
+		File:                 o.serverConfig.LogFile,
+		Level:                o.serverConfig.LogLevel,
+		FileMaxSize:          o.serverConfig.Log.File.MaxSize,
+		FileMaxDays:          o.serverConfig.Log.File.MaxDays,
+		FileMaxBackups:       o.serverConfig.Log.File.MaxBackups,
+		ZapInternalErrOutput: o.serverConfig.Log.InternalErrOutput,
 	})
 	defer cancel()
 
diff --git a/pkg/config/server_config.go b/pkg/config/server_config.go
index c484c9a79..4803e8073 100644
--- a/pkg/config/server_config.go
+++ b/pkg/config/server_config.go
@@ -59,7 +59,8 @@ type LogFileConfig struct {
 
 // LogConfig represents log config for server
 type LogConfig struct {
-	File *LogFileConfig `toml:"file" json:"file"`
+	File              *LogFileConfig `toml:"file" json:"file"`
+	InternalErrOutput string         `toml:"error-output" json:"error-output"`
 }
 
 var defaultServerConfig = &ServerConfig{
@@ -73,6 +74,7 @@ var defaultServerConfig = &ServerConfig{
 			MaxDays:    0,
 			MaxBackups: 0,
 		},
+		InternalErrOutput: "stderr",
 	},
 	DataDir: "",
 	GcTTL:   24 * 60 * 60, // 24H
diff --git a/pkg/logutil/log.go b/pkg/logutil/log.go
index 4daa3eb8f..8b526b1e0 100644
--- a/pkg/logutil/log.go
+++ b/pkg/logutil/log.go
@@ -48,6 +48,8 @@ type Config struct {
 	FileMaxDays int `toml:"max-days" json:"max-days"`
 	// Maximum number of old log files to retain.
 	FileMaxBackups int `toml:"max-backups" json:"max-backups"`
+	// ZapInternalErrOutput specify where the internal error of zap logger should be send to.
+	ZapInternalErrOutput string `toml:"error-output" json:"error-output"`
 }
 
 // Adjust adjusts config
@@ -91,6 +93,7 @@ func InitLogger(cfg *Config) error {
 			MaxDays:    cfg.FileMaxDays,
 			MaxBackups: cfg.FileMaxBackups,
 		},
+		ErrorOutputPath: cfg.ZapInternalErrOutput,
 	}
 
 	var lg *zap.Logger


Test patch:
diff --git a/pkg/cmd/server/server_test.go b/pkg/cmd/server/server_test.go
index 93ab12c7b..b77d4a59a 100644
--- a/pkg/cmd/server/server_test.go
+++ b/pkg/cmd/server/server_test.go
@@ -149,6 +149,7 @@ func TestParseCfg(t *testing.T) {
 				MaxDays:    0,
 				MaxBackups: 0,
 			},
+			InternalErrOutput: "stderr",
 		},
 		DataDir:                dataDir,
 		GcTTL:                  10,
@@ -289,6 +290,7 @@ server-worker-pool-size = 16
 				MaxDays:    1,
 				MaxBackups: 1,
 			},
+			InternalErrOutput: "stderr",
 		},
 		DataDir:                dataDir,
 		GcTTL:                  500,
@@ -419,6 +421,7 @@ cert-allowed-cn = ["dd","ee"]
 				MaxDays:    1,
 				MaxBackups: 1,
 			},
+			InternalErrOutput: "stderr",
 		},
 		DataDir:                dataDir,
 		GcTTL:                  10,
diff --git a/pkg/config/config_test_data.go b/pkg/config/config_test_data.go
index 9938fd118..dbffe4ec5 100644
--- a/pkg/config/config_test_data.go
+++ b/pkg/config/config_test_data.go
@@ -78,7 +78,8 @@ const (
       "max-size": 300,
       "max-days": 0,
       "max-backups": 0
-    }
+    },
+    "error-output": "stderr"
   },
   "data-dir": "",
   "gc-ttl": 86400,
diff --git a/pkg/logutil/log_test.go b/pkg/logutil/log_test.go
index 22acf2d4e..03df34a14 100644
--- a/pkg/logutil/log_test.go
+++ b/pkg/logutil/log_test.go
@@ -15,54 +15,49 @@ package logutil
 
 import (
 	"context"
+	"fmt"
+	"io/ioutil"
+	"os"
 	"path/filepath"
 	"testing"
 
-	"github.com/pingcap/check"
 	"github.com/pingcap/errors"
 	"github.com/pingcap/log"
-	"github.com/pingcap/tiflow/pkg/util/testleak"
+	"github.com/stretchr/testify/require"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
 )
 
-func TestSuite(t *testing.T) {
-	check.TestingT(t)
-}
-
-type logSuite struct{}
-
-var _ = check.Suite(&logSuite{})
+func TestInitLoggerAndSetLogLevel(t *testing.T) {
+	f, err := ioutil.TempFile("", "init-logger-test")
+	require.Nil(t, err)
+	defer os.Remove(f.Name())
 
-func (s *logSuite) TestInitLoggerAndSetLogLevel(c *check.C) {
-	defer testleak.AfterTest(c)()
-	f := filepath.Join(c.MkDir(), "test")
 	cfg := &Config{
 		Level: "warning",
-		File:  f,
+		File:  f.Name(),
 	}
 	cfg.Adjust()
-	err := InitLogger(cfg)
-	c.Assert(err, check.IsNil)
-	c.Assert(log.GetLevel(), check.Equals, zapcore.WarnLevel)
+	err = InitLogger(cfg)
+	require.NoError(t, err)
+	require.Equal(t, log.GetLevel(), zapcore.WarnLevel)
 
 	// Set a different level.
 	err = SetLogLevel("info")
-	c.Assert(err, check.IsNil)
-	c.Assert(log.GetLevel(), check.Equals, zapcore.InfoLevel)
+	require.NoError(t, err)
+	require.Equal(t, log.GetLevel(), zapcore.InfoLevel)
 
 	// Set the same level.
 	err = SetLogLevel("info")
-	c.Assert(err, check.IsNil)
-	c.Assert(log.GetLevel(), check.Equals, zapcore.InfoLevel)
+	require.NoError(t, err)
+	require.Equal(t, log.GetLevel(), zapcore.InfoLevel)
 
 	// Set an invalid level.
 	err = SetLogLevel("badlevel")
-	c.Assert(err, check.NotNil)
+	require.Error(t, err)
 }
 
-func (s *logSuite) TestZapErrorFilter(c *check.C) {
-	defer testleak.AfterTest(c)()
+func TestZapErrorFilter(t *testing.T) {
 	var (
 		err       = errors.New("test error")
 		testCases = []struct {
@@ -79,6 +74,35 @@ func (s *logSuite) TestZapErrorFilter(c *check.C) {
 		}
 	)
 	for _, tc := range testCases {
-		c.Assert(ZapErrorFilter(tc.err, tc.filters...), check.DeepEquals, tc.expected)
+		require.Equal(t, ZapErrorFilter(tc.err, tc.filters...), tc.expected)
+	}
+}
+
+func TestZapInternalErrorOutput(t *testing.T) {
+	testCases := []struct {
+		desc      string
+		errOutput string
+		error     bool
+	}{
+		{"test valid error output path", "stderr", false},
+		{"test invalid error output path", filepath.Join(t.TempDir(), "/not-there/foo.log"), true},
+	}
+
+	dir, err := ioutil.TempDir("", "zap-error-test")
+	require.NoError(t, err)
+	defer os.RemoveAll(dir)
+	for idx, tc := range testCases {
+		f := filepath.Join(dir, fmt.Sprintf("test-file%d", idx))
+		cfg := &Config{
+			Level:                "info",
+			File:                 f,
+			ZapInternalErrOutput: tc.errOutput,
+		}
+		err = InitLogger(cfg)
+		if tc.error {
+			require.NotNil(t, err)
+		} else {
+			require.Nil(t, err)
+		}
 	}
 }