kv client receives commit event less then resolved ts

[amyangfei]

What did you do?

to be added

What did you expect to see?

No response

What did you see instead?

/etc/kubernetes/kubeconfig.yaml --tail -1 --previous | grep 662911
[2021/10/18 04:02:18.469 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=448] [regionID=662911] [startKey=7480000000000006fff15f728000000005ff82986d0000000000fa] [endKey=7480000000000006fff15f728000000005ff8aa9b60000000000fa] [checkpointTs=428482147748938432]
[2021/10/18 04:02:18.768 +00:00] [INFO] [client.go:771] ["start new request"] [request="{\"header\":{\"cluster_id\":7013512749674368738,\"ticdc_version\":\"5.2.0-master\"},\"region_id\":662911,\"region_epoch\":{\"conf_ver\":101,\"version\":667},\"checkpoint_ts\":428482147748938432,\"start_key\":\"dIAAAAAAAAb/8V9ygAAAAAX/gphtAAAAAAD6\",\"end_key\":\"dIAAAAAAAAb/8V9ygAAAAAX/iqm2AAAAAAD6\",\"request_id\":44963,\"extra_op\":1,\"Request\":null}"] [addr=test-hightouch-tikv-0.test-hightouch-tikv-peer.tidb-test-hightouch.svc.us-east-1e.test-hightouch.tidb.musta.ch:20160]
[2021/10/18 04:02:19.133 +00:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=406] [regionID=136629118] [startKey=748000000000001bff405f72800000005eff719dbe0000000000fa] [endKey=748000000000001bff405f72800000005eff7eeefa0000000000fa] [checkpointTs=428482147748938432]
[2021/10/18 04:02:47.762 +00:00] [WARN] [region_worker.go:651] ["The time cost of initializing is too much"] [timeCost=28.475429159s] [regionID=662911]
[2021/10/18 04:03:10.402 +00:00] [PANIC] [region_worker.go:699] ["The CommitTs must be greater than the resolvedTs"] ["Event Type"=COMMIT] [CommitTs=428482145468286448] [resolvedTs=428482147748938432] [regionID=662911] [stack="github.com/pingcap/ticdc/cdc/kv.(*regionWorker).handleEventEntry\n\tgithub.com/pingcap/ticdc/cdc/kv/region_worker.go:699\ngithub.com/pingcap/ticdc/cdc/kv.(*regionWorker).processEvent\n\tgithub.com/pingcap/ticdc/cdc/kv/region_worker.go:409\ngithub.com/pingcap/ticdc/cdc/kv.(*regionWorker).eventHandler\n\tgithub.com/pingcap/ticdc/cdc/kv/region_worker.go:502\ngithub.com/pingcap/ticdc/cdc/kv.(*regionWorker).run.func3\n\tgithub.com/pingcap/ticdc/cdc/kv/region_worker.go:617\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\tgolang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57"]

[2021/10/18 04:03:10.402 +00:00] [PANIC] [region_worker.go:699] ["The CommitTs must be greater than the resolvedTs"] ["Event Type"=COMMIT] [CommitTs=428482145468286448] [resolvedTs=428482147748938432] [regionID=662911] [stack="github.com/pingcap/ticdc/cdc/kv.(*regionWorker).handleEventEntry\n\tgithub.com/pingcap/ticdc/cdc/kv/region_worker.go:699\ngithub.com/pingcap/ticdc/cdc/kv.(*regionWorker).processEvent\n\tgithub.com/pingcap/ticdc/cdc/kv/region_worker.go:409\ngithub.com/pingcap/ticdc/cdc/kv.(*regionWorker).eventHandler\n\tgithub.com/pingcap/ticdc/cdc/kv/region_worker.go:502\ngithub.com/pingcap/ticdc/cdc/kv.(*regionWorker).run.func3\n\tgithub.com/pingcap/ticdc/cdc/kv/region_worker.go:617\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\tgolang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57"]
panic: The CommitTs must be greater than the resolvedTs

goroutine 111046 [running]:
go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc02a632000, 0xc02a1a8100, 0x4, 0x4)
	go.uber.org/zap@v1.19.0/zapcore/entry.go:232 +0x532
go.uber.org/zap.(*Logger).Panic(0xc033871740, 0x328fb2e, 0x30, 0xc02a1a8100, 0x4, 0x4)
	go.uber.org/zap@v1.19.0/logger.go:230 +0x85
github.com/pingcap/log.Panic(0x328fb2e, 0x30, 0xc02a1a8100, 0x4, 0x4)
	github.com/pingcap/log@v0.0.0-20210818144256-6455d4a4c6f9/global.go:54 +0x10b
github.com/pingcap/ticdc/cdc/kv.(*regionWorker).handleEventEntry(0xc044066360, 0x3841ca8, 0xc044064840, 0xc0625ea190, 0xc0555b2f20, 0x2593faf, 0xc0a22bcdf8)
	github.com/pingcap/ticdc/cdc/kv/region_worker.go:699 +0xb43
github.com/pingcap/ticdc/cdc/kv.(*regionWorker).processEvent(0xc044066360, 0x3841ca8, 0xc044064840, 0xc07b12b350, 0x0, 0x0)
	github.com/pingcap/ticdc/cdc/kv/region_worker.go:409 +0x545
github.com/pingcap/ticdc/cdc/kv.(*regionWorker).eventHandler(0xc044066360, 0x3841ca8, 0xc044064840, 0xc0288a7100, 0x74)
	github.com/pingcap/ticdc/cdc/kv/region_worker.go:502 +0x712
github.com/pingcap/ticdc/cdc/kv.(*regionWorker).run.func3(0x0, 0x0)
	github.com/pingcap/ticdc/cdc/kv/region_worker.go:617 +0x3c
golang.org/x/sync/errgroup.(*Group).Go.func1(0xc0440690e0, 0xc036376c80)
	golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57 +0x59
created by golang.org/x/sync/errgroup.(*Group).Go
	golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:54 +0x66

Versions of the cluster

Upstream TiDB cluster version (execute SELECT tidb_version(); in a MySQL client):

tikv version: v5.2.1-tracing-20210920

TiCDC version (execute cdc version):

v5.2.x

[amyangfei]

I notice

1. cdc starts a new region request from 428482147748938432
2. cdc inits the region at [2021/10/18 04:02:47.762 +00:00]
3. cdc receives an outdated commit event at [2021/10/18 04:03:10.402 +00:00], with commit-ts 428482145468286448

Looks like a bug described in tikv/tikv#11055

[amyangfei]

Fixed by tikv/tikv#11098