Structured log: replace ngaut/log with logrus #612

andelf · 2017-04-11T18:24:49Z

Changes:

vendor: logrus for structured log
vendor: lumberjack for logrotate
server/util: additional wrapper, to make log format consistent

review link: https://github.com/pingcap/pd/pull/612/files/18ba74fb8628ad0c7f1b75b70af8724bc3ba8840..b99587ae691568efde81b68572e688bac8827fa5 (without vendor changes)

siddontang · 2017-04-12T01:22:23Z

server/util.go

+	for i := 0; i < cnt; i++ {
+		fu := runtime.FuncForPC(pc[i] - 1)
+		name := fu.Name()
+		if !strings.Contains(name, "github.com/Sirupsen/logrus") &&


extract the contain check to a function

how about a separate variable

you mean defining a table variable for these?

for standalone sub-package, a function is ok.
for mess up with server/util.go, another function may not be acceptable.

never mind 😹

siddontang · 2017-04-12T01:25:37Z

I think we should move the log to pkg logutil package. PD client may use this later.

Btw, please add test for it.

andelf · 2017-04-12T03:01:26Z

"move the log to pkg logutil package" is #602 😹

For that log setting up depends on Config, there will be a circular reference between logutil and server.

😞

siddontang · 2017-04-12T03:16:16Z

You can define a LogConfig for the log, and then embed it into ServerConfig. This can decouple the logic.

siddontang · 2017-04-12T03:20:34Z

server/util.go

+	} else {
+		b = &bytes.Buffer{}
+	}
+	b.WriteString(entry.Time.Format("2006/01/02 15:04:05"))


define a const var for the time format

siddontang · 2017-04-12T03:25:15Z

server/util.go

+	}
+	b.WriteString(entry.Time.Format("2006/01/02 15:04:05"))
+	if file, ok := entry.Data["file"]; ok {
+		b.WriteString(fmt.Sprintf(" %s:%v:", file, entry.Data["line"]))


seem you can use fmt.Fprintf(b, format, args...) directly to reduce the allocation cost for fmt.Sprintf?

andelf · 2017-04-12T03:33:43Z

LogConfig comes up with [log], may be done with #459 .

andelf · 2017-04-12T05:37:00Z

Update:

isolated sub-package pkg/logutil
logutil.LogConfig embedded in server.Config
tests

Incompatible Changes:

pd.toml: [log] section

andelf · 2017-04-12T05:38:38Z

review link:
https://github.com/pingcap/pd/pull/612/files/18ba74fb8628ad0c7f1b75b70af8724bc3ba8840..ddf4e8a0401d2bf41931e165c2b0384fde1cb794

siddontang · 2017-04-12T05:49:27Z

server/config.go

@@ -56,10 +57,8 @@ type Config struct {
 	// Etcd onlys support seoncds TTL, so here is second too.
 	LeaderLease int64 `toml:"lease" json:"lease"`

-	// Log level.
-	LogLevel string `toml:"log-level" json:"log-level"`


seem this can cause compatibility

Any other package references pd/server?

users have to change their config after updating. We should avoid this.

For Ansible deployment log-level is specified via command line argument: https://github.com/pingcap/tidb-ansible/blob/master/roles/pd/templates/run_pd.sh.j2

Shall we add a migration support for backward compatibility?

Not only for ansible, some users deploy manually. As far as I know, we have only one user who deploys manually, so we should help him changing the config before updating.

The default behavior is not changed. Only matters when a user changes default log level or specifies log file path in pd.toml .

siddontang · 2017-04-12T06:16:06Z

conf/config.toml

 tso-save-interval = "3s"

+[log]
+log-level = "info"


no need log-file here?

previously, log-file is always specified via command line arguments.

should add it but comment here.

siddontang · 2017-04-12T06:26:05Z

pkg/logutil/log.go

+// Fire implements logrus.Hook interface
+// https://github.com/sirupsen/logrus/issues/63
+func (hook *contextHook) Fire(entry *log.Entry) error {
+	pc := make([]uintptr, 3, 3)


make([]uinptr, 3) is enough.

siddontang · 2017-04-12T06:26:41Z

pkg/logutil/log.go

+func (rf *redirectFormatter) Flush() {}
+
+// isSKippedPackageName tests wether path name is on log library calling stack.
+func isSkippedPackageName(name string) bool {


add a simple test for this function

meaningless to add tests for such stupid library function calls.
Or else I'll make it a variable before if condition.

btw: coverage already covers this.

If we only cover "github.com/Sirupsen/logrus" but miss "github.com/coreos/pkg/capnslog", how do we know it, at run time?

log_test.go checks against "log.go"(all capnslog) and "log_test.go".

It is nonintuitive. Please test it explicitly.

siddontang · 2017-04-12T06:30:03Z

Rest LGTM

…pd into structured-log-stage1-use-logrus

siddontang · 2017-04-13T05:42:54Z

conf/config.toml

@@ -18,7 +18,8 @@ lease = 3
 tso-save-interval = "3s"

 [log]
-log-level = "info"
+level = "info"


do we need to update ansible now?

leave it what it is now

siddontang · 2017-04-14T01:41:41Z

PTAL @disksing

siddontang · 2017-04-14T01:50:48Z

pkg/logutil/log_test.go

+	entry, err = s.buf.ReadString('\n')
+	c.Assert(err, IsNil)
+	c.Assert(entry, Matches, logPattern)
+	c.Assert(strings.Contains(entry, thisFilename), IsTrue)


can use "log_test.go" here directly.

disksing · 2017-04-14T08:34:21Z

pkg/logutil/log.go

+	case "warn":
+		return log.WarnLevel
+	case "warning":
+		return log.WarnLevel


case "warn", "warning":

disksing · 2017-04-14T08:35:19Z

pkg/logutil/log.go

+	// trim square brackets
+	if len(logStr) > 2 && logStr[0] == '[' {
+		logStr = logStr[1 : len(logStr)-1]
+	}


When will it starts with '['? And the last char will always be ']' if first is '['?

All logs from etcd are wrapped in [] pairs. and yes.

disksing · 2017-04-14T08:35:54Z

pkg/logutil/log.go

+	case capnslog.DEBUG:
+		log.Debugf(logStr)
+	case capnslog.TRACE:
+		log.Debugf(logStr)


case sapnslog.DEBUG, sapnslog.TRACE:

disksing · 2017-04-14T08:42:55Z

pkg/logutil/log.go

+		if k != "file" && k != "line" {
+			fmt.Fprintf(b, " %v=%v", k, entry.Data[k])
+		}
+	}


how about for k, v := range entry.Data?

andelf · 2017-04-14T11:04:21Z

+Update: add backward compatibility check + warning

disksing · 2017-04-14T12:26:42Z

server/config.go

@@ -175,6 +182,19 @@ func (c *Config) Parse(arguments []string) error {
 		if err != nil {
 			return errors.Trace(err)
 		}
+
+		// Backward compatibility for toml config
+		fmt.Printf("fuck %+v\n", c)


siddontang · 2017-04-17T13:23:28Z

server/config.go

+		if c.LogFileDeprecated != "" && c.Log.Filename == "" {
+			c.Log.Filename = c.LogFileDeprecated
+			msg := fmt.Sprintf("log-file in %s is deprecated, use [log] instead", c.configFile)
+			c.WarningMsgs = append(c.WarningMsgs, msg)


output the warning message here directly

Should be logged after logger is initialized. :)

How about returning warning messages as []string and log them afterwards?

returning the warning message seems better.

any update?

Current implementation is OK for future planning.
config.Parse(), logutil.InitLogger() may all update warning messages.

siddontang · 2017-04-17T13:24:29Z

pkg/logutil/log.go

+	return log.AllLevels
+}
+
+func stringToLogLevel(level string) log.Level {


add test to cover all the conditions.

siddontang · 2017-04-17T13:49:36Z

server/config.go

@@ -85,6 +88,9 @@ type Config struct {
 	electionMs uint64

 	configFile string
+
+	// For all warnings during parsing.
+	WarningMsgs []string


/WarningMsgs/warningMsgs/s

public field here

Got it, but can we use a function to do this? exporting fields seems strange.

GetWarningMsgs() 🤣

LogWarningMsgs

ugly and export a meaningless function with side effect.

Exporting WarningMsg is too, what is the WarningMsgs for? what I first see is that there is a WarningMsg config.

siddontang · 2017-04-21T13:43:34Z

pkg/logutil/log_test.go

@@ -41,6 +41,16 @@ func (s *testLogSuite) SetUpSuite(c *C) {
 	s.buf = &bytes.Buffer{}
 }

+func (s *testLogSuite) TestStringToLogLevel(c *C) {
+	c.Assert(stringToLogLevel("fatal"), Equals, log.FatalLevel)


you can use table-driven test here.

let tt = []struct { name string level Level } { {"ERROR", log.ErrorLevel}, ... } for _, t := range tt { c.Assert() }

siddontang · 2017-04-21T13:44:01Z

Rest LGTM

PTAL @disksing @nolouch

ngaut · 2017-04-22T03:46:56Z

LGTM

siddontang · 2017-04-23T23:58:09Z

LGTM

PTAL @disksing

shenli · 2017-04-24T00:01:18Z

Should we also do this in tidb repo?
/cc @coocood @tiancaiamao

disksing · 2017-04-24T02:02:48Z

LGTM.

andelf · 2017-04-24T05:56:34Z

I'll fix circleCI status.

…e1-use-logrus

andelf added 3 commits April 12, 2017 02:08

vendor: prepare vendor for logrus

18ba74f

*: replace ngaut/log with logrus

b9be636

server/util: fix typo

b99587a

andelf force-pushed the structured-log-stage1-use-logrus branch from 97fca69 to b99587a Compare April 11, 2017 18:33

siddontang reviewed Apr 12, 2017

View reviewed changes

andelf added 3 commits April 12, 2017 11:56

server/util: address commit

de7eb72

*: isolate logutil subpackage

7e82d84

pkg/logutil: add testcase

ddf4e8a

andelf requested review from overvenus and nolouch April 12, 2017 05:35

siddontang reviewed Apr 12, 2017

View reviewed changes

siddontang approved these changes Apr 12, 2017

View reviewed changes

andelf and others added 5 commits April 12, 2017 17:58

*: minor fix, robust error handling

f398ee5

Merge branch 'master' into structured-log-stage1-use-logrus

909b94c

pkg/logutil: add filename check test

f82f062

conf: log config

805fa46

Merge branch 'structured-log-stage1-use-logrus' of github.com:andelf/…

025e7c6

…pd into structured-log-stage1-use-logrus

siddontang reviewed Apr 13, 2017

View reviewed changes

siddontang reviewed Apr 14, 2017

View reviewed changes

disksing reviewed Apr 14, 2017

View reviewed changes

andelf added 2 commits April 14, 2017 18:55

*: fix log config backward compatibility

59c005e

*: address comment

a980205

disksing reviewed Apr 14, 2017

View reviewed changes

config: fix debug print

376c8f0

siddontang reviewed Apr 17, 2017

View reviewed changes

andelf added 2 commits April 18, 2017 14:03

pkg/logutil: remove trim square bracket

2013cfa

pkg/logutil: add tests

7bb9555

siddontang reviewed Apr 21, 2017

View reviewed changes

Merge branch 'master' into structured-log-stage1-use-logrus

37a41ad

siddontang approved these changes Apr 23, 2017

View reviewed changes

andelf added 2 commits April 24, 2017 14:39

pkg/logutil: isolate file log config

acabc9b

ci: fix circle-ci under forked projects

6144c5c

andelf mentioned this pull request Apr 24, 2017

circleci: fix bad gopath under forked project #624

Merged

andelf added 2 commits April 24, 2017 15:19

Merge remote-tracking branch 'origin/master' into structured-log-stag…

96fa7d6

…e1-use-logrus

merge origin/master

2f600b8

siddontang merged commit 4d52abb into tikv:master Apr 24, 2017

andelf deleted the structured-log-stage1-use-logrus branch April 24, 2017 13:03

sre-bot added the contribution This PR is from a community contributor. label Dec 18, 2019

Structured log: replace ngaut/log with logrus #612

Structured log: replace ngaut/log with logrus #612

Conversation

andelf commented Apr 11, 2017 • edited Loading

Choose a reason for hiding this comment

andelf Apr 12, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

siddontang commented Apr 12, 2017

andelf commented Apr 12, 2017

siddontang commented Apr 12, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andelf commented Apr 12, 2017

andelf commented Apr 12, 2017

andelf commented Apr 12, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

siddontang Apr 13, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

siddontang commented Apr 12, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

siddontang commented Apr 14, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andelf commented Apr 14, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

siddontang commented Apr 21, 2017

ngaut commented Apr 22, 2017

siddontang commented Apr 23, 2017

shenli commented Apr 24, 2017

disksing commented Apr 24, 2017

andelf commented Apr 24, 2017

andelf commented Apr 11, 2017 •

edited

Loading

andelf Apr 12, 2017 •

edited

Loading

siddontang Apr 13, 2017 •

edited

Loading