unstable test TestConcurrentProcessRangeRequest #2694

overvenus · 2021-08-31T10:01:47Z

Bug Report

[2021-08-31T07:06:32.218Z] FAIL: client_test.go:3047: etcdSuite.TestConcurrentProcessRangeRequest
[2021-08-31T07:06:32.218Z] 
[2021-08-31T07:06:32.218Z] client_test.go:3160:
[2021-08-31T07:06:32.218Z]     c.Errorf("no more events received")
...

https://ci2.pingcap.net/blue/organizations/jenkins/cdc_ghpr_integration_test/detail/cdc_ghpr_integration_test/3556/pipeline#step-425-log-29

The text was updated successfully, but these errors were encountered:

Rustin170506 · 2021-09-08T06:31:51Z

another case: https://ci2.pingcap.net/blue/organizations/jenkins/cdc_ghpr_test/detail/cdc_ghpr_test/7330/pipeline

Rustin170506 · 2021-09-14T07:38:48Z

Successfully reproduce it in a resource-constrained docker. I will try to fix it.

Rustin170506 · 2021-09-14T08:00:35Z

Failed logs

[2021/09/14 07:23:23.241 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1000] [startKey=61] [endKey=6231303031] [checkpointTs=100]
[2021/09/14 07:23:24.243 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1000] [startKey=61] [endKey=6231303031] [checkpointTs=100]
[2021/09/14 07:23:24.244 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1000] [span="[61, 6231303031)"] [retrySpans="[{"Start":"YQAAAAAAAAD4","End":"YjEwMDEAAAD8"},{"Start":"YjEwMDEAAAD8","End":"YjEwMDIAAAD8"},{"Start":"YjEwMDIAAAD8","End":"YjEwMDMAAAD8"},{"Start":"YjEwMDMAAAD8","End":"YjEwMDQAAAD8"},{"Start":"YjEwMDQAAAD8","End":"YjEwMDUAAAD8"},{"Start":"YjEwMDUAAAD8","End":"YjEwMDYAAAD8"},{"Start":"YjEwMDYAAAD8","End":"YjEwMDcAAAD8"},{"Start":"YjEwMDcAAAD8","End":"YjEwMDgAAAD8"},{"Start":"YjEwMDgAAAD8","End":"YjEwMDkAAAD8"},{"Start":"YjEwMDkAAAD8","End":"YjEwMTAAAAD8"},{"Start":"YjEwMTAAAAD8","End":"YjEwMTEAAAD8"},{"Start":"YjEwMTEAAAD8","End":"YjEwMTIAAAD8"},{"Start":"YjEwMTIAAAD8","End":"YjEwMTMAAAD8"},{"Start":"YjEwMTMAAAD8","End":"YjEwMTQAAAD8"},{"Start":"YjEwMTQAAAD8","End":"YjEwMTUAAAD8"},{"Start":"YjEwMTUAAAD8","End":"YjEwMTYAAAD8"},{"Start":"YjEwMTYAAAD8","End":"YjEwMTcAAAD8"},{"Start":"YjEwMTcAAAD8","End":"YjEwMTgAAAD8"},{"Start":"YjEwMTgAAAD8","End":"YjEwMTkAAAD8"},{"Start":"YjEwMTkAAAD8","End":"YjEwMjAAAAD8"}]"]
[2021/09/14 07:23:24.246 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=7a] [checkpointTs=100]
[2021/09/14 07:23:24.247 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1019] [startKey=6231303139] [endKey=7a] [allOverlapping="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.247 +00:00] [INFO] [client.go:726] ["creating new stream to store to send request"] [regionID=1001] [requestID=2] [storeID=1] [addr=127.0.0.1:42017]
[2021/09/14 07:23:24.248 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1019] [span="[6231303139, 7a)"] [retrySpans="[]"]
[2021/09/14 07:23:24.248 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1002] [startKey=6231303032] [endKey=6231303033] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.250 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1009] [startKey=6231303039] [endKey=6231303130] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.250 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1001,"region_epoch":{"version":1},"checkpoint_ts":100,"start_key":"YjEwMDE=","end_key":"eg==","request_id":2,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:23:24.251 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1005] [startKey=6231303035] [endKey=6231303036] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.253 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1014] [startKey=6231303134] [endKey=6231303135] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.253 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1012] [startKey=6231303132] [endKey=6231303133] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.254 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1004] [startKey=6231303034] [endKey=6231303035] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.254 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1006] [startKey=6231303036] [endKey=6231303037] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.255 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1007] [startKey=6231303037] [endKey=6231303038] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.255 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1011] [startKey=6231303131] [endKey=6231303132] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.256 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1008] [startKey=6231303038] [endKey=6231303039] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.257 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1000] [startKey=61] [endKey=6231303031] [checkpointTs=100]
[2021/09/14 07:23:24.257 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1016] [startKey=6231303136] [endKey=6231303137] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.257 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1000,"region_epoch":{"version":1},"checkpoint_ts":100,"start_key":"YQ==","end_key":"YjEwMDE=","request_id":3,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:23:24.258 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1003] [startKey=6231303033] [endKey=6231303034] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.259 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1013] [startKey=6231303133] [endKey=6231303134] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.259 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1017] [startKey=6231303137] [endKey=6231303138] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.260 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1015] [startKey=6231303135] [endKey=6231303136] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.261 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=6231303032] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.261 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1018] [startKey=6231303138] [endKey=6231303139] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.262 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1010] [startKey=6231303130] [endKey=6231303131] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
[2021/09/14 07:23:24.262 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=6231303032] [blockedBy="["regionID: 1001, ver: 1, start: 6231303031, end: 7a"]"]
{"level":"error","ts":"2021-09-14T07:24:04.223Z","caller":"grpclog/grpclog.go:81","msg":"transport: Got too many pings from the client, closing the connection.","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.(*http2Server).handlePing\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:722\ngoogle.golang.org/grpc/internal/transport.(*http2Server).HandleStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:494\ngoogle.golang.org/grpc.(*Server).serveStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:742\ngoogle.golang.org/grpc.(*Server).handleRawConn.func1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:703"}
{"level":"error","ts":"2021-09-14T07:24:04.225Z","caller":"grpclog/grpclog.go:81","msg":"transport: loopyWriter.run returning. Err: transport: Connection closing","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.newHTTP2Server.func2\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:292"}
{"level":"error","ts":"2021-09-14T07:24:04.229Z","caller":"grpclog/grpclog.go:81","msg":"transport: Got too many pings from the client, closing the connection.","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.(*http2Server).handlePing\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:722\ngoogle.golang.org/grpc/internal/transport.(*http2Server).HandleStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:494\ngoogle.golang.org/grpc.(*Server).serveStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:742\ngoogle.golang.org/grpc.(*Server).handleRawConn.func1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:703"}
{"level":"error","ts":"2021-09-14T07:24:04.231Z","caller":"grpclog/grpclog.go:81","msg":"transport: loopyWriter.run returning. Err: transport: Connection closing","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.newHTTP2Server.func2\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:292"}
[2021/09/14 07:24:04.231 +00:00] [WARN] [client_v2.go:220] ["failed to receive from stream"] [addr=127.0.0.1:42017] [storeID=1] [error="rpc error: code = Unavailable desc = transport is closing"]
[2021/09/14 07:24:04.245 +00:00] [INFO] [client_v2.go:163] ["stream to store closed"] [addr=127.0.0.1:42017] [storeID=1]
[2021/09/14 07:24:04.245 +00:00] [INFO] [region_worker.go:465] ["region worker closed by error"]
[2021/09/14 07:24:04.246 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=7a] [checkpointTs=100]
[2021/09/14 07:24:04.247 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1000] [startKey=61] [endKey=6231303031] [checkpointTs=100]
[2021/09/14 07:24:04.248 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1011] [startKey=6231303131] [endKey=6231303132] [checkpointTs=100]
[2021/09/14 07:24:04.249 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1002] [startKey=6231303032] [endKey=6231303033] [checkpointTs=100]
[2021/09/14 07:24:04.250 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1009] [startKey=6231303039] [endKey=6231303130] [checkpointTs=100]
[2021/09/14 07:24:04.249 +00:00] [INFO] [client.go:726] ["creating new stream to store to send request"] [regionID=1011] [requestID=4] [storeID=1] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.251 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1011,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMTE=","end_key":"YjEwMTI=","request_id":4,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.252 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1002,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMDI=","end_key":"YjEwMDM=","request_id":5,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.251 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1005] [startKey=6231303035] [endKey=6231303036] [checkpointTs=100]
[2021/09/14 07:24:04.253 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1014] [startKey=6231303134] [endKey=6231303135] [checkpointTs=100]
[2021/09/14 07:24:04.253 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1012] [startKey=6231303132] [endKey=6231303133] [checkpointTs=100]
[2021/09/14 07:24:04.252 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1009,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMDk=","end_key":"YjEwMTA=","request_id":6,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.254 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1005,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMDU=","end_key":"YjEwMDY=","request_id":7,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.254 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1004] [startKey=6231303034] [endKey=6231303035] [checkpointTs=100]
[2021/09/14 07:24:04.255 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1017] [startKey=6231303137] [endKey=6231303138] [checkpointTs=100]
[2021/09/14 07:24:04.256 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1006] [startKey=6231303036] [endKey=6231303037] [checkpointTs=100]
[2021/09/14 07:24:04.255 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1014,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMTQ=","end_key":"YjEwMTU=","request_id":8,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.257 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1012,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMTI=","end_key":"YjEwMTM=","request_id":9,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.256 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1008] [startKey=6231303038] [endKey=6231303039] [checkpointTs=100]
[2021/09/14 07:24:04.258 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1007] [startKey=6231303037] [endKey=6231303038] [checkpointTs=100]
[2021/09/14 07:24:04.259 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=6231303032] [checkpointTs=100]
[2021/09/14 07:24:04.258 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1004,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMDQ=","end_key":"YjEwMDU=","request_id":10,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.259 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1015] [startKey=6231303135] [endKey=6231303136] [checkpointTs=100]
[2021/09/14 07:24:04.261 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1016] [startKey=6231303136] [endKey=6231303137] [checkpointTs=100]
[2021/09/14 07:24:04.261 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1003] [startKey=6231303033] [endKey=6231303034] [checkpointTs=100]
[2021/09/14 07:24:04.260 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1017,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMTc=","end_key":"YjEwMTg=","request_id":11,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.262 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1006,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMDY=","end_key":"YjEwMDc=","request_id":12,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.263 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1008,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMDg=","end_key":"YjEwMDk=","request_id":13,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.263 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1007,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMDc=","end_key":"YjEwMDg=","request_id":14,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.262 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1010] [startKey=6231303130] [endKey=6231303131] [checkpointTs=100]
[2021/09/14 07:24:04.264 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1013] [startKey=6231303133] [endKey=6231303134] [checkpointTs=100]
[2021/09/14 07:24:04.265 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1018] [startKey=6231303138] [endKey=6231303139] [checkpointTs=100]
[2021/09/14 07:24:04.264 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1001,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMDE=","end_key":"YjEwMDI=","request_id":15,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.266 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1015,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMTU=","end_key":"YjEwMTY=","request_id":16,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.267 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1016,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMTY=","end_key":"YjEwMTc=","request_id":17,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.265 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=6231303032] [allOverlapping="["regionID: 1001, ver: 2, start: 6231303031, end: 6231303032"]"]
[2021/09/14 07:24:04.267 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1003,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMDM=","end_key":"YjEwMDQ=","request_id":18,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.268 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1010,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMTA=","end_key":"YjEwMTE=","request_id":19,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.269 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1013,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMTM=","end_key":"YjEwMTQ=","request_id":20,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.270 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1018,"region_epoch":{"version":2},"checkpoint_ts":100,"start_key":"YjEwMTg=","end_key":"YjEwMTk=","request_id":21,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.268 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=7a] [allOverlapping="["regionID: 1001, ver: 2, start: 6231303031, end: 6231303032","regionID: 1002, ver: 2, start: 6231303032, end: 6231303033","regionID: 1003, ver: 2, start: 6231303033, end: 6231303034","regionID: 1004, ver: 2, start: 6231303034, end: 6231303035","regionID: 1005, ver: 2, start: 6231303035, end: 6231303036","regionID: 1006, ver: 2, start: 6231303036, end: 6231303037","regionID: 1007, ver: 2, start: 6231303037, end: 6231303038","regionID: 1008, ver: 2, start: 6231303038, end: 6231303039","regionID: 1009, ver: 2, start: 6231303039, end: 6231303130","regionID: 1010, ver: 2, start: 6231303130, end: 6231303131","regionID: 1011, ver: 2, start: 6231303131, end: 6231303132","regionID: 1012, ver: 2, start: 6231303132, end: 6231303133","regionID: 1013, ver: 2, start: 6231303133, end: 6231303134","regionID: 1014, ver: 2, start: 6231303134, end: 6231303135","regionID: 1015, ver: 2, start: 6231303135, end: 6231303136","regionID: 1016, ver: 2, start: 6231303136, end: 6231303137","regionID: 1017, ver: 2, start: 6231303137, end: 6231303138","regionID: 1018, ver: 2, start: 6231303138, end: 6231303139"]"]
[2021/09/14 07:24:04.268 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1001] [span="[6231303031, 6231303032)"] [retrySpans="[]"]
[2021/09/14 07:24:04.271 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1012] [startKey=6231303132] [endKey=6231303133] [allOverlapping="["regionID: 1012, ver: 2, start: 6231303132, end: 6231303133"]"]
[2021/09/14 07:24:04.271 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1003] [startKey=6231303033] [endKey=6231303034] [allOverlapping="["regionID: 1003, ver: 2, start: 6231303033, end: 6231303034"]"]
[2021/09/14 07:24:04.272 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1010] [startKey=6231303130] [endKey=6231303131] [allOverlapping="["regionID: 1010, ver: 2, start: 6231303130, end: 6231303131"]"]
[2021/09/14 07:24:04.271 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1001] [span="[6231303031, 7a)"] [retrySpans="[{"Start":"YjEwMTk=","End":"eg=="}]"]
[2021/09/14 07:24:04.272 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1012] [span="[6231303132, 6231303133)"] [retrySpans="[]"]
[2021/09/14 07:24:04.272 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1003] [span="[6231303033, 6231303034)"] [retrySpans="[]"]
[2021/09/14 07:24:04.273 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1006] [startKey=6231303036] [endKey=6231303037] [allOverlapping="["regionID: 1006, ver: 2, start: 6231303036, end: 6231303037"]"]
[2021/09/14 07:24:04.273 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1010] [span="[6231303130, 6231303131)"] [retrySpans="[]"]
[2021/09/14 07:24:04.273 +00:00] [INFO] [region_cache.go:831] ["mark store's regions need be refill"] [store=127.0.0.1:42017]
[2021/09/14 07:24:04.274 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1015] [startKey=6231303135] [endKey=6231303136] [allOverlapping="["regionID: 1015, ver: 2, start: 6231303135, end: 6231303136"]"]
[2021/09/14 07:24:04.275 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1006] [span="[6231303036, 6231303037)"] [retrySpans="[]"]
[2021/09/14 07:24:04.275 +00:00] [INFO] [region_cache.go:870] ["switch region peer to next due to send request fail"] [current="region ID: 1000, meta: id:1000 end_key:"b1001" region_epoch:<version:1 > peers:<id:1001 store_id:1 > , peer: id:1001 store_id:1 , addr: 127.0.0.1:42017, idx: 0, reqStoreType: TiKvOnly, runStoreType: tikv"] [needReload=false] [error="[CDC:ErrPendingRegionCancel]pending region cancelled due to stream disconnecting"] [errorVerbose="[CDC:ErrPendingRegionCancel]pending region cancelled due to stream disconnecting\ngithub.com/pingcap/errors.AddStack\n\t/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:159\ngithub.com/pingcap/ticdc/cdc/kv.(*eventFeedSession).receiveFromStreamV2.func1\n\t/go/src/github.com/pingcap/ticdc/cdc/kv/client_v2.go:171\ngithub.com/pingcap/ticdc/cdc/kv.(*eventFeedSession).receiveFromStreamV2\n\t/go/src/github.com/pingcap/ticdc/cdc/kv/client_v2.go:248\ngithub.com/pingcap/ticdc/cdc/kv.(*eventFeedSession).requestRegionToStore.func1\n\t/go/src/github.com/pingcap/ticdc/cdc/kv/client.go:768\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371"]
[2021/09/14 07:24:04.276 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1013] [startKey=6231303133] [endKey=6231303134] [allOverlapping="["regionID: 1013, ver: 2, start: 6231303133, end: 6231303134"]"]
[2021/09/14 07:24:04.278 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1005] [startKey=6231303035] [endKey=6231303036] [allOverlapping="["regionID: 1005, ver: 2, start: 6231303035, end: 6231303036"]"]
[2021/09/14 07:24:04.276 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1015] [span="[6231303135, 6231303136)"] [retrySpans="[]"]
[2021/09/14 07:24:04.278 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1013] [span="[6231303133, 6231303134)"] [retrySpans="[]"]
[2021/09/14 07:24:04.278 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1018] [startKey=6231303138] [endKey=6231303139] [allOverlapping="["regionID: 1018, ver: 2, start: 6231303138, end: 6231303139"]"]
[2021/09/14 07:24:04.280 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1007] [startKey=6231303037] [endKey=6231303038] [allOverlapping="["regionID: 1007, ver: 2, start: 6231303037, end: 6231303038"]"]
[2021/09/14 07:24:04.278 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1005] [span="[6231303035, 6231303036)"] [retrySpans="[]"]
[2021/09/14 07:24:04.280 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1018] [span="[6231303138, 6231303139)"] [retrySpans="[]"]
[2021/09/14 07:24:04.280 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1009] [startKey=6231303039] [endKey=6231303130] [allOverlapping="["regionID: 1009, ver: 2, start: 6231303039, end: 6231303130"]"]
[2021/09/14 07:24:04.282 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1008] [startKey=6231303038] [endKey=6231303039] [allOverlapping="["regionID: 1008, ver: 2, start: 6231303038, end: 6231303039"]"]
[2021/09/14 07:24:04.280 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1007] [span="[6231303037, 6231303038)"] [retrySpans="[]"]
[2021/09/14 07:24:04.282 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1009] [span="[6231303039, 6231303130)"] [retrySpans="[]"]
[2021/09/14 07:24:04.282 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1002] [startKey=6231303032] [endKey=6231303033] [allOverlapping="["regionID: 1002, ver: 2, start: 6231303032, end: 6231303033"]"]
[2021/09/14 07:24:04.284 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1016] [startKey=6231303136] [endKey=6231303137] [allOverlapping="["regionID: 1016, ver: 2, start: 6231303136, end: 6231303137"]"]
[2021/09/14 07:24:04.282 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1008] [span="[6231303038, 6231303039)"] [retrySpans="[]"]
[2021/09/14 07:24:04.284 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1002] [span="[6231303032, 6231303033)"] [retrySpans="[]"]
[2021/09/14 07:24:04.285 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1017] [startKey=6231303137] [endKey=6231303138] [allOverlapping="["regionID: 1017, ver: 2, start: 6231303137, end: 6231303138"]"]
[2021/09/14 07:24:04.285 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1016] [span="[6231303136, 6231303137)"] [retrySpans="[]"]
[2021/09/14 07:24:04.286 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1017] [span="[6231303137, 6231303138)"] [retrySpans="[]"]
[2021/09/14 07:24:04.286 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1004] [startKey=6231303034] [endKey=6231303035] [allOverlapping="["regionID: 1004, ver: 2, start: 6231303034, end: 6231303035"]"]
[2021/09/14 07:24:04.288 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1011] [startKey=6231303131] [endKey=6231303132] [allOverlapping="["regionID: 1011, ver: 2, start: 6231303131, end: 6231303132"]"]
[2021/09/14 07:24:04.288 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1014] [startKey=6231303134] [endKey=6231303135] [allOverlapping="["regionID: 1014, ver: 2, start: 6231303134, end: 6231303135"]"]
[2021/09/14 07:24:04.289 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1019] [startKey=6231303139] [endKey=7a] [checkpointTs=100]
[2021/09/14 07:24:04.289 +00:00] [INFO] [region_range_lock.go:246] ["tryLockRange stale"] [lockID=1] [regionID=1019] [startKey=6231303139] [endKey=7a] [allOverlapping="["regionID: 1019, ver: 1, start: 6231303139, end: 7a"]"]
[2021/09/14 07:24:04.288 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1011] [span="[6231303131, 6231303132)"] [retrySpans="[]"]
[2021/09/14 07:24:04.289 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1014] [span="[6231303134, 6231303135)"] [retrySpans="[]"]
[2021/09/14 07:24:04.288 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1004] [span="[6231303034, 6231303035)"] [retrySpans="[]"]
[2021/09/14 07:24:04.290 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1019,"region_epoch":{"version":1},"checkpoint_ts":100,"start_key":"YjEwMTk=","end_key":"eg==","request_id":22,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:04.290 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1000] [startKey=61] [endKey=6231303031] [checkpointTs=100]
[2021/09/14 07:24:04.290 +00:00] [INFO] [client.go:592] ["request expired"] [regionID=1019] [span="[6231303139, 7a)"] [retrySpans="[]"]
[2021/09/14 07:24:04.292 +00:00] [INFO] [region_cache.go:568] ["invalidate current region, because others failed on same store"] [region=1000] [store=127.0.0.1:42017]
[2021/09/14 07:24:04.293 +00:00] [INFO] [client.go:881] ["cannot get rpcCtx, retry span"] [regionID=1000] [span="[61, 6231303031)"]
[2021/09/14 07:24:04.293 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1000] [startKey=61] [endKey=6231303031] [checkpointTs=100]
[2021/09/14 07:24:04.294 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1000] [startKey=61] [endKey=6231303031] [checkpointTs=100]
[2021/09/14 07:24:04.294 +00:00] [INFO] [client.go:779] ["start new request"] [request="{"header":{"cluster_id":1},"region_id":1000,"region_epoch":{"version":1},"checkpoint_ts":100,"start_key":"YQ==","end_key":"YjEwMDE=","request_id":23,"Request":null}"] [addr=127.0.0.1:42017]
[2021/09/14 07:24:42.402 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=1]
[2021/09/14 07:24:42.404 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=2]
[2021/09/14 07:24:42.404 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=3]
[2021/09/14 07:24:42.405 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=4]
[2021/09/14 07:24:42.405 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=5]
[2021/09/14 07:24:42.406 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=6]
[2021/09/14 07:24:42.406 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=7]
[2021/09/14 07:24:42.407 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=8]
[2021/09/14 07:24:42.407 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=9]
[2021/09/14 07:24:42.408 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=10]
[2021/09/14 07:24:42.409 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=11]
[2021/09/14 07:24:42.409 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=12]
[2021/09/14 07:24:42.410 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=13]
[2021/09/14 07:24:42.410 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=14]
[2021/09/14 07:24:42.411 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=15]
[2021/09/14 07:24:42.411 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=16]
[2021/09/14 07:24:42.412 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=17]
[2021/09/14 07:24:42.412 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=18]
[2021/09/14 07:24:42.412 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=19]
[2021/09/14 07:24:42.413 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=20]
[2021/09/14 07:24:42.413 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=21]
[2021/09/14 07:24:42.414 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=22]
[2021/09/14 07:24:42.414 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=23]
[2021/09/14 07:24:42.415 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=24]
[2021/09/14 07:24:42.415 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=25]
[2021/09/14 07:24:42.416 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=26]
[2021/09/14 07:24:42.417 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=27]
[2021/09/14 07:24:42.417 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=28]
[2021/09/14 07:24:42.418 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=29]
[2021/09/14 07:24:42.418 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=30]
[2021/09/14 07:24:42.419 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=31]
[2021/09/14 07:24:42.419 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=32]
[2021/09/14 07:24:42.419 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=33]
[2021/09/14 07:24:42.420 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=34]
[2021/09/14 07:24:42.420 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=35]
[2021/09/14 07:24:42.421 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=36]
[2021/09/14 07:24:42.421 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=37]
[2021/09/14 07:24:42.422 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=38]
{"level":"error","ts":"2021-09-14T07:25:24.166Z","caller":"grpclog/grpclog.go:81","msg":"transport: Got too many pings from the client, closing the connection.","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.(*http2Server).handlePing\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:722\ngoogle.golang.org/grpc/internal/transport.(*http2Server).HandleStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:494\ngoogle.golang.org/grpc.(*Server).serveStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:742\ngoogle.golang.org/grpc.(*Server).handleRawConn.func1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:703"}
{"level":"error","ts":"2021-09-14T07:25:24.168Z","caller":"grpclog/grpclog.go:81","msg":"transport: loopyWriter.run returning. Err: transport: Connection closing","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.newHTTP2Server.func2\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:292"}
{"level":"error","ts":"2021-09-14T07:26:02.306Z","caller":"grpclog/grpclog.go:81","msg":"transport: Got too many pings from the client, closing the connection.","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.(*http2Server).handlePing\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:722\ngoogle.golang.org/grpc/internal/transport.(*http2Server).HandleStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:494\ngoogle.golang.org/grpc.(*Server).serveStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:742\ngoogle.golang.org/grpc.(*Server).handleRawConn.func1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:703"}
{"level":"error","ts":"2021-09-14T07:26:02.308Z","caller":"grpclog/grpclog.go:81","msg":"transport: loopyWriter.run returning. Err: transport: Connection closing","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.newHTTP2Server.func2\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:292"}
[2021/09/14 07:26:02.310 +00:00] [WARN] [client_v2.go:220] ["failed to receive from stream"] [addr=127.0.0.1:42017] [storeID=1] [error="rpc error: code = Unavailable desc = transport is closing"]
[2021/09/14 07:26:02.369 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1008] [startKey=6231303038] [endKey=6231303039] [checkpointTs=120]
[2021/09/14 07:26:02.370 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1016] [startKey=6231303136] [endKey=6231303137] [checkpointTs=120]
[2021/09/14 07:26:02.369 +00:00] [INFO] [region_worker.go:465] ["region worker closed by error"]
[2021/09/14 07:26:02.371 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1000] [startKey=61] [endKey=6231303031] [checkpointTs=100]
[2021/09/14 07:26:02.372 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1017] [startKey=6231303137] [endKey=6231303138] [checkpointTs=100]
[2021/09/14 07:26:02.373 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1008] [startKey=6231303038] [endKey=6231303039] [checkpointTs=120]
[2021/09/14 07:26:02.374 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1016] [startKey=6231303136] [endKey=6231303137] [checkpointTs=120]
[2021/09/14 07:26:02.374 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1000] [startKey=61] [endKey=6231303031] [checkpointTs=100]
[2021/09/14 07:26:02.375 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1009] [startKey=6231303039] [endKey=6231303130] [checkpointTs=120]
[2021/09/14 07:26:02.374 +00:00] [INFO] [region_cache.go:568] ["invalidate current region, because others failed on same store"] [region=1008] [store=127.0.0.1:42017]
[2021/09/14 07:26:02.374 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=39]
[2021/09/14 07:26:02.376 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=6231303032] [checkpointTs=120]
[2021/09/14 07:26:02.377 +00:00] [INFO] [client.go:881] ["cannot get rpcCtx, retry span"] [regionID=1008] [span="[6231303038, 6231303039)"]
[2021/09/14 07:26:02.378 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1010] [startKey=6231303130] [endKey=6231303131] [checkpointTs=120]
[2021/09/14 07:26:02.379 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1017] [startKey=6231303137] [endKey=6231303138] [checkpointTs=100]
[2021/09/14 07:26:02.379 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1008] [startKey=6231303038] [endKey=6231303039] [checkpointTs=120]
[2021/09/14 07:26:02.379 +00:00] [INFO] [region_cache.go:568] ["invalidate current region, because others failed on same store"] [region=1016] [store=127.0.0.1:42017]
[2021/09/14 07:26:02.380 +00:00] [INFO] [client.go:881] ["cannot get rpcCtx, retry span"] [regionID=1016] [span="[6231303136, 6231303137)"]
[2021/09/14 07:26:02.379 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1002] [startKey=6231303032] [endKey=6231303033] [checkpointTs=120]
[2021/09/14 07:26:02.381 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1019] [startKey=6231303139] [endKey=7a] [checkpointTs=120]
[2021/09/14 07:26:02.380 +00:00] [INFO] [client_test.go:3154] ["receive resolved count"] [count=40]
[2021/09/14 07:26:02.381 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1009] [startKey=6231303039] [endKey=6231303130] [checkpointTs=120]
[2021/09/14 07:26:02.382 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1016] [startKey=6231303136] [endKey=6231303137] [checkpointTs=120]
[2021/09/14 07:26:02.383 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1011] [startKey=6231303131] [endKey=6231303132] [checkpointTs=100]
[2021/09/14 07:26:02.383 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=6231303032] [checkpointTs=120]
[2021/09/14 07:26:02.384 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1] [regionID=1010] [startKey=6231303130] [endKey=6231303131] [checkpointTs=120]
[2021/09/14 07:26:02.384 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1003] [startKey=6231303033] [endKey=6231303034] [checkpointTs=100]
[2021/09/14 07:26:02.385 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1004] [startKey=6231303034] [endKey=6231303035] [checkpointTs=120]
[2021/09/14 07:26:02.385 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1012] [startKey=6231303132] [endKey=6231303133] [checkpointTs=120]
[2021/09/14 07:26:02.386 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1013] [startKey=6231303133] [endKey=6231303134] [checkpointTs=120]
[2021/09/14 07:26:02.386 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1005] [startKey=6231303035] [endKey=6231303036] [checkpointTs=120]
[2021/09/14 07:26:02.387 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1014] [startKey=6231303134] [endKey=6231303135] [checkpointTs=120]
[2021/09/14 07:26:02.387 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1006] [startKey=6231303036] [endKey=6231303037] [checkpointTs=120]
[2021/09/14 07:26:02.388 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1015] [startKey=6231303135] [endKey=6231303136] [checkpointTs=120]
[2021/09/14 07:26:02.388 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1007] [startKey=6231303037] [endKey=6231303038] [checkpointTs=120]
[2021/09/14 07:26:02.389 +00:00] [INFO] [client_v2.go:163] ["stream to store closed"] [addr=127.0.0.1:42017] [storeID=1]
[2021/09/14 07:26:02.389 +00:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1] [regionID=1018] [startKey=6231303138] [endKey=6231303139] [checkpointTs=100]

FAIL: client_test.go:3046: etcdSuite.TestConcurrentProcessRangeRequest

client_test.go:3159:
c.Errorf("no more events received")
... Error: no more events received

OOPS: 0 passed, 1 FAILED
--- FAIL: Test (160.28s)
FAIL
exit status 1

[2021/09/14 07:23:24.262 +00:00] [INFO] [region_range_lock.go:281] ["lock range blocked"] [lockID=1] [regionID=1001] [startKey=6231303031] [endKey=6231303032] [blockedBy="[\"regionID: 1001, ver: 1, start: 6231303031, end: 7a\"]"]
{"level":"error","ts":"2021-09-14T07:24:04.223Z","caller":"grpclog/grpclog.go:81","msg":"transport: Got too many pings from the client, closing the connection.","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.(*http2Server).handlePing\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:722\ngoogle.golang.org/grpc/internal/transport.(*http2Server).HandleStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:494\ngoogle.golang.org/grpc.(*Server).serveStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:742\ngoogle.golang.org/grpc.(*Server).handleRawConn.func1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:703"}
{"level":"error","ts":"2021-09-14T07:24:04.225Z","caller":"grpclog/grpclog.go:81","msg":"transport: loopyWriter.run returning. Err: transport: Connection closing","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.newHTTP2Server.func2\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:292"}
{"level":"error","ts":"2021-09-14T07:24:04.229Z","caller":"grpclog/grpclog.go:81","msg":"transport: Got too many pings from the client, closing the connection.","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.(*http2Server).handlePing\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:722\ngoogle.golang.org/grpc/internal/transport.(*http2Server).HandleStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:494\ngoogle.golang.org/grpc.(*Server).serveStreams\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:742\ngoogle.golang.org/grpc.(*Server).handleRawConn.func1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:703"}
{"level":"error","ts":"2021-09-14T07:24:04.231Z","caller":"grpclog/grpclog.go:81","msg":"transport: loopyWriter.run returning. Err: transport: Connection closing","stacktrace":"google.golang.org/grpc/grpclog.Errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/grpclog/grpclog.go:81\ngoogle.golang.org/grpc/internal/transport.errorf\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/log.go:42\ngoogle.golang.org/grpc/internal/transport.newHTTP2Server.func2\n\t/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:292"}
[2021/09/14 07:24:04.231 +00:00] [WARN] [client_v2.go:220] ["failed to receive from stream"] [addr=127.0.0.1:42017] [storeID=1] [error="rpc error: code = Unavailable desc = transport is closing"]
[2021/09/14 07:24:04.245 +00:00] [INFO] [client_v2.go:163] ["stream to store closed"] [addr=127.0.0.1:42017] [storeID=1]
[2021/09/14 07:24:04.245 +00:00] [INFO] [region_worker.go:465] ["region worker closed by error"]

maxshuang · 2021-11-29T10:28:48Z

A common solution has been pr in #3612. If you find this issue happens again after this pr, pls reopen the this issue and @ me.

overvenus added type/bug The issue is confirmed as a bug. component/test Unit tests and integration tests component. labels Aug 31, 2021

overvenus mentioned this issue Aug 31, 2021

Tracking issue for flaky tests #2246

Closed

jebter added the severity/major label Sep 2, 2021

overvenus assigned Rustin170506 Sep 8, 2021

maxshuang assigned maxshuang and Rustin170506 and unassigned Rustin170506 Nov 29, 2021

maxshuang mentioned this issue Nov 29, 2021

kvclient(ticdc): fix kvclient takes too long time to recover #3612

Merged

maxshuang closed this as completed Nov 29, 2021

AkiraXie added the area/ticdc Issues or PRs related to TiCDC. label Mar 9, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

unstable test TestConcurrentProcessRangeRequest #2694

unstable test TestConcurrentProcessRangeRequest #2694

overvenus commented Aug 31, 2021

Rustin170506 commented Sep 8, 2021

Rustin170506 commented Sep 14, 2021

Rustin170506 commented Sep 14, 2021 •

edited

Loading

maxshuang commented Nov 29, 2021

unstable test TestConcurrentProcessRangeRequest #2694

unstable test TestConcurrentProcessRangeRequest #2694

Comments

overvenus commented Aug 31, 2021

Bug Report

Rustin170506 commented Sep 8, 2021

Rustin170506 commented Sep 14, 2021

Rustin170506 commented Sep 14, 2021 • edited Loading

maxshuang commented Nov 29, 2021

Rustin170506 commented Sep 14, 2021 •

edited

Loading