*: refine tikv/client-go log to print context information(such as conn id) as much as possible by crazycs520 · Pull Request #45559 · pingcap/tidb

crazycs520 · 2023-07-25T08:14:59Z

What problem does this PR solve?

Issue Number: close #45558

Problem Summary: refine tikv/client-go log to print context information(such as conn id) as much as possible.

What is changed and how it works?

Use Logger(ctx) instead of BgLogger as much as possible.

Since Logger(ctx) maybe contain other information such as connection id, which is good for debug.

Here are some log before this PR:

[2023/07/25 16:02:19.812 +08:00] [WARN] [region_request.go:612] ["unable to find stores with given labels"] [labels="[{\"key\":\"zone\",\"value\":\"z99\"}]"]
[2023/07/25 16:01:34.877 +08:00] [WARN] [region_request.go:1942] ["tikv reports `DataIsNotReady` retry later"] [store-id=4] [peer-id=8008] [region-id=1011] [safe-ts=443094687287869442] [ctx="region ID: 1011, meta: id:1011 start_key:\"t\\200\\000\\000\\000\\000\\000\\000`_r\\00100000000\\37700000000\\37700000000\\377051486\\000\\000\\375\\0010000-000\\3771\\000\\000\\000\\000\\000\\000\\000\\370\\003\\227s\\332eMU\\256\\350\" end_key:\"x\\000\\000\\000\" region_epoch:<conf_ver:77 version:63 > peers:<id:8006 store_id:1 > peers:<id:8007 store_id:14 > peers:<id:8008 store_id:4 > , peer: id:8008 store_id:4 , addr: 10.0.1.9:22160, idx: 0, reqStoreType: TiKvOnly, runStoreType: tikv"]
[2023/07/25 16:05:33.038 +08:00] [WARN] [backoff.go:158] ["regionMiss backoffer.maxSleep 40000ms is exceeded, errors:\nepoch_not_match:<>  at 2023-07-25T16:05:30.479434+08:00\nsend tikv request error: no available connections, ctx: region ID: 7034, meta: id:7034 start_key:\"r\\000\\000\\001\" end_key:\"t\\200\\000\\000\\000\\000\\000\\000`_r\\00100000000\\37700000000\\37700000000\\377051486\\000\\000\\375\\0010000-000\\3771\\000\\000\\000\\000\\000\\000\\000\\370\\003\\227s\\332eMU\\256\\350\" region_epoch:<conf_ver:59 version:63 > peers:<id:7035 store_id:7 > peers:<id:7036 store_id:3 > peers:<id:8002 store_id:2 > , peer: id:7036 store_id:3 , addr: 10.0.1.9:21161, idx: 0, reqStoreType: TiKvOnly, runStoreType: tikv, try next peer later at 2023-07-25T16:05:30.99473+08:00\nepoch_not_match:<>  at 2023-07-25T16:05:32.538+08:00\nlongest sleep type: tikvRPC, time: 23808ms"]

In this PR, those logs will contain conn information:

[2023/07/31 14:41:16.401 +08:00] [WARN] [region_request.go:615] ["unable to find stores with given labels"] [conn=1822425092] [region=31] [leader-invalid=false] [labels="[{\"key\":\"zone\",\"value\":\"z99\"}]"]
[2023/07/31 14:41:16.404 +08:00] [WARN] [region_request.go:2018] ["tikv reports `DataIsNotReady` retry later"] [conn=1822425092] [store-id=12] [peer-id=164] [region-id=31] [safe-ts=443229319455309828] [ctx="region ID: 31, meta: id:31 start_key:\"t\\200\\000\\000\\000\\000\\000\\000`\" end_key:\"t\\200\\000\\377\\377\\377\\377\\377\\371\" region_epoch:<conf_ver:5 version:58 > peers:<id:32 store_id:5 > peers:<id:112 store_id:1 > peers:<id:164 store_id:12 > , peer: id:164 store_id:12 , addr: 10.0.1.9:20161, idx: 0, reqStoreType: TiKvOnly, runStoreType: tikv"]
[2023/07/31 14:42:58.334 +08:00] [WARN] [backoff.go:172] ["regionMiss backoffer.maxSleep 40000ms is exceeded, errors:\nsend tikv request error: no available connections, ctx: region ID: 31, meta: id:31 start_key:\"t\\200\\000\\000\\000\\000\\000\\000`\" end_key:\"t\\200\\000\\377\\377\\377\\377\\377\\371\" region_epoch:<conf_ver:5 version:58 > peers:<id:32 store_id:5 > peers:<id:112 store_id:1 > peers:<id:164 store_id:12 > , peer: id:164 store_id:12 , addr: 10.0.1.9:20161, idx: 0, reqStoreType: TiKvOnly, runStoreType: tikv, try next peer later at 2023-07-31T14:42:53.995741+08:00\nregion_id:31, region_ver:58, store_type:tikv, peer_addr:10.0.1.9:20161, error:epoch_not_match:<>  at 2023-07-31T14:42:55.923103+08:00\nsend tikv request error: no available connections, ctx: region ID: 31, meta: id:31 start_key:\"t\\200\\000\\000\\000\\000\\000\\000`\" end_key:\"t\\200\\000\\377\\377\\377\\377\\377\\371\" region_epoch:<conf_ver:5 version:58 > peers:<id:32 store_id:5 > peers:<id:112 store_id:1 > peers:<id:164 store_id:12 > , peer: id:164 store_id:12 , addr: 10.0.1.9:20161, idx: 0, reqStoreType: TiKvOnly, runStoreType: tikv, try next peer later at 2023-07-31T14:42:56.425557+08:00\ntotal-backoff-times: 46, backoff-detail: regionMiss:23, tikvRPC:23\nlongest sleep type: tikvRPC, time: 32815ms"] [conn=1822425092]

Check List

Tests

Unit test
Integration test
Manual test (add detailed scripts or steps below)
No code

Side effects

Performance regression: Consumes more CPU
Performance regression: Consumes more Memory
Breaking backward compatibility

Documentation

Release note

Please refer to Release Notes Language Style Guide to write a quality release note.

None

…n id) as much as possible Signed-off-by: crazycs520 <crazycs520@gmail.com>

tiprow · 2023-07-25T08:15:27Z

Hi @crazycs520. Thanks for your PR.

PRs from untrusted users cannot be marked as trusted with /ok-to-test in this repo meaning untrusted PR authors can never trigger tests themselves. Collaborators can still trigger tests on the PR using /test all.

I understand the commands that are listed here.

Details

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

…client-go-log

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

ti-chi-bot · 2023-08-01T03:11:42Z

[LGTM Timeline notifier]

Timeline:

2023-08-01 02:51:35.657761854 +0000 UTC m=+153779.600110377: ☑️ agreed by ekexium.
2023-08-01 03:11:41.017832966 +0000 UTC m=+154984.960181497: ☑️ agreed by hawkingrei.

cfzjywxk · 2023-08-01T03:12:07Z

/merge

ti-chi-bot · 2023-08-01T03:12:09Z

@cfzjywxk: We have migrated to builtin LGTM and approve plugins for reviewing.

Please use /approve when you want approve this pull request.

The changes announcement: LGTM plugin changes

Details

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the ti-community-infra/tichi repository.

ti-chi-bot · 2023-08-01T03:14:50Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: cfzjywxk, ekexium, hawkingrei, MyonKeminta, you06

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Details

Needs approval from an approver in each of these files:

~~OWNERS~~ [MyonKeminta,cfzjywxk,ekexium,hawkingrei,you06]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

codecov · 2023-08-01T03:22:36Z

Codecov Report

Merging #45559 (92def41) into master (0e068ed) will increase coverage by 0.1838%.
Report is 3 commits behind head on master.
The diff coverage is 100.0000%.

Additional details and impacted files

@@               Coverage Diff                @@
##             master     #45559        +/-   ##
================================================
+ Coverage   73.2002%   73.3840%   +0.1838%     
================================================
  Files          1265       1268         +3     
  Lines        390134     391818      +1684     
================================================
+ Hits         285579     287532      +1953     
+ Misses        86238      86002       -236     
+ Partials      18317      18284        -33

Flag	Coverage Δ
integration	`78.1388% <ø> (?)`
unit	`73.3758% <100.0000%> (+0.1756%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Components	Coverage Δ
dumpling	`54.0444% <ø> (ø)`
parser	`85.0467% <ø> (+0.0108%)`	⬆️
br	`52.0368% <ø> (+0.0461%)`	⬆️

hawkingrei · 2023-08-01T04:34:02Z

/retest

crazycs520 · 2023-08-01T05:09:49Z

/test unit-test

tiprow · 2023-08-01T05:10:18Z

@crazycs520: Cannot trigger testing until a trusted user reviews the PR and leaves an /ok-to-test message.

Details

In response to this:

/test unit-test

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

crazycs520 · 2023-08-01T05:10:41Z

/ok-to-test

…n id) as much as possible (pingcap#45559) Signed-off-by: crazycs520 <crazycs520@gmail.com>

* sessionctx: add sysvar to control exp feats of replica selector Signed-off-by: zyguan <zhongyangguan@gmail.com> * *: add rpc error stats and refine log (#52810) Signed-off-by: crazycs520 <crazycs520@gmail.com> * store: refine coprocessor error log (#52729) Signed-off-by: crazycs520 <crazycs520@gmail.com> * *: improve log about stale-read query (#52494) Signed-off-by: crazycs520 <crazycs520@gmail.com> * *: refine tikv/client-go log to print context information(such as conn id) as much as possible (#45559) Signed-off-by: crazycs520 <crazycs520@gmail.com> * add leader peer id log Signed-off-by: crazycs520 <crazycs520@gmail.com> * update log Signed-off-by: crazycs520 <crazycs520@gmail.com> * executor: fix issue that some query execution stats was omitted when execution was interrupted (#51787) close #51660 Signed-off-by: crazycs520 <crazycs520@gmail.com> * update go.mod Signed-off-by: crazycs520 <crazycs520@gmail.com> --------- Signed-off-by: zyguan <zhongyangguan@gmail.com> Signed-off-by: crazycs520 <crazycs520@gmail.com> Co-authored-by: zyguan <zhongyangguan@gmail.com>

*: refine tikv/client-go log to print context information(such as con…

a1d1672

…n id) as much as possible Signed-off-by: crazycs520 <crazycs520@gmail.com>

ti-chi-bot bot added release-note-none Denotes a PR that doesn't merit a release note. size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels Jul 25, 2023

crazycs520 mentioned this pull request Jul 25, 2023

use context logger as much as possible tikv/client-go#908

Merged

crazycs520 added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Jul 25, 2023

ti-chi-bot bot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Jul 28, 2023

Merge branch 'master' of https://github.com/pingcap/tidb into refine-…

114042e

…client-go-log

ti-chi-bot bot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Jul 31, 2023

crazycs520 removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Jul 31, 2023

Merge branch 'master' of https://github.com/pingcap/tidb into refine-…

cb67c8f

…client-go-log

ekexium approved these changes Aug 1, 2023

View reviewed changes

ti-chi-bot bot added needs-1-more-lgtm Indicates a PR needs 1 more LGTM. approved labels Aug 1, 2023

make bazel_prepare

92def41

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

ti-chi-bot bot added size/S Denotes a PR that changes 10-29 lines, ignoring generated files. and removed size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels Aug 1, 2023

hawkingrei approved these changes Aug 1, 2023

View reviewed changes

ti-chi-bot bot added lgtm and removed needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Aug 1, 2023

cfzjywxk approved these changes Aug 1, 2023

View reviewed changes

you06 approved these changes Aug 1, 2023

View reviewed changes

MyonKeminta approved these changes Aug 1, 2023

View reviewed changes

ti-chi-bot bot added the ok-to-test Indicates a PR is ready to be tested. label Aug 1, 2023

ti-chi-bot bot merged commit 4220dfa into pingcap:master Aug 1, 2023

crazycs520 added a commit to crazycs520/tidb that referenced this pull request May 15, 2024

*: refine tikv/client-go log to print context information(such as con…

7c4f34a

…n id) as much as possible (pingcap#45559) Signed-off-by: crazycs520 <crazycs520@gmail.com>

crazycs520 mentioned this pull request May 21, 2024

*: add rpc error stats and refine log for diagnose #53335

Merged

13 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

*: refine tikv/client-go log to print context information(such as conn id) as much as possible#45559

*: refine tikv/client-go log to print context information(such as conn id) as much as possible#45559
ti-chi-bot[bot] merged 4 commits intopingcap:masterfrom
crazycs520:refine-client-go-log

crazycs520 commented Jul 25, 2023 •

edited

Loading

Uh oh!

tiprow bot commented Jul 25, 2023

Uh oh!

ti-chi-bot bot commented Aug 1, 2023

Uh oh!

cfzjywxk commented Aug 1, 2023

Uh oh!

ti-chi-bot bot commented Aug 1, 2023

Uh oh!

ti-chi-bot bot commented Aug 1, 2023

Uh oh!

codecov bot commented Aug 1, 2023 •

edited

Loading

Uh oh!

hawkingrei commented Aug 1, 2023

Uh oh!

crazycs520 commented Aug 1, 2023

Uh oh!

tiprow bot commented Aug 1, 2023

Uh oh!

crazycs520 commented Aug 1, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

Conversation

crazycs520 commented Jul 25, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

Uh oh!

tiprow bot commented Jul 25, 2023

Uh oh!

ti-chi-bot bot commented Aug 1, 2023

[LGTM Timeline notifier]

Uh oh!

cfzjywxk commented Aug 1, 2023

Uh oh!

ti-chi-bot bot commented Aug 1, 2023

Uh oh!

ti-chi-bot bot commented Aug 1, 2023

Uh oh!

codecov bot commented Aug 1, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

hawkingrei commented Aug 1, 2023

Uh oh!

crazycs520 commented Aug 1, 2023

Uh oh!

tiprow bot commented Aug 1, 2023

Uh oh!

crazycs520 commented Aug 1, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

crazycs520 commented Jul 25, 2023 •

edited

Loading

codecov bot commented Aug 1, 2023 •

edited

Loading