*: improve the format of the error log (#12155) #16182

sre-bot · 2020-04-08T06:31:53Z

cherry-pick #12155 to release-3.1

Signed-off-by: nolouch nolouch@gmail.com

What problem does this PR solve?

Fix #10586

Only print stack information in FATAL level, the most of the time the stack information for error is useless.
Use ErrorVerbose to control the stack information in error message

What is changed and how it works?

Check List

Tests

Unit test
before:

[2019/09/11 16:20:46.454 +08:00] [INFO] [store.go:68] ["new store"] [path=tikv:///tmp/tidb]
[2019/09/11 16:20:46.454 +08:00] [INFO] [client.go:148] ["[pd] create pd client with endpoints"] [pd-address="[]"]
[2019/09/11 16:20:46.454 +08:00] [ERROR] [client.go:204] ["[pd] failed to get cluster id"] [error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp: missing address\""] [errorVerbose="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp: missing address\"\ngithub.com/pingcap/pd/client.(*client).getMembers\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:239\ngithub.com/pingcap/pd/client.(*client).initClusterID\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:201\ngithub.com/pingcap/pd/client.(*client).initRetry\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:188\ngithub.com/pingcap/pd/client.NewClient\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:161\ngithub.com/pingcap/tidb/store/tikv.Driver.Open\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/tikv/kv.go:80\ngithub.com/pingcap/tidb/store.newStoreWithRetry.func1\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:69\ngithub.com/pingcap/tidb/util.RunWithRetry\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/util/misc.go:46\ngithub.com/pingcap/tidb/store.newStoreWithRetry\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:67\ngithub.com/pingcap/tidb/store.New\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:51\nmain.createStoreAndDomain\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/tidb-server/main.go:235\nmain.main\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/tidb-server/main.go:176\nruntime.main\n\t/usr/local/Cellar/go/1.13/libexec/src/runtime/proc.go:203\nruntime.goexit\n\t/usr/local/Cellar/go/1.13/libexec/src/runtime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/log@v0.0.0-20190307075452-bd41d9273596/global.go:42\ngithub.com/pingcap/pd/client.(*client).initClusterID\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:204\ngithub.com/pingcap/pd/client.(*client).initRetry\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:188\ngithub.com/pingcap/pd/client.NewClient\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:161\ngithub.com/pingcap/tidb/store/tikv.Driver.Open\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/tikv/kv.go:80\ngithub.com/pingcap/tidb/store.newStoreWithRetry.func1\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:69\ngithub.com/pingcap/tidb/util.RunWithRetry\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/util/misc.go:46\ngithub.com/pingcap/tidb/store.newStoreWithRetry\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:67\ngithub.com/pingcap/tidb/store.New\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:51\nmain.createStoreAndDomain\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/tidb-server/main.go:235\nmain.main\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/tidb-server/main.go:176\nruntime.main\n\t/usr/local/Cellar/go/1.13/libexec/src/runtime/proc.go:203"]
[2019/09/11 16:20:47.460 +08:00] [ERROR] [client.go:204] ["[pd] failed to get cluster id"] [error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp: missing address\""] [errorVerbose="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp: missing address\"\ngithub.com/pingcap/pd/client.(*client).getMembers\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:239\ngithub.com/pingcap/pd/client.(*client).initClusterID\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:201\ngithub.com/pingcap/pd/client.(*client).initRetry\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:188\ngithub.com/pingcap/pd/client.NewClient\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:161\ngithub.com/pingcap/tidb/store/tikv.Driver.Open\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/tikv/kv.go:80\ngithub.com/pingcap/tidb/store.newStoreWithRetry.func1\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:69\ngithub.com/pingcap/tidb/util.RunWithRetry\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/util/misc.go:46\ngithub.com/pingcap/tidb/store.newStoreWithRetry\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:67\ngithub.com/pingcap/tidb/store.New\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:51\nmain.createStoreAndDomain\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/tidb-server/main.go:235\nmain.main\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/tidb-server/main.go:176\nruntime.main\n\t/usr/local/Cellar/go/1.13/libexec/src/runtime/proc.go:203\nruntime.goexit\n\t/usr/local/Cellar/go/1.13/libexec/src/runtime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/log@v0.0.0-20190307075452-bd41d9273596/global.go:42\ngithub.com/pingcap/pd/client.(*client).initClusterID\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:204\ngithub.com/pingcap/pd/client.(*client).initRetry\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:188\ngithub.com/pingcap/pd/client.NewClient\n\t/Users/nolouch/csn/program/go/pkg/mod/github.com/pingcap/pd@v0.0.0-20190712044914-75a1f9f3062b/client/client.go:161\ngithub.com/pingcap/tidb/store/tikv.Driver.Open\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/tikv/kv.go:80\ngithub.com/pingcap/tidb/store.newStoreWithRetry.func1\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:69\ngithub.com/pingcap/tidb/util.RunWithRetry\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/util/misc.go:46\ngithub.com/pingcap/tidb/store.newStoreWithRetry\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:67\ngithub.com/pingcap/tidb/store.New\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/store/store.go:51\nmain.createStoreAndDomain\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/tidb-server/main.go:235\nmain.main\n\t/Users/nolouch/csn/program/go/src/github.com/pingcap/tidb/tidb-server/main.go:176\nruntime.main\n\t/usr/local/Cellar/go/1.13/libexec/src/runtime/proc.go:203"]

after:

[2019/09/11 16:19:38.544 +08:00] [INFO] [store.go:68] ["new store"] [path=tikv:///tmp/tidb]
[2019/09/11 16:19:38.545 +08:00] [INFO] [client.go:148] ["[pd] create pd client with endpoints"] [pd-address="[]"]
[2019/09/11 16:19:38.549 +08:00] [ERROR] [client.go:204] ["[pd] failed to get cluster id"] [error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp: missing address\""]
[2019/09/11 16:19:39.549 +08:00] [ERROR] [client.go:204] ["[pd] failed to get cluster id"] [error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp: missing address\""]
[2019/09/11 16:19:40.550 +08:00] [ERROR] [client.go:204] ["[pd] failed to get cluster id"] [error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = \"transport: Error while dialing dial tcp: missing address\""]

Signed-off-by: sre-bot <sre-bot@pingcap.com>

sre-bot · 2020-04-08T06:31:55Z

/run-all-tests

config/config.go

Signed-off-by: nolouch <nolouch@gmail.com>

nolouch · 2020-04-09T06:02:14Z

PTAL @zimulala @lysu

zimulala

LGTM

zz-jason

LGTM

sre-bot · 2020-04-09T06:35:47Z

Your auto merge job has been accepted, waiting for 16053, 16226

sre-bot · 2020-04-09T06:44:11Z

/run-all-tests

cherry pick pingcap#12155 to release-3.1

3443e37

Signed-off-by: sre-bot <sre-bot@pingcap.com>

sre-bot mentioned this pull request Apr 8, 2020

*: improve the format of the error log #12155

Merged

sre-bot added component/util type/3.1-cherry-pick labels Apr 8, 2020

sre-bot requested review from gregwebs, lysu, zimulala and zz-jason April 8, 2020 06:31

zimulala reviewed Apr 8, 2020

View reviewed changes

config/config.go Outdated Show resolved Hide resolved

github-actions bot added the component/config label Apr 8, 2020

fix conflict

74ea79e

Signed-off-by: nolouch <nolouch@gmail.com>

zimulala reviewed Apr 9, 2020

View reviewed changes

zimulala added the status/LGT1 Indicates that a PR has LGTM 1. label Apr 9, 2020

zz-jason approved these changes Apr 9, 2020

View reviewed changes

zz-jason added status/can-merge Indicates a PR has been approved by a committer. status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Apr 9, 2020

zz-jason removed request for gregwebs and lysu April 9, 2020 06:35

Merge branch 'release-3.1' into release-3.1-cbf4ddc9e279

3e1ed38

sre-bot merged commit b2d6f52 into pingcap:release-3.1 Apr 9, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

*: improve the format of the error log (#12155) #16182

*: improve the format of the error log (#12155) #16182

sre-bot commented Apr 8, 2020

sre-bot commented Apr 8, 2020

nolouch commented Apr 9, 2020

zimulala left a comment

zz-jason left a comment

sre-bot commented Apr 9, 2020

sre-bot commented Apr 9, 2020

*: improve the format of the error log (#12155) #16182

*: improve the format of the error log (#12155) #16182

Conversation

sre-bot commented Apr 8, 2020

What problem does this PR solve?

What is changed and how it works?

Check List

sre-bot commented Apr 8, 2020

nolouch commented Apr 9, 2020

zimulala left a comment

Choose a reason for hiding this comment

zz-jason left a comment

Choose a reason for hiding this comment

sre-bot commented Apr 9, 2020

sre-bot commented Apr 9, 2020