Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

flaky test(ticdc/pkg/p2p): TestMessageClientBasics #3825

Open
maxshuang opened this issue Dec 10, 2021 · 9 comments
Open

flaky test(ticdc/pkg/p2p): TestMessageClientBasics #3825

maxshuang opened this issue Dec 10, 2021 · 9 comments
Assignees
Labels
affects-5.4 area/ticdc Issues or PRs related to TiCDC. component/test Unit tests and integration tests component.

Comments

@maxshuang
Copy link
Contributor

maxshuang commented Dec 10, 2021

Which jobs are flaking?

local ut test

Which test(s) are flaking?

TestMessageClientBasics

Jenkins logs or GitHub Actions link

==================
WARNING: DATA RACE
Write at 0x00c000494280 by goroutine 57:
  github.com/pingcap/ticdc/pkg/p2p.TestMessageClientBasics()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client_test.go:183 +0x18e8
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1259 +0x198

Previous read at 0x00c000494280 by goroutine 60:
  github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
      /Users/maxshuang/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:285 +0x34
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/maxshuang/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:393 +0x78
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/maxshuang/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:383 +0x1b0
  github.com/pingcap/ticdc/pkg/p2p.(*mockSendMessageClient).Recv()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/mock_grpc_client.go:50 +0x5c
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).runRx()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:347 +0x24c
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run.func2()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:204 +0xbc
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57 +0x68

Goroutine 57 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1306 +0x5b8
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1598 +0xac
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1259 +0x198
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1596 +0x780
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1504 +0x928
  go.uber.org/goleak.VerifyTestMain()
      /Users/maxshuang/go/pkg/mod/go.uber.org/[email protected]/testmain.go:53 +0x38
  github.com/pingcap/ticdc/pkg/leakutil.SetUpLeakTest()
      /Users/maxshuang/GolandProjects/ticdc/pkg/leakutil/leak_helper.go:32 +0x2f8
  github.com/pingcap/ticdc/pkg/p2p.TestMain()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/main_test.go:23 +0x370
  main.main()
      _testmain.go:203 +0x360

Goroutine 60 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:54 +0x68
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:202 +0x3a8
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).launchStream()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:191 +0x2c8
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:162 +0x854
  github.com/pingcap/ticdc/pkg/p2p.TestMessageClientBasics.func5()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client_test.go:118 +0x100
==================
==================
WARNING: DATA RACE
Write at 0x00c000494298 by goroutine 57:
  github.com/pingcap/ticdc/pkg/p2p.TestMessageClientBasics()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client_test.go:184 +0x1920
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1259 +0x198

Previous write at 0x00c000494298 by goroutine 60:
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/maxshuang/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:430 +0xb2c
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/maxshuang/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:383 +0x1b0
  github.com/pingcap/ticdc/pkg/p2p.(*mockSendMessageClient).Recv()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/mock_grpc_client.go:50 +0x5c
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).runRx()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:347 +0x24c
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run.func2()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:204 +0xbc
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57 +0x68

Goroutine 57 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1306 +0x5b8
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1598 +0xac
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1259 +0x198
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1596 +0x780
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1504 +0x928
  go.uber.org/goleak.VerifyTestMain()
      /Users/maxshuang/go/pkg/mod/go.uber.org/[email protected]/testmain.go:53 +0x38
  github.com/pingcap/ticdc/pkg/leakutil.SetUpLeakTest()
      /Users/maxshuang/GolandProjects/ticdc/pkg/leakutil/leak_helper.go:32 +0x2f8
  github.com/pingcap/ticdc/pkg/p2p.TestMain()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/main_test.go:23 +0x370
  main.main()
      _testmain.go:203 +0x360

Goroutine 60 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:54 +0x68
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:202 +0x3a8
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).launchStream()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:191 +0x2c8
  github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:162 +0x854
  github.com/pingcap/ticdc/pkg/p2p.TestMessageClientBasics.func5()
      /Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client_test.go:118 +0x100
==================
[2021/12/10 14:26:42.128 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="fake error"] [errorVerbose="fake error\ngithub.com/pingcap/ticdc/pkg/p2p.TestMessageClientBasics\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client_test.go:198\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1259\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:42.129 +08:00] [INFO] [client.go:297] ["peer-to-peer client retrying"] [topic=topic-1] [from-seq=2]
[2021/12/10 14:26:42.138 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).runRx\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:349\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run.func2\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:204\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:42.139 +08:00] [INFO] [client.go:116] ["peer message client exited"] [addr=] [capture-id=node-2] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/ticdc/pkg/p2p.TestMessageClientBasics.func5\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client_test.go:118\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
--- FAIL: TestMessageClientBasics (0.05s)
    client_test.go:128: PASS:	Connect(string)
    client_test.go:129: PASS:	SendMessage(string,[]grpc.CallOption)
    client_test.go:143: PASS:	Append(*p2p.MessageEntry)
    client_test.go:180: PASS:	Append(*p2p.MessageEntry)
    client_test.go:180: PASS:	Append(*p2p.MessageEntry)
    client_test.go:224: PASS:	Append(*p2p.MessageEntry)
    client_test.go:224: PASS:	Flush()
    testing.go:1152: race detected during execution of test
[2021/12/10 14:26:42.139 +08:00] [INFO] [client.go:116] ["peer message client exited"] [addr=] [capture-id=node-2] [error="[CDC:ErrPeerMessageClientPermanentFail]peer-to-peer message client has failed permanently, no need to reconnect: test message"] [errorVerbose="[CDC:ErrPeerMessageClientPermanentFail]peer-to-peer message client has failed permanently, no need to reconnect: test message\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:159\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).runRx\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:355\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run.func2\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:204\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:42.140 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).retrySending\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:289\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).runTx\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:211\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:199\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:42.140 +08:00] [INFO] [client.go:116] ["peer message client exited"] [addr=] [capture-id=node-2] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/ticdc/pkg/p2p.TestClientSendAnomalies.func4\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client_test.go:327\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:42.142 +08:00] [WARN] [message_router.go:124] ["failed to create client, no peer"] [target=server-4] [stack="github.com/pingcap/ticdc/pkg/p2p.TestMessageRouterBasic\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/message_router_test.go:120\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1259"]
[2021/12/10 14:26:42.145 +08:00] [INFO] [server.go:524] ["peer connection received"] [sender-id=test-client-1] [addr=127.0.0.1:51914] [epoch=1]
[2021/12/10 14:26:42.145 +08:00] [INFO] [server.go:524] ["peer connection received"] [sender-id=test-client-1] [addr=127.0.0.1:51915] [epoch=1]
[2021/12/10 14:26:42.146 +08:00] [INFO] [server.go:524] ["peer connection received"] [sender-id=test-client-1] [addr=127.0.0.1:51916] [epoch=1]
[2021/12/10 14:26:52.141 +08:00] [WARN] [server.go:316] ["sending response to peer failed"] [error="context deadline exceeded"] [errorVerbose="context deadline exceeded\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*streamHandle).Send\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server_stream_handle.go:71\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).tick\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:311\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:212\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).Run.func2\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:190\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.141 +08:00] [WARN] [server.go:316] ["sending response to peer failed"] [error="context deadline exceeded"] [errorVerbose="context deadline exceeded\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*streamHandle).Send\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server_stream_handle.go:71\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).tick\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:311\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:212\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).Run.func2\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:190\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.141 +08:00] [WARN] [server.go:316] ["sending response to peer failed"] [error="context deadline exceeded"] [errorVerbose="context deadline exceeded\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*streamHandle).Send\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server_stream_handle.go:71\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).tick\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:311\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:212\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).Run.func2\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:190\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.141 +08:00] [WARN] [server.go:316] ["sending response to peer failed"] [error="context deadline exceeded"] [errorVerbose="context deadline exceeded\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*streamHandle).Send\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server_stream_handle.go:71\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).tick\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:311\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:212\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).Run.func2\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:190\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.141 +08:00] [WARN] [server.go:316] ["sending response to peer failed"] [error="context deadline exceeded"] [errorVerbose="context deadline exceeded\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*streamHandle).Send\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server_stream_handle.go:71\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).tick\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:311\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:212\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).Run.func2\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:190\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.141 +08:00] [WARN] [server.go:618] ["peer-to-peer message handler error"] [error="rpc error: code = Canceled desc = context canceled"] [errorVerbose="rpc error: code = Canceled desc = context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).receive\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:704\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).SendMessage.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:617\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.141 +08:00] [WARN] [server.go:621] ["error receiving from peer"] [error="context canceled"]
[2021/12/10 14:26:52.142 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).runTx\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:232\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:199\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.142 +08:00] [INFO] [client.go:116] ["peer message client exited"] [addr=127.0.0.1:51911] [capture-id=server-1] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/ticdc/pkg/p2p.(*messageRouterImpl).GetClient.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/message_router.go:144\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.142 +08:00] [WARN] [message_router.go:145] ["p2p client exited with error"] [addr=127.0.0.1:51911] [target-capture=server-1] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/ticdc/pkg/p2p.(*messageRouterImpl).GetClient.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/message_router.go:144\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.142 +08:00] [WARN] [server.go:618] ["peer-to-peer message handler error"] [error="rpc error: code = Canceled desc = context canceled"] [errorVerbose="rpc error: code = Canceled desc = context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).receive\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:704\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).SendMessage.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:617\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.142 +08:00] [WARN] [server.go:621] ["error receiving from peer"] [error="context canceled"]
[2021/12/10 14:26:52.142 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).runTx\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:232\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:199\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.142 +08:00] [INFO] [client.go:116] ["peer message client exited"] [addr=127.0.0.1:51913] [capture-id=server-3] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/ticdc/pkg/p2p.(*messageRouterImpl).GetClient.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/message_router.go:144\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.142 +08:00] [WARN] [message_router.go:145] ["p2p client exited with error"] [addr=127.0.0.1:51913] [target-capture=server-3] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/ticdc/pkg/p2p.(*messageRouterImpl).GetClient.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/message_router.go:144\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.142 +08:00] [WARN] [server.go:618] ["peer-to-peer message handler error"] [error="rpc error: code = Canceled desc = context canceled"] [errorVerbose="rpc error: code = Canceled desc = context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).receive\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:704\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageServer).SendMessage.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/server.go:617\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.143 +08:00] [WARN] [server.go:621] ["error receiving from peer"] [error="context canceled"]
[2021/12/10 14:26:52.143 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="rpc error: code = Canceled desc = context canceled"] [errorVerbose="rpc error: code = Canceled desc = context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).runRx\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:349\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run.func2\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:204\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/Users/maxshuang/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.143 +08:00] [INFO] [client.go:116] ["peer message client exited"] [addr=127.0.0.1:51912] [capture-id=server-2] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/ticdc/pkg/p2p.(*messageRouterImpl).GetClient.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/message_router.go:144\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.143 +08:00] [WARN] [message_router.go:145] ["p2p client exited with error"] [addr=127.0.0.1:51912] [target-capture=server-2] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/ticdc/pkg/p2p.(*messageRouterImpl).GetClient.func1\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/message_router.go:144\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1133"]
[2021/12/10 14:26:52.144 +08:00] [WARN] [message_router.go:124] ["failed to create client, no peer"] [target=server-1] [stack="github.com/pingcap/ticdc/pkg/p2p.TestMessageRouterBasic.func4\n\t/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/message_router_test.go:161\ngithub.com/stretchr/testify/assert.Eventually.func1\n\t/Users/maxshuang/go/pkg/mod/github.com/stretchr/[email protected]/assert/assertions.go:1655"]
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x2 addr=0x0 pc=0x101217b9c]

goroutine 544 [running]:
github.com/pingcap/ticdc/pkg/p2p.(*MessageClient).CurrentAck(0x0, {0x101252b3b, 0xa})
	/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/client.go:454 +0x4c
github.com/pingcap/ticdc/pkg/p2p.TestMessageRouterBasic.func4()
	/Users/maxshuang/GolandProjects/ticdc/pkg/p2p/message_router_test.go:161 +0x94
github.com/stretchr/testify/assert.Eventually.func1(0xc0005ea000, 0xc000ad9200)
	/Users/maxshuang/go/pkg/mod/github.com/stretchr/[email protected]/assert/assertions.go:1655 +0x34
created by github.com/stretchr/testify/assert.Eventually
	/Users/maxshuang/go/pkg/mod/github.com/stretchr/[email protected]/assert/assertions.go:1655 +0x25c
FAIL	github.com/pingcap/ticdc/pkg/p2p	10.544s

Anything else we need to know

  • Does this test exist for other branches as well?

  • Has there been a high frequency of failure lately?

@maxshuang maxshuang added the component/test Unit tests and integration tests component. label Dec 10, 2021
@maxshuang maxshuang added the area/ticdc Issues or PRs related to TiCDC. label Dec 10, 2021
@maxshuang maxshuang changed the title flaky test(ticdc/pkg/p2p): data race and panic flaky test(ticdc/pkg/p2p): TestMessageClientBasics data race and panic Dec 10, 2021
@maxshuang
Copy link
Contributor Author

It occur every time I run uts locally. Why It can be merge to master? 😢

@asddongmen
Copy link
Contributor

Another case:
https://ci.pingcap.net/blue/organizations/jenkins/atom-ut/detail/atom-ut/4876/tests/

错误
Failed
栈跟踪
=== RUN   TestClientSendAnomalies
[2021/12/14 15:26:34.873 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).runTx\n\t/home/jenkins/agent/workspace/atom-ut/ticdc/pkg/p2p/client.go:232\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).run.func1\n\t/home/jenkins/agent/workspace/atom-ut/ticdc/pkg/p2p/client.go:199\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371"]
[2021/12/14 15:26:34.874 +08:00] [INFO] [client.go:116] ["peer message client exited"] [addr=] [capture-id=node-2] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/ticdc/pkg/p2p.(*MessageClient).Run\n\t/home/jenkins/agent/workspace/atom-ut/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/ticdc/pkg/p2p.TestClientSendAnomalies.func4\n\t/home/jenkins/agent/workspace/atom-ut/ticdc/pkg/p2p/client_test.go:327\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371"]
    client_test.go:335: 
        	Error Trace:	client_test.go:335
        	Error:      	Expect "[CDC:ErrPeerMessageClientClosed]peer-to-peer message client has been closed" to match ".*ErrPeerMessageSendTryAgain.*"
        	Test:       	TestClientSendAnomalies
--- FAIL: TestClientSendAnomalies (0.01s)

@asddongmen
Copy link
Contributor

@overvenus
Copy link
Member

Another failed case

=== RUN   TestMessageRouterBasic
panic: 
assert: mock: I don't know what to return because the method call was unexpected.
	Either do Mock.On("Append").Return(...) first, or remove the Append() call.
	This method was unexpected:
		Append(*p2p.MessageEntry)
		0: &p2p.MessageEntry{Topic:"test-topic", Content:[]uint8{0x7b, 0x22, 0x76, 0x61, 0x6c, 0x75, 0x65, 0x22, 0x3a, 0x31, 0x7d}, Sequence:1, XXX_NoUnkeyedLiteral:struct {}{}, XXX_unrecognized:[]uint8(nil), XXX_sizecache:0}
	at: [client_test.go:39 client.go:263 client.go:199 errgroup.go:57 asm_amd64.s:1371]
goroutine 81 [running]:
github.com/stretchr/testify/mock.(*Mock).fail(0xc00052c240, 0x1431a9f, 0xc1, 0xc000516580, 0x4, 0x4)
	/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:254 +0x21f
github.com/stretchr/testify/mock.(*Mock).MethodCalled(0xc00052c240, 0x18fc4ef, 0x6, 0xc0005145e0, 0x1, 0x1, 0xc000516400, 0x4, 0x4)
	/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:418 +0xea5
github.com/stretchr/testify/mock.(*Mock).Called(0xc00052c240, 0xc0005145e0, 0x1, 0x1, 0xc00052c480, 0x13fc701, 0xf)
	/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:383 +0x1ee
github.com/pingcap/tiflow/pkg/p2p.(*mockClientBatchSender).Append(0xc00052c240, 0xc000518410, 0xc00053a700, 0x2)
	/home/jenkins/agent/workspace/atom-ut/tiflow/pkg/p2p/client_test.go:39 +0xa5
github.com/pingcap/tiflow/pkg/p2p.(*MessageClient).runTx(0xc000532380, 0x17a95d8, 0xc0000ff740, 0x17af290, 0xc00053a500, 0x0, 0x0)
	/home/jenkins/agent/workspace/atom-ut/tiflow/pkg/p2p/client.go:263 +0x997
github.com/pingcap/tiflow/pkg/p2p.(*MessageClient).run.func1(0x0, 0x0)
	/home/jenkins/agent/workspace/atom-ut/tiflow/pkg/p2p/client.go:199 +0x11b
golang.org/x/sync/errgroup.(*Group).Go.func1(0xc0006fac90, 0xc0000ff780)
	/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57 +0x95
created by golang.org/x/sync/errgroup.(*Group).Go
	/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:54 +0x74

@overvenus
Copy link
Member

Another failed case

=== RUN   TestMessageClientBasics
    client_test.go:128: PASS:	Connect(string)
    client_test.go:129: PASS:	SendMessage(string,[]grpc.CallOption)
    client_test.go:143: PASS:	Append(*p2p.MessageEntry)
    client_test.go:180: PASS:	Append(*p2p.MessageEntry)
    client_test.go:180: PASS:	Append(*p2p.MessageEntry)
[2021/12/28 11:04:51.870 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="fake error"] [errorVerbose="fake error\ngithub.com/pingcap/tiflow/pkg/p2p.TestMessageClientBasics\n\t/home/jenkins/agent/workspace/atom-ut/tiflow/pkg/p2p/client_test.go:198\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1193\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371"]
[2021/12/28 11:04:51.879 +08:00] [INFO] [client.go:297] ["peer-to-peer client retrying"] [topic=topic-1] [from-seq=2]
    client_test.go:224: PASS:	Append(*p2p.MessageEntry)
    client_test.go:224: FAIL:	Flush()
        		at: [client_test.go:196]
    client_test.go:224: FAIL: 1 out of 2 expectation(s) were met.
        	The code you are testing needs to make 1 more call(s).
        	at: [client_test.go:224]
[2021/12/28 11:04:51.889 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/tiflow/pkg/p2p.(*MessageClient).runRx\n\t/home/jenkins/agent/workspace/atom-ut/tiflow/pkg/p2p/client.go:349\ngithub.com/pingcap/tiflow/pkg/p2p.(*MessageClient).run.func2\n\t/home/jenkins/agent/workspace/atom-ut/tiflow/pkg/p2p/client.go:204\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371"]
[2021/12/28 11:04:51.890 +08:00] [INFO] [client.go:116] ["peer message client exited"] [addr=] [capture-id=node-2] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/tiflow/pkg/p2p.(*MessageClient).Run\n\t/home/jenkins/agent/workspace/atom-ut/tiflow/pkg/p2p/client.go:133\ngithub.com/pingcap/tiflow/pkg/p2p.TestMessageClientBasics.func5\n\t/home/jenkins/agent/workspace/atom-ut/tiflow/pkg/p2p/client_test.go:118\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371"]
--- FAIL: TestMessageClientBasics (0.07s)

https://ci.pingcap.net/blue/organizations/jenkins/atom-ut/detail/atom-ut/7230/tests/

@overvenus overvenus changed the title flaky test(ticdc/pkg/p2p): TestMessageClientBasics data race and panic flaky test(ticdc/pkg/p2p): TestMessageClientBasics Dec 28, 2021
@overvenus
Copy link
Member

==================
WARNING: DATA RACE
Write at 0x00c000616198 by goroutine 87:
  github.com/pingcap/tiflow/pkg/p2p.TestMessageClientBasics()
      /home/stn/ticdc/pkg/p2p/client_test.go:184 +0x18e9
  testing.tRunner()
      /home/stn/.local/go/src/testing/testing.go:1259 +0x22f
  testing.(*T).Run·dwrap·21()
      /home/stn/.local/go/src/testing/testing.go:1306 +0x47

Previous write at 0x00c000616198 by goroutine 90:
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /home/stn/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:430 +0xc3d
  github.com/stretchr/testify/mock.(*Mock).Called()
      /home/stn/go/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:383 +0x1a4
  github.com/pingcap/tiflow/pkg/p2p.(*mockSendMessageClient).Recv()
      /home/stn/ticdc/pkg/p2p/mock_grpc_client.go:50 +0x64
  github.com/pingcap/tiflow/pkg/p2p.(*MessageClient).runRx()
      /home/stn/ticdc/pkg/p2p/client.go:347 +0x224
  github.com/pingcap/tiflow/pkg/p2p.(*MessageClient).run.func2()
      /home/stn/ticdc/pkg/p2p/client.go:204 +0xd8
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/stn/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57 +0x96

Goroutine 87 (running) created at:
  testing.(*T).Run()
      /home/stn/.local/go/src/testing/testing.go:1306 +0x726
  testing.runTests.func1()
      /home/stn/.local/go/src/testing/testing.go:1598 +0x99
  testing.tRunner()
      /home/stn/.local/go/src/testing/testing.go:1259 +0x22f
  testing.runTests()
      /home/stn/.local/go/src/testing/testing.go:1596 +0x7ca
  testing.(*M).Run()
      /home/stn/.local/go/src/testing/testing.go:1504 +0x9d1
  go.uber.org/goleak.VerifyTestMain()
      /home/stn/go/pkg/mod/go.uber.org/[email protected]/testmain.go:53 +0x59
  github.com/pingcap/tiflow/pkg/leakutil.SetUpLeakTest()
      /home/stn/ticdc/pkg/leakutil/leak_helper.go:32 +0x2cb
  github.com/pingcap/tiflow/pkg/p2p.TestMain()
      /home/stn/ticdc/pkg/p2p/main_test.go:23 +0x368
  main.main()
      _testmain.go:205 +0x35c

Goroutine 90 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /home/stn/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:54 +0xf0
  github.com/pingcap/tiflow/pkg/p2p.(*MessageClient).run()
      /home/stn/ticdc/pkg/p2p/client.go:202 +0x384
  github.com/pingcap/tiflow/pkg/p2p.(*MessageClient).launchStream()
      /home/stn/ticdc/pkg/p2p/client.go:191 +0x2b3
  github.com/pingcap/tiflow/pkg/p2p.(*MessageClient).Run()
      /home/stn/ticdc/pkg/p2p/client.go:162 +0xa24
  github.com/pingcap/tiflow/pkg/p2p.TestMessageClientBasics.func5()
      /home/stn/ticdc/pkg/p2p/client_test.go:118 +0x167
==================
[2022/01/03 23:13:26.838 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="fake error"] [errorVerbose="fake error\ngithub.com/pingcap/tiflow/pkg/p2p.TestMessageClientBasics\n\t/home/stn/ticdc/pkg/p2p/client_test.go:198\ntesting.tRunner\n\t/home/stn/.local/go/src/testing/testing.go:1259\nruntime.goexit\n\t/home/stn/.local/go/src/runtime/asm_amd64.s:1581"]
[2022/01/03 23:13:26.840 +08:00] [INFO] [client.go:297] ["peer-to-peer client retrying"] [topic=topic-1] [from-seq=2]
[2022/01/03 23:13:26.849 +08:00] [WARN] [client.go:167] ["peer message client detected error, restarting"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/home/stn/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/home/stn/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/tiflow/pkg/p2p.(*MessageClient).runTx\n\t/home/stn/ticdc/pkg/p2p/client.go:232\ngithub.com/pingcap/tiflow/pkg/p2p.(*MessageClient).run.func1\n\t/home/stn/ticdc/pkg/p2p/client.go:199\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/home/stn/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/home/stn/.local/go/src/runtime/asm_amd64.s:1581"]
[2022/01/03 23:13:26.850 +08:00] [INFO] [client.go:116] ["peer message client exited"] [addr=] [capture-id=node-2] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/home/stn/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/home/stn/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/tiflow/pkg/p2p.(*MessageClient).Run\n\t/home/stn/ticdc/pkg/p2p/client.go:133\ngithub.com/pingcap/tiflow/pkg/p2p.TestMessageClientBasics.func5\n\t/home/stn/ticdc/pkg/p2p/client_test.go:118\nruntime.goexit\n\t/home/stn/.local/go/src/runtime/asm_amd64.s:1581"]
--- FAIL: TestMessageClientBasics (0.06s)
    client_test.go:128: PASS:   Connect(string)
    client_test.go:129: PASS:   SendMessage(string,[]grpc.CallOption)
    client_test.go:143: PASS:   Append(*p2p.MessageEntry)
    client_test.go:180: PASS:   Append(*p2p.MessageEntry)
    client_test.go:180: PASS:   Append(*p2p.MessageEntry)
    client_test.go:224: PASS:   Append(*p2p.MessageEntry)
    client_test.go:224: PASS:   Flush()
    testing.go:1152: race detected during execution of test

A new case found at 60ba6a6

@Rustin170506
Copy link
Member

@nongfushanquan
Copy link
Contributor

/label affects-5.4

@overvenus
Copy link
Member

https://ci.pingcap.net/blue/organizations/jenkins/ut-check/detail/ut-check/20185/pipeline/#step-49-log-396

[2022-06-30T07:34:05.859Z] === FAIL: pkg/p2p TestMessageClientBasics (0.07s)

[2022-06-30T07:34:05.859Z]     client_test.go:128: PASS:	Connect(string)

[2022-06-30T07:34:05.859Z]     client_test.go:129: PASS:	SendMessage(string,[]grpc.CallOption)

[2022-06-30T07:34:05.859Z]     client_test.go:143: PASS:	Append(*p2p.MessageEntry)

[2022-06-30T07:34:05.859Z]     client_test.go:180: PASS:	Append(*p2p.MessageEntry)

[2022-06-30T07:34:05.859Z]     client_test.go:180: PASS:	Append(*p2p.MessageEntry)

[2022-06-30T07:34:05.859Z] [2022/06/30 15:32:33.894 +08:00] [WARN] [client.go:168] ["peer message client detected error, restarting"] [error="fake error"] [errorVerbose="fake error\ngithub.com/pingcap/tiflow/pkg/p2p.TestMessageClientBasics\n\t/home/jenkins/agent/workspace/ut-check/tiflow/pkg/p2p/client_test.go:197\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1571"]

[2022-06-30T07:34:05.859Z] [2022/06/30 15:32:33.902 +08:00] [INFO] [client.go:297] ["peer-to-peer client retrying"] [topic=topic-1] [fromSeq=2]

[2022-06-30T07:34:05.859Z]     client_test.go:223: PASS:	Append(*p2p.MessageEntry)

[2022-06-30T07:34:05.859Z]     client_test.go:223: FAIL:	Flush()

[2022-06-30T07:34:05.859Z]         		at: [client_test.go:195]

[2022-06-30T07:34:05.859Z]     client_test.go:223: FAIL: 1 out of 2 expectation(s) were met.

[2022-06-30T07:34:05.859Z]         	The code you are testing needs to make 1 more call(s).

[2022-06-30T07:34:05.859Z]         	at: [client_test.go:223]

[2022-06-30T07:34:05.859Z] [2022/06/30 15:32:33.914 +08:00] [WARN] [client.go:168] ["peer message client detected error, restarting"] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/tiflow/pkg/p2p.(*MessageClient).runRx\n\t/home/jenkins/agent/workspace/ut-check/tiflow/pkg/p2p/client.go:349\ngithub.com/pingcap/tiflow/pkg/p2p.(*MessageClient).run.func2\n\t/home/jenkins/agent/workspace/ut-check/tiflow/pkg/p2p/client.go:205\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:74\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1571"]

[2022-06-30T07:34:05.860Z] [2022/06/30 15:32:33.914 +08:00] [INFO] [client.go:117] ["peer message client exited"] [addr=] [captureID=node-2] [error="context canceled"] [errorVerbose="context canceled\ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/[email protected]/juju_adaptor.go:15\ngithub.com/pingcap/tiflow/pkg/p2p.(*MessageClient).Run\n\t/home/jenkins/agent/workspace/ut-check/tiflow/pkg/p2p/client.go:134\ngithub.com/pingcap/tiflow/pkg/p2p.TestMessageClientBasics.func5\n\t/home/jenkins/agent/workspace/ut-check/tiflow/pkg/p2p/client_test.go:118\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1571"]

@overvenus overvenus reopened this Jun 30, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
affects-5.4 area/ticdc Issues or PRs related to TiCDC. component/test Unit tests and integration tests component.
Projects
None yet
Development

No branches or pull requests

7 participants