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.

Sign up for GitHub

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

Jump to bottom

tso: unexpected "reset user timestamp failed" in TestConcurrentlyReset #6385

Closed
binshi-bing opened this issue Apr 26, 2023 · 0 comments · Fixed by #6396
Closed

tso: unexpected "reset user timestamp failed" in TestConcurrentlyReset #6385

binshi-bing opened this issue Apr 26, 2023 · 0 comments · Fixed by #6396
Labels
type/ci The issue is related to CI.

Comments

@binshi-bing
Copy link
Contributor

binshi-bing commented Apr 26, 2023 •
edited by rleungx
Loading

Flaky Test

Which jobs are failing

TestMicroserviceTSOServer/TestConcurrentlyReset

CI link

=== RUN   TestMicroserviceTSOServer/TestConcurrentlyReset
[2023/04/25 13:11:59.235 -07:00] [INFO] [lease.go:139] ["start lease keep alive worker"] [interval=1s] [purpose="keyspace group primary election"]
[2023/04/25 13:11:59.275 -07:00] [INFO] [server.go:1839] ["update service primary addr"] [service-key=/ms/7226082837749027631/tso/00000/primary] [primary-addr=http://127.0.0.1:51883]
[2023/04/25 13:11:59.411 -07:00] [INFO] [server.go:1751] ["start to watch service primary addr"] [service-key=/ms/7226082837749027631/tso/00000/primary]
[2023/04/25 13:11:59.327 -07:00] [INFO] [server.go:1839] ["update service primary addr"] [service-key=/ms/7226082837749027631/tso/00000/primary] [primary-addr=http://127.0.0.1:51883]
[2023/04/25 13:11:59.411 -07:00] [INFO] [server.go:1751] ["start to watch service primary addr"] [service-key=/ms/7226082837749027631/tso/00000/primary]
[2023/04/25 13:11:59.411 -07:00] [INFO] [handler.go:37] [reset-ts] [new-ts=441045095392477184] [ignore-smaller=false] [skip-upper-bound-check=false] [keyspace-group-id=0]
[2023/04/25 13:11:59.411 -07:00] [INFO] [handler.go:37] [reset-ts] [new-ts=441045095392477184] [ignore-smaller=false] [skip-upper-bound-check=false] [keyspace-group-id=0]
[2023/04/25 13:11:59.411 -07:00] [INFO] [server.go:1751] ["start to watch service primary addr"] [service-key=/ms/7226082837749027631/tso/00000/primary]
[2023/04/25 13:11:59.411 -07:00] [INFO] [global_allocator.go:542] ["initializing the global tso allocator"]
    server_test.go:116:
        	Error Trace:	/Users/binshi/code/pingcap/my-pd/tests/integrations/tso/server_test.go:116
        	            				/Users/binshi/code/pingcap/my-pd/tests/integrations/tso/server_test.go:159
        	            				/usr/local/go/src/runtime/asm_arm64.s:1172
        	Error:      	Error "[PD:tso:ErrResetUserTimestamp]reset user timestamp failed, the specified ts is too larger than now" does not contain "is smaller than now"
        	Test:       	TestMicroserviceTSOServer/TestConcurrentlyReset
    server_test.go:116:
        	Error Trace:	/Users/binshi/code/pingcap/my-pd/tests/integrations/tso/server_test.go:116
        	            				/Users/binshi/code/pingcap/my-pd/tests/integrations/tso/server_test.go:159
        	            				/usr/local/go/src/runtime/asm_arm64.s:1172
        	Error:      	Error "[PD:tso:ErrResetUserTimestamp]reset user timestamp failed, the specified ts is too larger than now" does not contain "is smaller than now"
        	Test:       	TestMicroserviceTSOServer/TestConcurrentlyReset
[2023/04/25 13:11:59.415 -07:00] [INFO] [server.go:1113] ["PD server config is updated"] [new="{\"use-region-storage\":\"true\",\"max-gap-reset-ts\":\"24h0m0s\",\"key-type\":\"table\",\"runtime-services\":\"\",\"metric-storage\":\"\",\"dashboard-address\":\"http://127.0.0.1:51834\",\"trace-region-flow\":\"true\",\"flow-round-by-digit\":3,\"min-resolved-ts-persistence-interval\":\"1s\",\"server-memory-limit\":0,\"server-memory-limit-gc-trigger\":0.7,\"enable-gogc-tuner\":\"false\",\"gc-tuner-threshold\":0.6}"] [old="{\"use-region-storage\":\"true\",\"max-gap-reset-ts\":\"24h0m0s\",\"key-type\":\"table\",\"runtime-services\":\"\",\"metric-storage\":\"\",\"dashboard-address\":\"auto\",\"trace-region-flow\":\"true\",\"flow-round-by-digit\":3,\"min-resolved-ts-persistence-interval\":\"1s\",\"server-memory-limit\":0,\"server-memory-limit-gc-trigger\":0.7,\"enable-gogc-tuner\":\"false\",\"gc-tuner-threshold\":0.6}"]
=== RUN   TestMicroserviceTSOServer/TestZeroTSOCount
[2023/04/25 13:11:59.422 -07:00] [INFO] [allocator_manager.go:713] ["exit allocator daemon"]
[2023/04/25 13:11:59.422 -07:00] [INFO] [lease.go:164] ["stop lease keep alive worker"] [purpose="keyspace group primary election"]
[2023/04/25 13:11:59.422 -07:00] [INFO] [allocator_manager.go:280] ["exit allocator loop"]
[2023/04/25 13:11:59.422 -07:00] [INFO] [register.go:78] ["exit register process"] [key=/ms/7226082837749027631/tso/registry/http://127.0.0.1:51883]
[2023/04/25 13:11:59.422 -07:00] [INFO] [server.go:168] ["closing tso server ..."]
[2023/04/25 13:11:59.422 -07:00] [INFO] [server.go:1578] ["server is closed, exit etcd leader loop"]
[2023/04/25 13:11:59.422 -07:00] [INFO] [keyspace_group_manager.go:287] ["closing keyspace group manager"]
[2023/04/25 13:11:59.422 -07:00] [INFO] [server.go:1561] ["server is closed"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:605] ["server is closed, exist encryption key manager loop"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:1755] ["server is closed, exist watch service primary addr loop"] [service=tso]
[2023/04/25 13:11:59.422 -07:00] [INFO] [keyspace_group_manager.go:79] ["closing all keyspace groups"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:1578] ["server is closed, exit etcd leader loop"]
[2023/04/25 13:11:59.422 -07:00] [INFO] [server.go:1578] ["server is closed, exit etcd leader loop"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:591] ["server is closed, exit metrics loop"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:591] ["server is closed, exit metrics loop"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [lease.go:164] ["stop lease keep alive worker"] [purpose="leader election"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:591] ["server is closed, exit metrics loop"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:1755] ["server is closed, exist watch service primary addr loop"] [service=tso]
[2023/04/25 13:11:59.425 -07:00] [INFO] [allocator_manager.go:286] ["closing the allocator manager"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:1755] ["server is closed, exist watch service primary addr loop"] [service=tso]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:605] ["server is closed, exist encryption key manager loop"]
[2023/04/25 13:11:59.423 -07:00] [INFO] [server.go:605] ["server is closed, exist encryption key manager loop"]
[2023/04/25 13:11:59.434 -07:00] [INFO] [tso.go:184] ["sync and save timestamp"] [last=0001/01/01 00:00:00.000 +00:00] [save=2023/04/25 13:12:02.415 -07:00] [next=2023/04/25 13:11:59.415 -07:00]
[2023/04/25 13:11:59.434 -07:00] [INFO] [global_allocator.go:559] ["tso primary is ready to serve"] [tso-primary-name=http://127.0.0.1:51883-00000]
[2023/04/25 13:11:59.434 -07:00] [INFO] [global_allocator.go:573] ["exit leader campaign"]
[2023/04/25 13:11:59.482 -07:00] [INFO] [tso.go:375] ["reset the timestamp in memory"]
[2023/04/25 13:11:59.482 -07:00] [INFO] [global_allocator.go:484] ["exit the global tso primary election loop"]
[2023/04/25 13:11:59.483 -07:00] [INFO] [allocator_manager.go:295] ["closed the allocator manager"]
[2023/04/25 13:11:59.483 -07:00] [INFO] [keyspace_group_manager.go:92] ["keyspace group closed"] [keyspace-group-id=0]
[2023/04/25 13:11:59.483 -07:00] [INFO] [keyspace_group_manager.go:98] ["all keyspace groups closed"]
[2023/04/25 13:11:59.483 -07:00] [INFO] [keyspace_group_manager.go:298] ["keyspace group manager closed"]
[2023/04/25 13:11:59.490 -07:00] [INFO] [server.go:1450] ["start to campaign API service leader"] [campaign-leader-name=pd3]
[2023/04/25 13:11:59.523 -07:00] [INFO] [server.go:440] ["mux stop serving"] [error="accept tcp 127.0.0.1:51883: use of closed network connection"]
[2023/04/25 13:11:59.523 -07:00] [INFO] [server.go:374] ["grpc server stopped serving"]
[2023/04/25 13:11:59.523 -07:00] [INFO] [server.go:410] ["http server stopped serving"]
[2023/04/25 13:11:59.523 -07:00] [INFO] [server.go:381] ["try to gracefully stop the server now"]
[2023/04/25 13:11:59.523 -07:00] [INFO] [server.go:417] ["all http(s) requests finished"]
[2023/04/25 13:11:59.523 -07:00] [INFO] [server.go:393] ["grpc server stopped"]
[2023/04/25 13:11:59.523 -07:00] [INFO] [server.go:420] ["http server stopped"]
[2023/04/25 13:11:59.523 -07:00] [INFO] [lease.go:66] ["lease granted"] [lease-id=4227058958387455286] [lease-timeout=3] [purpose="leader election"]
[2023/04/25 13:11:59.523 -07:00] [INFO] [server.go:185] ["tso server is closed"]
[2023/04/25 13:11:59.524 -07:00] [INFO] [server.go:478] ["closing server"]
[2023/04/25 13:11:59.540 -07:00] [INFO] [leadership.go:122] ["check campaign resp"] [resp="{\"header\":{\"cluster_id\":323630441434437818,\"member_id\":6562690303699073705,\"revision\":24,\"raft_term\":2},\"succeeded\":true,\"responses\":[{\"Response\":{\"ResponsePut\":{\"header\":{\"revision\":24}}}}]}"]
[2023/04/25 13:11:59.540 -07:00] [INFO] [leadership.go:131] ["write leaderData to leaderPath ok"] [leaderPath=/pd/7226082837749027631/leader] [purpose="leader election"]
[2023/04/25 13:11:59.540 -07:00] [INFO] [server.go:1476] ["campaign API service leader ok"] [campaign-leader-name=pd3]
[2023/04/25 13:11:59.541 -07:00] [INFO] [lease.go:139] ["start lease keep alive worker"] [interval=1s] [purpose="leader election"]
[2023/04/25 13:11:59.541 -07:00] [INFO] [lease.go:164] ["stop lease keep alive worker"] [purpose="leader election"]
[2023/04/25 13:11:59.541 -07:00] [WARN] [lease.go:150] ["lease keep alive failed"] [purpose="leader election"] [error="context canceled"]
[2023/04/25 13:11:59.546 -07:00] [INFO] [server.go:1598] ["server enable region storage"]
[2023/04/25 13:11:59.549 -07:00] [INFO] [server.go:1513] ["triggering the leader callback functions"]
[2023/04/25 13:11:59.562 -07:00] [WARN] [manager.go:144] ["init default group failed"] [error="[PD:resourcemanager:ErrResourceGroupAlreadyExists]the default resource group already exists"]
[2023/04/25 13:11:59.562 -07:00] [INFO] [manager.go:152] ["resource group manager finishes initialization"]
[2023/04/25 13:11:59.576 -07:00] [INFO] [id.go:174] ["idAllocator allocates a new id"] [new-end=2000] [new-base=1000] [label=idalloc] [check-curr-end=true]
[2023/04/25 13:11:59.576 -07:00] [INFO] [util.go:41] ["load cluster version"] [cluster-version=0.0.0]
[2023/04/25 13:11:59.576 -07:00] [INFO] [server.go:1542] ["API service leader is ready to serve"] [leader-name=pd3]
[2023/04/25 13:11:59.576 -07:00] [INFO] [server.go:1561] ["server is closed"]
[2023/04/25 13:11:59.616 -07:00] [INFO] [server.go:1450] ["start to campaign API service leader"] [campaign-leader-name=pd3]
[2023/04/25 13:11:59.660 -07:00] [INFO] [lease.go:66] ["lease granted"] [lease-id=4227058958387455301] [lease-timeout=3] [purpose="leader election"]
[2023/04/25 13:11:59.675 -07:00] [INFO] [server.go:1432] ["pd leader has changed, try to re-campaign a pd leader"]
[2023/04/25 13:11:59.675 -07:00] [INFO] [server.go:1438] ["skip campaigning of pd leader and check later"] [server-name=pd2] [etcd-leader-id=6562690303699073705] [member-id=8079119029083973728]
[2023/04/25 13:11:59.676 -07:00] [INFO] [server.go:1432] ["pd leader has changed, try to re-campaign a pd leader"]
[2023/04/25 13:11:59.676 -07:00] [INFO] [leadership.go:122] ["check campaign resp"] [resp="{\"header\":{\"cluster_id\":323630441434437818,\"member_id\":6562690303699073705,\"revision\":28,\"raft_term\":2},\"succeeded\":true,\"responses\":[{\"Response\":{\"ResponsePut\":{\"header\":{\"revision\":28}}}}]}"]
[2023/04/25 13:11:59.676 -07:00] [INFO] [server.go:1438] ["skip campaigning of pd leader and check later"] [server-name=pd1] [etcd-leader-id=6562690303699073705] [member-id=726785608463940718]
[2023/04/25 13:11:59.676 -07:00] [INFO] [leadership.go:131] ["write leaderData to leaderPath ok"] [leaderPath=/pd/7226082837749027631/leader] [purpose="leader election"]
[2023/04/25 13:11:59.681 -07:00] [INFO] [server.go:1476] ["campaign API service leader ok"] [campaign-leader-name=pd3]
[2023/04/25 13:11:59.681 -07:00] [INFO] [lease.go:139] ["start lease keep alive worker"] [interval=1s] [purpose="leader election"]
[2023/04/25 13:11:59.681 -07:00] [INFO] [lease.go:164] ["stop lease keep alive worker"] [purpose="leader election"]
[2023/04/25 13:11:59.681 -07:00] [WARN] [lease.go:150] ["lease keep alive failed"] [purpose="leader election"] [error="context canceled"]
[2023/04/25 13:11:59.684 -07:00] [INFO] [server.go:1598] ["server enable region storage"]
[2023/04/25 13:11:59.685 -07:00] [INFO] [server.go:1513] ["triggering the leader callback functions"]
[2023/04/25 13:11:59.703 -07:00] [WARN] [manager.go:144] ["init default group failed"] [error="[PD:resourcemanager:ErrResourceGroupAlreadyExists]the default resource group already exists"]
[2023/04/25 13:11:59.703 -07:00] [INFO] [manager.go:152] ["resource group manager finishes initialization"]
[2023/04/25 13:11:59.733 -07:00] [INFO] [id.go:174] ["idAllocator allocates a new id"] [new-end=3000] [new-base=2000] [label=idalloc] [check-curr-end=true]
[2023/04/25 13:11:59.733 -07:00] [INFO] [util.go:41] ["load cluster version"] [cluster-version=0.0.0]
[2023/04/25 13:11:59.733 -07:00] [INFO] [server.go:1542] ["API service leader is ready to serve"] [leader-name=pd3]
[2023/04/25 13:11:59.734 -07:00] [INFO] [server.go:1561] ["server is closed"]
[2023/04/25 13:11:59.754 -07:00] [INFO] [server.go:1450] ["start to campaign API service leader"] [campaign-leader-name=pd3]
[2023/04/25 13:11:59.766 -07:00] [INFO] [lease.go:66] ["lease granted"] [lease-id=4227058958387455316] [lease-timeout=3] [purpose="leader election"]
[2023/04/25 13:11:59.780 -07:00] [INFO] [leadership.go:122] ["check campaign resp"] [resp="{\"header\":{\"cluster_id\":323630441434437818,\"member_id\":6562690303699073705,\"revision\":32,\"raft_term\":2},\"succeeded\":true,\"responses\":[{\"Response\":{\"ResponsePut\":{\"header\":{\"revision\":32}}}}]}"]
[2023/04/25 13:11:59.780 -07:00] [INFO] [leadership.go:131] ["write leaderData to leaderPath ok"] [leaderPath=/pd/7226082837749027631/leader] [purpose="leader election"]
[2023/04/25 13:11:59.780 -07:00] [INFO] [server.go:1476] ["campaign API service leader ok"] [campaign-leader-name=pd3]
[2023/04/25 13:11:59.780 -07:00] [INFO] [lease.go:139] ["start lease keep alive worker"] [interval=1s] [purpose="leader election"]
[2023/04/25 13:11:59.780 -07:00] [INFO] [lease.go:164] ["stop lease keep alive worker"] [purpose="leader election"]
[2023/04/25 13:11:59.781 -07:00] [WARN] [lease.go:150] ["lease keep alive failed"] [purpose="leader election"] [error="context canceled"]
[2023/04/25 13:11:59.785 -07:00] [INFO] [server.go:1598] ["server enable region storage"]
[2023/04/25 13:11:59.830 -07:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {127.0.0.1:62732  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:62732: connect: connection refused\". Reconnecting..."]
[2023/04/25 13:11:59.851 -07:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {127.0.0.1:62676  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:62676: connect: connection refused\". Reconnecting..."]
[2023/04/25 13:11:59.882 -07:00] [INFO] [server.go:1406] ["server is closed, return API service leader loop"]
[2023/04/25 13:11:59.887 -07:00] [INFO] [server.go:1598] ["server enable region storage"]
[2023/04/25 13:11:59.961 -07:00] [INFO] [server.go:1428] ["start to watch pd leader"] [pd-leader="name:\"pd3\" member_id:6562690303699073705 peer_urls:\"http://127.0.0.1:51839\" client_urls:\"http://127.0.0.1:51838\" "]
[2023/04/25 13:11:59.961 -07:00] [INFO] [etcd.go:369] ["closing etcd server"] [name=pd1] [data-dir=/tmp/pd-tests3499931188] [advertise-peer-urls="[http://127.0.0.1:51835]"] [advertise-client-urls="[http://127.0.0.1:51834]"]
[2023/04/25 13:11:59.961 -07:00] [INFO] [client.go:126] ["region syncer start load region"]
[2023/04/25 13:11:59.965 -07:00] [INFO] [client.go:129] ["region syncer finished load region"] [time-cost=50.292µs]
[2023/04/25 13:11:59.965 -07:00] [INFO] [server.go:1432] ["pd leader has changed, try to re-campaign a pd leader"]
[2023/04/25 13:11:59.965 -07:00] [WARN] [grpclog.go:60] ["transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:51834->127.0.0.1:51879: use of closed network connection"]
[2023/04/25 13:11:59.965 -07:00] [INFO] [server.go:1494] ["skipped leadership transfer; local server is not leader"] [local-member-id=a160fa9045bfc6e] [current-leader-member-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.965 -07:00] [INFO] [server.go:1438] ["skip campaigning of pd leader and check later"] [server-name=pd2] [etcd-leader-id=6562690303699073705] [member-id=8079119029083973728]
[2023/04/25 13:11:59.965 -07:00] [INFO] [peer.go:333] ["stopping remote peer"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.966 -07:00] [WARN] [peer.go:179] ["failed to process Raft message"] [error="raft: stopped"]
[2023/04/25 13:11:59.967 -07:00] [INFO] [server.go:1513] ["triggering the leader callback functions"]
[2023/04/25 13:11:59.967 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=a160fa9045bfc6e] [error=EOF]
[2023/04/25 13:11:59.967 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.967 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.968 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream Message"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=a160fa9045bfc6e] [error=EOF]
[2023/04/25 13:11:59.968 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.968 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.968 -07:00] [INFO] [pipeline.go:86] ["stopped HTTP pipelining with remote peer"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.968 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=5b135c0f82e23aa9] [error="context canceled"]
[2023/04/25 13:11:59.969 -07:00] [WARN] [peer_status.go:68] ["peer became inactive (message send to peer failed)"] [peer-id=5b135c0f82e23aa9] [error="failed to read 5b135c0f82e23aa9 on stream MsgApp v2 (context canceled)"]
[2023/04/25 13:11:59.981 -07:00] [WARN] [manager.go:144] ["init default group failed"] [error="[PD:resourcemanager:ErrResourceGroupAlreadyExists]the default resource group already exists"]
[2023/04/25 13:11:59.982 -07:00] [INFO] [manager.go:152] ["resource group manager finishes initialization"]
[2023/04/25 13:11:59.982 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.982 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream Message"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=5b135c0f82e23aa9] [error="context canceled"]
[2023/04/25 13:11:59.983 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream Message"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.983 -07:00] [INFO] [peer.go:340] ["stopped remote peer"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:11:59.983 -07:00] [INFO] [peer.go:333] ["stopping remote peer"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:11:59.983 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=a160fa9045bfc6e] [error=EOF]
[2023/04/25 13:11:59.983 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:11:59.984 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:11:59.984 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream Message"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=a160fa9045bfc6e] [error=EOF]
[2023/04/25 13:11:59.988 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:11:59.988 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:11:59.988 -07:00] [INFO] [pipeline.go:86] ["stopped HTTP pipelining with remote peer"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:11:59.988 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=701ecbf3b2a62860] [error="context canceled"]
[2023/04/25 13:11:59.988 -07:00] [WARN] [peer_status.go:68] ["peer became inactive (message send to peer failed)"] [peer-id=701ecbf3b2a62860] [error="failed to read 701ecbf3b2a62860 on stream MsgApp v2 (context canceled)"]
[2023/04/25 13:11:59.997 -07:00] [INFO] [id.go:174] ["idAllocator allocates a new id"] [new-end=4000] [new-base=3000] [label=idalloc] [check-curr-end=true]
[2023/04/25 13:12:00.169 -07:00] [WARN] [peer_status.go:68] ["peer became inactive (message send to peer failed)"] [peer-id=a160fa9045bfc6e] [error="failed to write a160fa9045bfc6e on stream Message (write tcp 127.0.0.1:51839->127.0.0.1:51858: write: broken pipe)"]
[2023/04/25 13:12:00.184 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:00.184 -07:00] [INFO] [util.go:41] ["load cluster version"] [cluster-version=0.0.0]
[2023/04/25 13:12:00.184 -07:00] [INFO] [server.go:1542] ["API service leader is ready to serve"] [leader-name=pd3]
[2023/04/25 13:12:00.176 -07:00] [INFO] [server.go:1598] ["server enable region storage"]
[2023/04/25 13:12:00.184 -07:00] [WARN] [stream.go:224] ["lost TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:00.184 -07:00] [INFO] [server.go:1561] ["server is closed"]
[2023/04/25 13:12:00.184 -07:00] [INFO] [server.go:1428] ["start to watch pd leader"] [pd-leader="name:\"pd3\" member_id:6562690303699073705 peer_urls:\"http://127.0.0.1:51839\" client_urls:\"http://127.0.0.1:51838\" "]
[2023/04/25 13:12:00.184 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream Message"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=701ecbf3b2a62860] [error="context canceled"]
[2023/04/25 13:12:00.328 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream Message"] [local-member-id=a160fa9045bfc6e] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:00.329 -07:00] [INFO] [peer.go:340] ["stopped remote peer"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:00.184 -07:00] [INFO] [client.go:126] ["region syncer start load region"]
[2023/04/25 13:12:00.185 -07:00] [WARN] [stream.go:224] ["lost TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:00.200 -07:00] [INFO] [server.go:1450] ["start to campaign API service leader"] [campaign-leader-name=pd3]
[2023/04/25 13:12:00.333 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=5b135c0f82e23aa9] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.333 -07:00] [INFO] [client.go:129] ["region syncer finished load region"] [time-cost=61.542µs]
[2023/04/25 13:12:00.333 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=5b135c0f82e23aa9] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.343 -07:00] [INFO] [lease.go:66] ["lease granted"] [lease-id=4227058958387455331] [lease-timeout=3] [purpose="leader election"]
[2023/04/25 13:12:00.333 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=701ecbf3b2a62860] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.333 -07:00] [WARN] [http.go:147] ["failed to process Raft message"] [local-member-id=a160fa9045bfc6e] [error="raft: stopped"]
[2023/04/25 13:12:00.351 -07:00] [INFO] [server.go:1432] ["pd leader has changed, try to re-campaign a pd leader"]
[2023/04/25 13:12:00.351 -07:00] [WARN] [peer_status.go:68] ["peer became inactive (message send to peer failed)"] [peer-id=a160fa9045bfc6e] [error="failed to dial a160fa9045bfc6e on stream Message (peer a160fa9045bfc6e failed to find local node 701ecbf3b2a62860)"]
[2023/04/25 13:12:00.333 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=701ecbf3b2a62860] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.353 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=5b135c0f82e23aa9] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.357 -07:00] [INFO] [server.go:1438] ["skip campaigning of pd leader and check later"] [server-name=pd2] [etcd-leader-id=6562690303699073705] [member-id=8079119029083973728]
[2023/04/25 13:12:00.354 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=5b135c0f82e23aa9] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.358 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=701ecbf3b2a62860] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.358 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=701ecbf3b2a62860] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.360 -07:00] [INFO] [leadership.go:122] ["check campaign resp"] [resp="{\"header\":{\"cluster_id\":323630441434437818,\"member_id\":6562690303699073705,\"revision\":36,\"raft_term\":2},\"succeeded\":true,\"responses\":[{\"Response\":{\"ResponsePut\":{\"header\":{\"revision\":36}}}}]}"]
[2023/04/25 13:12:00.361 -07:00] [INFO] [leadership.go:131] ["write leaderData to leaderPath ok"] [leaderPath=/pd/7226082837749027631/leader] [purpose="leader election"]
[2023/04/25 13:12:00.361 -07:00] [INFO] [server.go:1476] ["campaign API service leader ok"] [campaign-leader-name=pd3]
[2023/04/25 13:12:00.365 -07:00] [INFO] [etcd.go:564] ["stopping serving peer traffic"] [address=127.0.0.1:51835]
[2023/04/25 13:12:00.454 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=5b135c0f82e23aa9] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.427 -07:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {127.0.0.1:64635  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:64635: connect: connection refused\". Reconnecting..."]
[2023/04/25 13:12:00.455 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=5b135c0f82e23aa9] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.459 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=701ecbf3b2a62860] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.361 -07:00] [INFO] [lease.go:139] ["start lease keep alive worker"] [interval=1s] [purpose="leader election"]
[2023/04/25 13:12:00.461 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=a160fa9045bfc6e] [remote-peer-id-stream-handler=a160fa9045bfc6e] [remote-peer-id-from=701ecbf3b2a62860] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:00.584 -07:00] [INFO] [lease.go:164] ["stop lease keep alive worker"] [purpose="leader election"]
[2023/04/25 13:12:00.568 -07:00] [INFO] [server.go:1598] ["server enable region storage"]
[2023/04/25 13:12:00.563 -07:00] [WARN] [http.go:147] ["failed to process Raft message"] [local-member-id=a160fa9045bfc6e] [error="raft: stopped"]
[2023/04/25 13:12:00.584 -07:00] [WARN] [lease.go:150] ["lease keep alive failed"] [purpose="leader election"] [error="context canceled"]
[2023/04/25 13:12:00.580 -07:00] [INFO] [server.go:1598] ["server enable region storage"]
[2023/04/25 13:12:00.564 -07:00] [WARN] [http.go:147] ["failed to process Raft message"] [local-member-id=a160fa9045bfc6e] [error="raft: stopped"]
[2023/04/25 13:12:00.584 -07:00] [INFO] [server.go:1428] ["start to watch pd leader"] [pd-leader="name:\"pd3\" member_id:6562690303699073705 peer_urls:\"http://127.0.0.1:51839\" client_urls:\"http://127.0.0.1:51838\" "]
[2023/04/25 13:12:00.584 -07:00] [INFO] [client.go:126] ["region syncer start load region"]
[2023/04/25 13:12:00.568 -07:00] [WARN] [http.go:147] ["failed to process Raft message"] [local-member-id=a160fa9045bfc6e] [error="raft: stopped"]
[2023/04/25 13:12:00.586 -07:00] [INFO] [server.go:1513] ["triggering the leader callback functions"]
[2023/04/25 13:12:00.576 -07:00] [INFO] [etcd.go:571] ["stopped serving peer traffic"] [address=127.0.0.1:51835]
[2023/04/25 13:12:00.589 -07:00] [INFO] [client.go:129] ["region syncer finished load region"] [time-cost=31.917µs]
[2023/04/25 13:12:00.589 -07:00] [INFO] [etcd.go:373] ["closed etcd server"] [name=pd1] [data-dir=/tmp/pd-tests3499931188] [advertise-peer-urls="[http://127.0.0.1:51835]"] [advertise-client-urls="[http://127.0.0.1:51834]"]
[2023/04/25 13:12:00.589 -07:00] [INFO] [server.go:1432] ["pd leader has changed, try to re-campaign a pd leader"]
[2023/04/25 13:12:00.589 -07:00] [INFO] [server.go:1438] ["skip campaigning of pd leader and check later"] [server-name=pd2] [etcd-leader-id=6562690303699073705] [member-id=8079119029083973728]
[2023/04/25 13:12:00.899 -07:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {127.0.0.1:64635  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:64635: connect: connection refused\". Reconnecting..."]
[2023/04/25 13:12:00.590 -07:00] [INFO] [server.go:511] ["triggering the close callback functions"]
[2023/04/25 13:12:00.979 -07:00] [INFO] [manager.go:72] ["exit dashboard loop"]
[2023/04/25 13:12:00.980 -07:00] [INFO] [server.go:516] ["close server"]
[2023/04/25 13:12:00.604 -07:00] [WARN] [manager.go:144] ["init default group failed"] [error="[PD:resourcemanager:ErrResourceGroupAlreadyExists]the default resource group already exists"]
[2023/04/25 13:12:00.980 -07:00] [INFO] [manager.go:152] ["resource group manager finishes initialization"]
[2023/04/25 13:12:00.980 -07:00] [WARN] [retry_interceptor.go:62] ["retrying of unary invoker failed"] [target=endpoint://client-8ff1bfa3-2890-463e-a416-2c2d4afd8132/127.0.0.1:51834] [attempt=0] [error="rpc error: code = Canceled desc = context canceled"]
[2023/04/25 13:12:00.993 -07:00] [ERROR] [etcdutil.go:138] ["load from etcd meet error"] [key=/pd/7226082837749027631/scheduler_config/] [error="[PD:etcd:ErrEtcdKVGet]context canceled: context canceled"]
[2023/04/25 13:12:01.000 -07:00] [INFO] [id.go:174] ["idAllocator allocates a new id"] [new-end=5000] [new-base=4000] [label=idalloc] [check-curr-end=true]
[2023/04/25 13:12:01.000 -07:00] [INFO] [util.go:41] ["load cluster version"] [cluster-version=0.0.0]
[2023/04/25 13:12:01.000 -07:00] [INFO] [server.go:1542] ["API service leader is ready to serve"] [leader-name=pd3]
[2023/04/25 13:12:01.000 -07:00] [INFO] [server.go:1561] ["server is closed"]
[2023/04/25 13:12:01.007 -07:00] [INFO] [server.go:478] ["closing server"]
[2023/04/25 13:12:01.014 -07:00] [INFO] [server.go:1450] ["start to campaign API service leader"] [campaign-leader-name=pd3]
[2023/04/25 13:12:01.029 -07:00] [INFO] [lease.go:66] ["lease granted"] [lease-id=4227058958387455346] [lease-timeout=3] [purpose="leader election"]
[2023/04/25 13:12:01.046 -07:00] [INFO] [leadership.go:122] ["check campaign resp"] [resp="{\"header\":{\"cluster_id\":323630441434437818,\"member_id\":6562690303699073705,\"revision\":40,\"raft_term\":2},\"succeeded\":true,\"responses\":[{\"Response\":{\"ResponsePut\":{\"header\":{\"revision\":40}}}}]}"]
[2023/04/25 13:12:01.046 -07:00] [INFO] [leadership.go:131] ["write leaderData to leaderPath ok"] [leaderPath=/pd/7226082837749027631/leader] [purpose="leader election"]
[2023/04/25 13:12:01.046 -07:00] [INFO] [server.go:1476] ["campaign API service leader ok"] [campaign-leader-name=pd3]
[2023/04/25 13:12:01.047 -07:00] [INFO] [lease.go:139] ["start lease keep alive worker"] [interval=1s] [purpose="leader election"]
[2023/04/25 13:12:01.048 -07:00] [INFO] [lease.go:164] ["stop lease keep alive worker"] [purpose="leader election"]
[2023/04/25 13:12:01.048 -07:00] [WARN] [lease.go:150] ["lease keep alive failed"] [purpose="leader election"] [error="context canceled"]
[2023/04/25 13:12:01.052 -07:00] [INFO] [server.go:1598] ["server enable region storage"]
[2023/04/25 13:12:01.054 -07:00] [INFO] [server.go:1513] ["triggering the leader callback functions"]
[2023/04/25 13:12:01.066 -07:00] [WARN] [manager.go:144] ["init default group failed"] [error="[PD:resourcemanager:ErrResourceGroupAlreadyExists]the default resource group already exists"]
[2023/04/25 13:12:01.066 -07:00] [INFO] [manager.go:152] ["resource group manager finishes initialization"]
[2023/04/25 13:12:01.078 -07:00] [INFO] [id.go:174] ["idAllocator allocates a new id"] [new-end=6000] [new-base=5000] [label=idalloc] [check-curr-end=true]
[2023/04/25 13:12:01.078 -07:00] [INFO] [util.go:41] ["load cluster version"] [cluster-version=0.0.0]
[2023/04/25 13:12:01.078 -07:00] [INFO] [server.go:1542] ["API service leader is ready to serve"] [leader-name=pd3]
[2023/04/25 13:12:01.078 -07:00] [INFO] [server.go:1561] ["server is closed"]
[2023/04/25 13:12:01.090 -07:00] [INFO] [server.go:1450] ["start to campaign API service leader"] [campaign-leader-name=pd3]
[2023/04/25 13:12:01.132 -07:00] [INFO] [lease.go:66] ["lease granted"] [lease-id=4227058958387455361] [lease-timeout=3] [purpose="leader election"]
[2023/04/25 13:12:01.146 -07:00] [INFO] [leadership.go:122] ["check campaign resp"] [resp="{\"header\":{\"cluster_id\":323630441434437818,\"member_id\":6562690303699073705,\"revision\":44,\"raft_term\":2},\"succeeded\":true,\"responses\":[{\"Response\":{\"ResponsePut\":{\"header\":{\"revision\":44}}}}]}"]
[2023/04/25 13:12:01.147 -07:00] [INFO] [leadership.go:131] ["write leaderData to leaderPath ok"] [leaderPath=/pd/7226082837749027631/leader] [purpose="leader election"]
[2023/04/25 13:12:01.147 -07:00] [INFO] [server.go:1476] ["campaign API service leader ok"] [campaign-leader-name=pd3]
[2023/04/25 13:12:01.147 -07:00] [INFO] [lease.go:139] ["start lease keep alive worker"] [interval=1s] [purpose="leader election"]
[2023/04/25 13:12:01.147 -07:00] [INFO] [lease.go:164] ["stop lease keep alive worker"] [purpose="leader election"]
[2023/04/25 13:12:01.147 -07:00] [WARN] [lease.go:150] ["lease keep alive failed"] [purpose="leader election"] [error="context canceled"]
[2023/04/25 13:12:01.154 -07:00] [INFO] [server.go:1598] ["server enable region storage"]
[2023/04/25 13:12:01.157 -07:00] [INFO] [server.go:1513] ["triggering the leader callback functions"]
[2023/04/25 13:12:01.173 -07:00] [WARN] [manager.go:144] ["init default group failed"] [error="[PD:resourcemanager:ErrResourceGroupAlreadyExists]the default resource group already exists"]
[2023/04/25 13:12:01.173 -07:00] [INFO] [manager.go:152] ["resource group manager finishes initialization"]
[2023/04/25 13:12:01.180 -07:00] [INFO] [server.go:1406] ["server is closed, return API service leader loop"]
[2023/04/25 13:12:01.180 -07:00] [INFO] [etcd.go:369] ["closing etcd server"] [name=pd2] [data-dir=/tmp/pd-tests3405903039] [advertise-peer-urls="[http://127.0.0.1:51837]"] [advertise-client-urls="[http://127.0.0.1:51836]"]
[2023/04/25 13:12:01.180 -07:00] [WARN] [grpclog.go:60] ["transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:51836->127.0.0.1:51877: use of closed network connection"]
[2023/04/25 13:12:01.180 -07:00] [INFO] [server.go:1494] ["skipped leadership transfer; local server is not leader"] [local-member-id=701ecbf3b2a62860] [current-leader-member-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.186 -07:00] [INFO] [peer.go:333] ["stopping remote peer"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:01.186 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:01.187 -07:00] [INFO] [id.go:174] ["idAllocator allocates a new id"] [new-end=7000] [new-base=6000] [label=idalloc] [check-curr-end=true]
[2023/04/25 13:12:01.326 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:01.326 -07:00] [INFO] [util.go:41] ["load cluster version"] [cluster-version=0.0.0]
[2023/04/25 13:12:01.326 -07:00] [INFO] [server.go:1542] ["API service leader is ready to serve"] [leader-name=pd3]
[2023/04/25 13:12:01.326 -07:00] [INFO] [server.go:1561] ["server is closed"]
[2023/04/25 13:12:01.186 -07:00] [WARN] [peer.go:179] ["failed to process Raft message"] [error="raft: stopped"]
[2023/04/25 13:12:01.326 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:01.326 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:01.327 -07:00] [WARN] [peer.go:179] ["failed to process Raft message"] [error="raft: stopped"]
[2023/04/25 13:12:01.327 -07:00] [INFO] [pipeline.go:86] ["stopped HTTP pipelining with remote peer"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:01.328 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:01.328 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream Message"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:01.328 -07:00] [INFO] [peer.go:340] ["stopped remote peer"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:01.328 -07:00] [INFO] [peer.go:333] ["stopping remote peer"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.329 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.330 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=701ecbf3b2a62860] [error=EOF]
[2023/04/25 13:12:01.337 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.337 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.337 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.338 -07:00] [INFO] [pipeline.go:86] ["stopped HTTP pipelining with remote peer"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.338 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream Message"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=701ecbf3b2a62860] [error=EOF]
[2023/04/25 13:12:01.341 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=5b135c0f82e23aa9] [error="context canceled"]
[2023/04/25 13:12:01.342 -07:00] [WARN] [peer_status.go:68] ["peer became inactive (message send to peer failed)"] [peer-id=5b135c0f82e23aa9] [error="failed to read 5b135c0f82e23aa9 on stream MsgApp v2 (context canceled)"]
[2023/04/25 13:12:01.342 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.342 -07:00] [WARN] [stream.go:436] ["lost TCP streaming connection with remote peer"] [stream-reader-type="stream Message"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=5b135c0f82e23aa9] [error="context canceled"]
[2023/04/25 13:12:01.345 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream Message"] [local-member-id=701ecbf3b2a62860] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.345 -07:00] [INFO] [peer.go:340] ["stopped remote peer"] [remote-peer-id=5b135c0f82e23aa9]
[2023/04/25 13:12:01.351 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=701ecbf3b2a62860] [remote-peer-id-stream-handler=701ecbf3b2a62860] [remote-peer-id-from=5b135c0f82e23aa9] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:01.351 -07:00] [WARN] [http.go:448] ["failed to find remote peer in cluster"] [local-member-id=701ecbf3b2a62860] [remote-peer-id-stream-handler=701ecbf3b2a62860] [remote-peer-id-from=5b135c0f82e23aa9] [cluster-id=47dc42bfc33d8ba]
[2023/04/25 13:12:01.352 -07:00] [WARN] [peer_status.go:68] ["peer became inactive (message send to peer failed)"] [peer-id=701ecbf3b2a62860] [error="failed to dial 701ecbf3b2a62860 on stream MsgApp v2 (peer 701ecbf3b2a62860 failed to find local node 5b135c0f82e23aa9)"]
[2023/04/25 13:12:01.372 -07:00] [INFO] [etcd.go:564] ["stopping serving peer traffic"] [address=127.0.0.1:51837]
[2023/04/25 13:12:01.373 -07:00] [INFO] [etcd.go:571] ["stopped serving peer traffic"] [address=127.0.0.1:51837]
[2023/04/25 13:12:01.373 -07:00] [INFO] [etcd.go:373] ["closed etcd server"] [name=pd2] [data-dir=/tmp/pd-tests3405903039] [advertise-peer-urls="[http://127.0.0.1:51837]"] [advertise-client-urls="[http://127.0.0.1:51836]"]
[2023/04/25 13:12:01.374 -07:00] [INFO] [server.go:511] ["triggering the close callback functions"]
[2023/04/25 13:12:01.374 -07:00] [INFO] [manager.go:72] ["exit dashboard loop"]
[2023/04/25 13:12:01.374 -07:00] [INFO] [server.go:516] ["close server"]
[2023/04/25 13:12:01.374 -07:00] [WARN] [retry_interceptor.go:62] ["retrying of unary invoker failed"] [target=endpoint://client-9e13834c-5293-472f-aec0-ad6e290f3700/127.0.0.1:51836] [attempt=0] [error="rpc error: code = Canceled desc = context canceled"]
[2023/04/25 13:12:01.374 -07:00] [ERROR] [etcdutil.go:138] ["load from etcd meet error"] [key=/pd/7226082837749027631/scheduler_config/] [error="[PD:etcd:ErrEtcdKVGet]context canceled: context canceled"]
[2023/04/25 13:12:01.436 -07:00] [INFO] [server.go:478] ["closing server"]
[2023/04/25 13:12:01.604 -07:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {127.0.0.1:62727  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:62727: connect: connection refused\". Reconnecting..."]
[2023/04/25 13:12:01.812 -07:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {127.0.0.1:62727  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:62727: connect: connection refused\". Reconnecting..."]
[2023/04/25 13:12:01.873 -07:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {127.0.0.1:62732  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:62732: connect: connection refused\". Reconnecting..."]
[2023/04/25 13:12:01.884 -07:00] [WARN] [probing_status.go:70] ["prober detected unhealthy status"] [round-tripper-name=ROUND_TRIPPER_RAFT_MESSAGE] [remote-peer-id=a160fa9045bfc6e] [rtt=0s] [error="dial tcp 127.0.0.1:51835: connect: connection refused"]
[2023/04/25 13:12:01.894 -07:00] [WARN] [probing_status.go:70] ["prober detected unhealthy status"] [round-tripper-name=ROUND_TRIPPER_SNAPSHOT] [remote-peer-id=a160fa9045bfc6e] [rtt=0s] [error="dial tcp 127.0.0.1:51835: connect: connection refused"]
[2023/04/25 13:12:02.304 -07:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {127.0.0.1:64635  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:64635: connect: connection refused\". Reconnecting..."]
[2023/04/25 13:12:02.326 -07:00] [WARN] [retry_interceptor.go:62] ["retrying of unary invoker failed"] [target=endpoint://client-e97edf85-af48-422f-97e2-9cd5fa8de87f/127.0.0.1:51838] [attempt=0] [error="rpc error: code = DeadlineExceeded desc = context deadline exceeded"]
[2023/04/25 13:12:02.326 -07:00] [INFO] [server.go:1406] ["server is closed, return API service leader loop"]
[2023/04/25 13:12:02.327 -07:00] [INFO] [etcd.go:369] ["closing etcd server"] [name=pd3] [data-dir=/tmp/pd-tests952261179] [advertise-peer-urls="[http://127.0.0.1:51839]"] [advertise-client-urls="[http://127.0.0.1:51838]"]
[2023/04/25 13:12:02.327 -07:00] [WARN] [grpclog.go:60] ["transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:51838->127.0.0.1:51875: use of closed network connection"]
[2023/04/25 13:12:02.327 -07:00] [WARN] [server.go:1549] ["leadership transfer failed"] [local-member-id=5b135c0f82e23aa9] [error="etcdserver: unhealthy cluster"]
[2023/04/25 13:12:02.327 -07:00] [INFO] [peer.go:333] ["stopping remote peer"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:02.328 -07:00] [WARN] [grpclog.go:60] ["grpc: addrConn.createTransport failed to connect to {127.0.0.1:51838  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial tcp 127.0.0.1:51838: connect: connection refused\". Reconnecting..."]
[2023/04/25 13:12:02.335 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:02.336 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:02.336 -07:00] [INFO] [pipeline.go:86] ["stopped HTTP pipelining with remote peer"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:02.336 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:02.337 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream Message"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:02.337 -07:00] [INFO] [peer.go:340] ["stopped remote peer"] [remote-peer-id=a160fa9045bfc6e]
[2023/04/25 13:12:02.337 -07:00] [INFO] [peer.go:333] ["stopping remote peer"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:02.337 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:02.337 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream MsgApp v2"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:02.337 -07:00] [WARN] [stream.go:291] ["closed TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:02.339 -07:00] [WARN] [stream.go:301] ["stopped TCP streaming connection with remote peer"] [stream-writer-type="stream Message"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:02.339 -07:00] [INFO] [pipeline.go:86] ["stopped HTTP pipelining with remote peer"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:02.339 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream MsgApp v2"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:02.339 -07:00] [INFO] [stream.go:459] ["stopped stream reader with remote peer"] [stream-reader-type="stream Message"] [local-member-id=5b135c0f82e23aa9] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:02.339 -07:00] [INFO] [peer.go:340] ["stopped remote peer"] [remote-peer-id=701ecbf3b2a62860]
[2023/04/25 13:12:02.363 -07:00] [INFO] [etcd.go:564] ["stopping serving peer traffic"] [address=127.0.0.1:51839]
[2023/04/25 13:12:02.363 -07:00] [INFO] [etcd.go:571] ["stopped serving peer traffic"] [address=127.0.0.1:51839]
[2023/04/25 13:12:02.363 -07:00] [INFO] [etcd.go:373] ["closed etcd server"] [name=pd3] [data-dir=/tmp/pd-tests952261179] [advertise-peer-urls="[http://127.0.0.1:51839]"] [advertise-client-urls="[http://127.0.0.1:51838]"]
[2023/04/25 13:12:02.364 -07:00] [INFO] [server.go:511] ["triggering the close callback functions"]
[2023/04/25 13:12:02.364 -07:00] [INFO] [manager.go:72] ["exit dashboard loop"]
[2023/04/25 13:12:02.364 -07:00] [INFO] [server.go:516] ["close server"]
[2023/04/25 13:12:02.365 -07:00] [WARN] [retry_interceptor.go:62] ["retrying of unary invoker failed"] [target=endpoint://client-e97edf85-af48-422f-97e2-9cd5fa8de87f/127.0.0.1:51838] [attempt=0] [error="rpc error: code = Canceled desc = context canceled"]
[2023/04/25 13:12:02.365 -07:00] [ERROR] [etcdutil.go:138] ["load from etcd meet error"] [key=/pd/7226082837749027631/scheduler_config/] [error="[PD:etcd:ErrEtcdKVGet]context canceled: context canceled"]
--- FAIL: TestMicroserviceTSOServer (8.42s)
    --- FAIL: TestMicroserviceTSOServer/TestConcurrentlyReset (0.01s)
    --- PASS: TestMicroserviceTSOServer/TestZeroTSOCount (0.00s)
FAIL
	github.com/tikv/pd/tests/integrations/tso	coverage: 100.0% of statements
exit status 1
FAIL	github.com/tikv/pd/tests/integrations/tso	246.158s
cd ../../.. && /Library/Developer/CommandLineTools/usr/bin/make failpoint-disable

Reason for failure (if possible)

Anything else
@binshi-bing binshi-bing added the type/ci The issue is related to CI. label Apr 26, 2023
@binshi-bing binshi-bing changed the title Unexpected "reset user timestamp failed" in TestMicroserviceTSOServer/TestConcurrentlyReset tso: unexpected "reset user timestamp failed" in TestConcurrentlyReset Apr 26, 2023
@binshi-bing binshi-bing mentioned this issue Apr 28, 2023
Merged
ti-chi-bot bot pushed a commit that referenced this issue Apr 28, 2023
@binshi-bing
tests: fix Flaky TestMicroserviceTSOServer/TestConcurrentlyReset (#6396)
dcfd9ba 
close #6385

Get a copy of now then call base.add, because now is shared by all goroutines and now.add() will add to itself which isn't atomic and multi-goroutine safe.

Signed-off-by: Bin Shi <binshi.bing@gmail.com>
zeminzhou pushed a commit to zeminzhou/pd that referenced this issue May 10, 2023
@binshi-bing @zeminzhou
tests: fix Flaky TestMicroserviceTSOServer/TestConcurrentlyReset (tik…
d48c127 
…v#6396)

close tikv#6385

Get a copy of now then call base.add, because now is shared by all goroutines and now.add() will add to itself which isn't atomic and multi-goroutine safe.

Signed-off-by: Bin Shi <binshi.bing@gmail.com>
Signed-off-by: zeminzhou <zhouzemin@pingcap.com>
rleungx pushed a commit to rleungx/pd that referenced this issue Aug 2, 2023
@binshi-bing @rleungx
tests: fix Flaky TestMicroserviceTSOServer/TestConcurrentlyReset (tik…
2ffaf95 
…v#6396)

close tikv#6385

Get a copy of now then call base.add, because now is shared by all goroutines and now.add() will add to itself which isn't atomic and multi-goroutine safe.

Signed-off-by: Bin Shi <binshi.bing@gmail.com>
@lhy1024 lhy1024 mentioned this issue Aug 29, 2023
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
type/ci The issue is related to CI.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

tests: fix Flaky TestMicroserviceTSOServer/TestConcurrentlyReset binshi-bing/pd
1 participant
@binshi-bing