search

pingcap / tiflow

This repo maintains DM (a data migration platform) and TiCDC (change data capture for TiDB)
Apache License 2.0
424 stars 283 forks source link

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

Open maxshuang opened 2 years ago

maxshuang commented 2 years ago

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/testify@v1.7.0/mock/mock.go:285 +0x34
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/maxshuang/go/pkg/mod/github.com/stretchr/testify@v1.7.0/mock/mock.go:393 +0x78
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/maxshuang/go/pkg/mod/github.com/stretchr/testify@v1.7.0/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/sync@v0.0.0-20210220032951-036812b2e83c/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/goleak@v1.1.12/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/sync@v0.0.0-20210220032951-036812b2e83c/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/testify@v1.7.0/mock/mock.go:430 +0xb2c
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/maxshuang/go/pkg/mod/github.com/stretchr/testify@v1.7.0/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/sync@v0.0.0-20210220032951-036812b2e83c/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/goleak@v1.1.12/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/Users/maxshuang/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/testify@v1.7.0/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/testify@v1.7.0/assert/assertions.go:1655 +0x34
created by github.com/stretchr/testify/assert.Eventually
    /Users/maxshuang/go/pkg/mod/github.com/stretchr/testify@v1.7.0/assert/assertions.go:1655 +0x25c
FAIL    github.com/pingcap/ticdc/pkg/p2p    10.544s

Anything else we need to know

maxshuang commented 2 years ago

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

asddongmen commented 2 years ago

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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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 commented 2 years ago

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

overvenus commented 2 years ago

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/testify@v1.7.0/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/testify@v1.7.0/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/testify@v1.7.0/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/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57 +0x95
created by golang.org/x/sync/errgroup.(*Group).Go
    /go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:54 +0x74
overvenus commented 2 years ago

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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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 commented 2 years ago 
==================
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/testify@v1.7.0/mock/mock.go:430 +0xc3d
  github.com/stretchr/testify/mock.(*Mock).Called()
      /home/stn/go/pkg/mod/github.com/stretchr/testify@v1.7.0/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/sync@v0.0.0-20210220032951-036812b2e83c/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/goleak@v1.1.12/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/home/stn/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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/sync@v0.0.0-20210220032951-036812b2e83c/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/errors@v0.11.5-0.20211009033009-93128226aaa3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/home/stn/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211009033009-93128226aaa3/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 60ba6a6b6

Rustin170506 commented 2 years ago

another case: https://ci.pingcap.net/blue/organizations/jenkins/ut-check/detail/ut-check/10687/pipeline/

nongfushanquan commented 2 years ago

/label affects-5.4

overvenus commented 2 years ago

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/errors@v0.11.5-0.20211224045212-9687c2b0f87c/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/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/sync@v0.0.0-20220513210516-0976fa681c29/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/errors@v0.11.5-0.20211224045212-9687c2b0f87c/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/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"]