util/logutil: migrate to testify #26322

ofey404 · 2021-07-18T16:12:56Z

What problem does this PR solve?

Issue Number: close #26154

What is changed and how it works?

What's Changed: Removed pingcap/check for utils/logutil, moved to testify.

Release note

No release note

CLAassistant · 2021-07-18T16:13:01Z

All committers have signed the CLA.

ti-srebot · 2021-07-18T16:13:29Z

No release note, Please follow https://github.com/pingcap/community/blob/master/contributors/release-note-checker.md

ofey404 · 2021-07-18T16:18:08Z

There are several places I redefine variable assert:

assert := assert.New(s.T())

It will trigger a warning of goland, but the documentation of testify do so. If I redefine the variable to something else like a, it may harm the readability(a.NotNil(xxxxxx) balabala...).

Which way is more proper?

ofey404 · 2021-07-18T16:38:39Z

About the CI failure:

[2021-07-18T16:26:25.316Z] ./tools/check/check_testSuite.sh
[2021-07-18T16:26:25.885Z] testHexSuite in ./util/logutil is not enabled
[2021-07-18T16:26:25.885Z] testLogSuite in ./util/logutil is not enabled

I checked ./tools/check/check_testSuite.sh, it may be some naming collision with previous definition of test suites.

Maybe I shouldn't use the same name as the original suite, would HexTestSuite and LogTestSuite be better?

tisonkun · 2021-07-18T16:44:19Z

Thanks for submitting this PR @ofey404 . You may take a looks at this comment #26318 (comment) and we'd better avoid suite usage of testify.

The check script is for gocheck test-infra, you may modify it, work around it, or remove it if necessary. But since suite of testify suffers #26082 (comment), you may think of avoiding it.

tisonkun · 2021-07-18T16:45:44Z

Also, c.Assert fails fast when assertion fails, it equals to require in testify, not assert.

ofey404 · 2021-07-19T15:39:51Z

There is a buffer seems never used in the test, except in SetUpSuite and SetUpTest. What does it do?

In current commit I just simply remove it, but I'm not quite sure if it's OK to do so.

ofey404 · 2021-07-19T15:48:18Z

The test has some goroutine leak, I'm finding out where it is.

tisonkun · 2021-07-19T16:13:15Z

@ofey404 I've created a patch for you tisonkun@852979f that you can make use of.

Today I updated some notes about best practices when migrating tests #26022 , which you may take a look at.

tisonkun · 2021-07-19T16:14:54Z

"gopkg.in/natefinch/lumberjack%2ev2.(*Logger).millRun" is a known un-clean-up goroutine that you can find in util/testleak/leaktest.go

ofey404 · 2021-07-19T16:29:10Z

@ofey404 I've created a patch for you tisonkun@852979f that you can make use of.

Today I updated some notes about best practices when migrating tests #26022 , which you may take a look at.

Thank you very much! I know this is gonna sound really stupid, but how can I make use of this patch? It looks similar to what I've commit...

ofey404 · 2021-07-19T16:51:40Z

Oh! I understand what happened!

tisonkun · 2021-07-20T01:45:13Z

@ofey404 thanks for your updates! I provide the patch for I think code express quickly :P

tisonkun

LGTM

ti-chi-bot · 2021-07-20T01:46:12Z

@tisonkun: Thanks for your review. The bot only counts approvals from reviewers and higher roles in list, but you're still welcome to leave your comments.

In response to this:

LGTM

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 · 2021-07-20T13:19:23Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

tiancaiamao
xhebox

To complete the pull request process, please ask the reviewers in the list to review by filling /cc @reviewer in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the list by filling /assign @committer in the comment to help you merge this pull request.

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

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.

ti-chi-bot · 2021-07-20T13:19:35Z

This pull request has been accepted and is ready to merge.

Commit hash: c987ef2

ofey404 · 2021-07-20T15:31:43Z

About the unit test failure, what should I do?

[2021-07-20T15:22:47.401Z] ok  	github.com/pingcap/tidb/expression/aggregation	(cached)

[2021-07-20T15:22:47.401Z] FAIL

tisonkun · 2021-07-20T15:32:54Z

/run-all-tests

tisonkun · 2021-07-20T15:34:14Z

@ofey404 it seems one of unstable tests that should not be caused by this pull request. You can take a look at #25899 to see if it is a known unstable test, and if not, report it. We will retrigger tests and moving the merging phase.

tisonkun · 2021-07-20T15:37:42Z

/merge

ti-chi-bot · 2021-07-20T15:37:44Z

@tisonkun: /merge is only allowed for the committers, you can assign this pull request to the committer in list by filling /assign @committer in the comment to help merge this pull request.

In response to this:

/merge

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.

tisonkun · 2021-07-20T15:47:46Z

/run-unit-test

tisonkun · 2021-07-21T01:57:34Z

/run-unit-test

tisonkun · 2021-07-21T02:11:38Z

[2021-07-21T01:59:57.394Z] ==================
[2021-07-21T01:59:57.394Z] WARNING: DATA RACE
[2021-07-21T01:59:57.394Z] Write at 0x0000020fb3a0 by goroutine 14:
[2021-07-21T01:59:57.394Z]   google.golang.org/grpc/grpclog.SetLoggerV2()
[2021-07-21T01:59:57.395Z]       /nfs/cache/mod/google.golang.org/[email protected]/grpclog/loggerv2.go:68 +0x1fa
[2021-07-21T01:59:57.395Z]   github.com/grpc-ecosystem/go-grpc-middleware/logging/zap.ReplaceGrpcLoggerV2WithVerbosity()
[2021-07-21T01:59:57.395Z]       /nfs/cache/mod/github.com/grpc-ecosystem/[email protected]/logging/zap/grpclogger.go:60 +0x1ea
[2021-07-21T01:59:57.395Z]   github.com/grpc-ecosystem/go-grpc-middleware/logging/zap.ReplaceGrpcLoggerV2()
[2021-07-21T01:59:57.395Z]       /nfs/cache/mod/github.com/grpc-ecosystem/[email protected]/logging/zap/grpclogger.go:51 +0x1dc
[2021-07-21T01:59:57.395Z]   github.com/pingcap/tidb/util/logutil.InitLogger()
[2021-07-21T01:59:57.395Z]       /home/jenkins/agent/workspace/tidb_ghpr_unit_test/go/src/github.com/pingcap/tidb/util/logutil/log.go:119 +0x1c5
[2021-07-21T01:59:57.395Z]   github.com/pingcap/tidb/util/logutil.TestZapLoggerWithKeys()
[2021-07-21T01:59:57.395Z]       /home/jenkins/agent/workspace/tidb_ghpr_unit_test/go/src/github.com/pingcap/tidb/util/logutil/log_test.go:41 +0x15a
[2021-07-21T01:59:57.395Z]   testing.tRunner()
[2021-07-21T01:59:57.395Z]       /usr/local/go/src/testing/testing.go:1193 +0x202
[2021-07-21T01:59:57.395Z] 
[2021-07-21T01:59:57.395Z] Previous write at 0x0000020fb3a0 by goroutine 15:
[2021-07-21T01:59:57.395Z]   google.golang.org/grpc/grpclog.SetLoggerV2()
[2021-07-21T01:59:57.395Z]       /nfs/cache/mod/google.golang.org/[email protected]/grpclog/loggerv2.go:68 +0x1fa
[2021-07-21T01:59:57.395Z]   github.com/grpc-ecosystem/go-grpc-middleware/logging/zap.ReplaceGrpcLoggerV2WithVerbosity()
[2021-07-21T01:59:57.395Z]       /nfs/cache/mod/github.com/grpc-ecosystem/[email protected]/logging/zap/grpclogger.go:60 +0x1ea
[2021-07-21T01:59:57.395Z]   github.com/grpc-ecosystem/go-grpc-middleware/logging/zap.ReplaceGrpcLoggerV2()
[2021-07-21T01:59:57.395Z]       /nfs/cache/mod/github.com/grpc-ecosystem/[email protected]/logging/zap/grpclogger.go:51 +0x1dc
[2021-07-21T01:59:57.395Z]   github.com/pingcap/tidb/util/logutil.InitLogger()
[2021-07-21T01:59:57.395Z]       /home/jenkins/agent/workspace/tidb_ghpr_unit_test/go/src/github.com/pingcap/tidb/util/logutil/log.go:119 +0x1c5
[2021-07-21T01:59:57.395Z]   github.com/pingcap/tidb/util/logutil.TestSetLevel()
[2021-07-21T01:59:57.395Z]       /home/jenkins/agent/workspace/tidb_ghpr_unit_test/go/src/github.com/pingcap/tidb/util/logutil/log_test.go:90 +0x119
[2021-07-21T01:59:57.395Z]   testing.tRunner()
[2021-07-21T01:59:57.395Z]       /usr/local/go/src/testing/testing.go:1193 +0x202
[2021-07-21T01:59:57.395Z] 
[2021-07-21T01:59:57.395Z] Goroutine 14 (running) created at:
[2021-07-21T01:59:57.395Z]   testing.(*T).Run()
[2021-07-21T01:59:57.395Z]       /usr/local/go/src/testing/testing.go:1238 +0x5d7
[2021-07-21T01:59:57.395Z]   testing.runTests.func1()
[2021-07-21T01:59:57.395Z]       /usr/local/go/src/testing/testing.go:1511 +0xa6
[2021-07-21T01:59:57.395Z]   testing.tRunner()
[2021-07-21T01:59:57.395Z]       /usr/local/go/src/testing/testing.go:1193 +0x202
[2021-07-21T01:59:57.395Z]   testing.runTests()
[2021-07-21T01:59:57.395Z]       /usr/local/go/src/testing/testing.go:1509 +0x612
[2021-07-21T01:59:57.396Z]   testing.(*M).Run()
[2021-07-21T01:59:57.396Z]       /usr/local/go/src/testing/testing.go:1417 +0x3b3
[2021-07-21T01:59:57.396Z]   go.uber.org/goleak.VerifyTestMain()
[2021-07-21T01:59:57.396Z]       /nfs/cache/mod/go.uber.org/[email protected]/testmain.go:53 +0x5e
[2021-07-21T01:59:57.396Z]   github.com/pingcap/tidb/util/logutil.TestMain()
[2021-07-21T01:59:57.396Z]       /home/jenkins/agent/workspace/tidb_ghpr_unit_test/go/src/github.com/pingcap/tidb/util/logutil/main_test.go:40 +0x9e
[2021-07-21T01:59:57.396Z]   main.main()
[2021-07-21T01:59:57.396Z]       _testmain.go:53 +0x271
[2021-07-21T01:59:57.396Z] 
[2021-07-21T01:59:57.396Z] Goroutine 15 (running) created at:
[2021-07-21T01:59:57.396Z]   testing.(*T).Run()
[2021-07-21T01:59:57.396Z]       /usr/local/go/src/testing/testing.go:1238 +0x5d7
[2021-07-21T01:59:57.396Z]   testing.runTests.func1()
[2021-07-21T01:59:57.396Z]       /usr/local/go/src/testing/testing.go:1511 +0xa6
[2021-07-21T01:59:57.396Z]   testing.tRunner()
[2021-07-21T01:59:57.396Z]       /usr/local/go/src/testing/testing.go:1193 +0x202
[2021-07-21T01:59:57.396Z]   testing.runTests()
[2021-07-21T01:59:57.396Z]       /usr/local/go/src/testing/testing.go:1509 +0x612
[2021-07-21T01:59:57.396Z]   testing.(*M).Run()
[2021-07-21T01:59:57.396Z]       /usr/local/go/src/testing/testing.go:1417 +0x3b3
[2021-07-21T01:59:57.396Z]   go.uber.org/goleak.VerifyTestMain()
[2021-07-21T01:59:57.396Z]       /nfs/cache/mod/go.uber.org/[email protected]/testmain.go:53 +0x5e
[2021-07-21T01:59:57.396Z]   github.com/pingcap/tidb/util/logutil.TestMain()
[2021-07-21T01:59:57.396Z]       /home/jenkins/agent/workspace/tidb_ghpr_unit_test/go/src/github.com/pingcap/tidb/util/logutil/main_test.go:40 +0x9e
[2021-07-21T01:59:57.396Z]   main.main()
[2021-07-21T01:59:57.396Z]       _testmain.go:53 +0x271
[2021-07-21T01:59:57.396Z] ==================
[2021-07-21T01:59:57.396Z]     testing.go:1092: race detected during execution of test
[2021-07-21T01:59:57.396Z] --- FAIL: TestHex (0.00s)
[2021-07-21T01:59:57.396Z] === CONT  TestZapLoggerWithKeys
[2021-07-21T01:59:57.396Z]     testing.go:1092: race detected during execution of test
[2021-07-21T01:59:57.396Z] --- FAIL: TestZapLoggerWithKeys (0.01s)
[2021-07-21T01:59:57.396Z] FAIL
[2021-07-21T01:59:57.396Z] FAIL	github.com/pingcap/tidb/util/logutil	0.048s

@ofey404 it seems data race happen on this PR change set. Please take a look.

tisonkun · 2021-07-21T02:17:51Z

As log in TiDB used as global variable, we may not run in parallel. What do you think @xhebox @tiancaiamao ?

xhebox · 2021-07-21T03:19:25Z

As log in TiDB used as global variable, we may not run in parallel. What do you think @xhebox @tiancaiamao ?

Fine.InitLogger should only be called once anyway, another solution is sync.Once.

tiancaiamao · 2021-07-21T04:19:07Z

There are many global variables like that, it's one of the reason some test suite can not run parallel.
I'm OK with here not making it parallel

…which causes data race Signed-off-by: tison <[email protected]>

tisonkun · 2021-07-21T04:35:02Z

@tiancaiamao @xhebox I push a commit to run these tests serially. Please re-trigger /merge if it looks good.

@xhebox among tests, it may set InitLogger with different config multiple times. May we also evaluate code refactor to enable using logger locally while keeping globally access functionality when integrate pingcap/log#16 .

xhebox · 2021-07-21T04:52:02Z

/merge

ti-chi-bot · 2021-07-21T04:52:06Z

This pull request has been accepted and is ready to merge.

Commit hash: 6250f70

qw4990 · 2021-09-17T05:24:04Z

/cherry-pick release-5.1

Signed-off-by: ti-srebot <[email protected]>

ti-srebot · 2021-09-17T05:24:34Z

cherry pick to release-5.1 in PR #28137

xhebox · 2021-09-17T08:33:24Z

@qw4990 Why cherry pick this PR?

tisonkun · 2021-09-17T14:17:02Z

@xhebox I think it is because we'd like to port #27238 to 5.1 and @xuyifangreeneyes & @qw4990 decided that we can bring also all previously PRs.

ofey404 added 4 commits July 18, 2021 22:40

feat: marked all check occurrences as TODO

1db8336

feat: transfer to testify, manually checked that new tests are working

281465e

feat: move refactored test back

a31d108

feat: rename suites back

cf41df4

ti-chi-bot added the size/L Denotes a PR that changes 100-499 lines, ignoring generated files. label Jul 18, 2021

feat: add main_test.go

6f1bc1f

feat: remove suite usage, check the code style

ca75c7b

feat: ignore known un-clean-up goroutine

c47641b

Merge branch 'master' into util-logutil-testify

c987ef2

tisonkun approved these changes Jul 20, 2021

View reviewed changes

tisonkun requested review from xhebox and tiancaiamao July 20, 2021 01:46

xhebox approved these changes Jul 20, 2021

View reviewed changes

ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Jul 20, 2021

tiancaiamao approved these changes Jul 20, 2021

View reviewed changes

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Jul 20, 2021

ti-chi-bot added 2 commits July 20, 2021 21:19

Merge branch 'master' into util-logutil-testify

aedfee3

Merge branch 'master' into util-logutil-testify

70f9825

logutil.InitLogger sets gloabl variable, avoid run tests in parallel …

6250f70

…which causes data race Signed-off-by: tison <[email protected]>

ti-chi-bot removed the status/can-merge Indicates a PR has been approved by a committer. label Jul 21, 2021

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Jul 21, 2021

ti-chi-bot merged commit 9f1c6b8 into pingcap:master Jul 21, 2021

qw4990 added the needs-cherry-pick-release-5.1 label Sep 17, 2021

ti-srebot mentioned this pull request Sep 17, 2021

util/logutil: migrate to testify (#26322) #28137

Merged

ti-srebot pushed a commit to ti-srebot/tidb that referenced this pull request Sep 17, 2021

cherry pick pingcap#26322 to release-5.1

2fbd75e

Signed-off-by: ti-srebot <[email protected]>

ti-chi-bot pushed a commit that referenced this pull request Sep 17, 2021

util/logutil: migrate to testify (#26322) (#28137)

51b88fe

util/logutil: migrate to testify #26322

util/logutil: migrate to testify #26322

Conversation

ofey404 commented Jul 18, 2021 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Release note

CLAassistant commented Jul 18, 2021 • edited Loading

ti-srebot commented Jul 18, 2021

ofey404 commented Jul 18, 2021

ofey404 commented Jul 18, 2021

tisonkun commented Jul 18, 2021

tisonkun commented Jul 18, 2021 • edited Loading

ofey404 commented Jul 19, 2021

ofey404 commented Jul 19, 2021

tisonkun commented Jul 19, 2021

tisonkun commented Jul 19, 2021

ofey404 commented Jul 19, 2021

ofey404 commented Jul 19, 2021

tisonkun commented Jul 20, 2021

tisonkun left a comment

Choose a reason for hiding this comment

ti-chi-bot commented Jul 20, 2021

ti-chi-bot commented Jul 20, 2021

ti-chi-bot commented Jul 20, 2021

ofey404 commented Jul 20, 2021

tisonkun commented Jul 20, 2021

tisonkun commented Jul 20, 2021

tisonkun commented Jul 20, 2021

ti-chi-bot commented Jul 20, 2021

tisonkun commented Jul 20, 2021

tisonkun commented Jul 21, 2021

tisonkun commented Jul 21, 2021

tisonkun commented Jul 21, 2021

xhebox commented Jul 21, 2021

tiancaiamao commented Jul 21, 2021

tisonkun commented Jul 21, 2021 • edited Loading

xhebox commented Jul 21, 2021

ti-chi-bot commented Jul 21, 2021

qw4990 commented Sep 17, 2021

ti-srebot commented Sep 17, 2021

xhebox commented Sep 17, 2021

tisonkun commented Sep 17, 2021

ofey404 commented Jul 18, 2021 •

edited

Loading

CLAassistant commented Jul 18, 2021 •

edited

Loading

tisonkun commented Jul 18, 2021 •

edited

Loading

tisonkun commented Jul 21, 2021 •

edited

Loading