CalvinNeo
commented
1 year ago the region has peer on 29(tiflash-2) and 31(tiflash-0).
store 31 is which is tiflash-0, send a remote read request to store 29 which is tiflash-2 at 2023/07/30 23:27:05.167 +08:00, and got an error remote reader meets error: Region epoch not match after retries: Region {319305,31,167} not in region cache.
We can see logs on tiflash-2
[2023/07/30 23:26:20.643 +08:00] [INFO] [FlashService.cpp:169] ["Handling coprocessor request, is_remote_read: true, start ts: 443214871671341074, region info: 319305, region epoch: conf_ver: 31\nversion: 167\n"] [source=FlashService] [thread_id=2280]at that time, the region does not exist in store 6, it actually is removed since 2023/07/30 21:18:43.436 +08:00.
[2023/07/30 21:18:43.434 +08:00] [INFO] [apply.rs:2465] ["conf change successfully"] ["current region"="id: 319305 start_key: 7480000000000000FFFE5F728000000000FF0100D20000000000FA end_key: 7480000000000000FFFE5F728000000000FF01678C0000000000FA region_epoch { conf_ver: 28 version: 167 } peers { id: 319306 store_id: 4 } peers { id: 319307 store_id: 6 role: DemotingVoter } peers { id: 319308 store_id: 1 } peers { id: 319309 store_id: 31 role: Learner } peers { id: 319310 store_id: 29 role: Learner } peers { id: 347199 store_id: 5 role: IncomingVoter }"] ["original region"="id: 319305 start_key: 7480000000000000FFFE5F728000000000FF0100D20000000000FA end_key: 7480000000000000FFFE5F728000000000FF01678C0000000000FA region_epoch { conf_ver: 26 version: 167 } peers { id: 319306 store_id: 4 } peers { id: 319307 store_id: 6 } peers { id: 319308 store_id: 1 } peers { id: 319309 store_id: 31 role: Learner } peers { id: 319310 store_id: 29 role: Learner } peers { id: 347199 store_id: 5 role: Learner }"] [changes="[peer { id: 347199 store_id: 5 }, change_type: AddLearnerNode peer { id: 319307 store_id: 6 role: Learner }]"] [peer_id=319309] [region_id=319305]
[2023/07/30 21:18:43.436 +08:00] [INFO] [apply.rs:2465] ["conf change successfully"] ["current region"="id: 319305 start_key: 7480000000000000FFFE5F728000000000FF0100D20000000000FA end_key: 7480000000000000FFFE5F728000000000FF01678C0000000000FA region_epoch { conf_ver: 31 version: 167 } peers { id: 319306 store_id: 4 } peers { id: 319308 store_id: 1 } peers { id: 319309 store_id: 31 role: Learner } peers { id: 319310 store_id: 29 role: Learner } peers { id: 347199 store_id: 5 }"] ["original region"="id: 319305 start_key: 7480000000000000FFFE5F728000000000FF0100D20000000000FA end_key: 7480000000000000FFFE5F728000000000FF01678C0000000000FA region_epoch { conf_ver: 30 version: 167 } peers { id: 319306 store_id: 4 } peers { id: 319307 store_id: 6 role: Learner } peers { id: 319308 store_id: 1 } peers { id: 319309 store_id: 31 role: Learner } peers { id: 319310 store_id: 29 role: Learner } peers { id: 347199 store_id: 5 }"] [changes="[change_type: RemoveNode peer { id: 319307 store_id: 6 role: Learner }]"] [peer_id=319309] [region_id=319305]The local peer on store 31, which is 319309, creates at 2023/07/30 21:07:20.873 +08:00
[2023/07/30 21:07:20.873 +08:00] [INFO] [raft.rs:1127] ["became follower at term 6"] [term=6] [raft_id=319309] [region_id=319305]
[2023/07/30 21:07:20.873 +08:00] [INFO] [region.rs:103] [" 31:319305 319309, peer created"] [is_replicated=false] [role=Follower] [leader_id=319306] [region_id=319305]The region epoch on store 31 is advanced to { conf_ver: 31 version: 167 }
[2023/07/30 21:18:43.436 +08:00] [INFO] [apply.rs:2465] ["conf change successfully"] ["current region"="id: 319305 start_key: 7480000000000000FFFE5F728000000000FF0100D20000000000FA end_key: 7480000000000000FFFE5F728000000000FF01678C0000000000FA region_epoch { conf_ver: 31 version: 167 } peers { id: 319306 store_id: 4 } peers { id: 319308 store_id: 1 } peers { id: 319309 store_id: 31 role: Learner } peers { id: 319310 store_id: 29 role: Learner } peers { id: 347199 store_id: 5 }"] ["original region"="id: 319305 start_key: 7480000000000000FFFE5F728000000000FF0100D20000000000FA end_key: 7480000000000000FFFE5F728000000000FF01678C0000000000FA region_epoch { conf_ver: 30 version: 167 } peers { id: 319306 store_id: 4 } peers { id: 319307 store_id: 6 role: Learner } peers { id: 319308 store_id: 1 } peers { id: 319309 store_id: 31 role: Learner } peers { id: 319310 store_id: 29 role: Learner } peers { id: 347199 store_id: 5 }"] [changes="[change_type: RemoveNode peer { id: 319307 store_id: 6 role: Learner }]"] [peer_id=319309] [region_id=319305]
[2023/07/30 21:21:13.668 +08:00] [INFO] [apply.rs:1690] ["execute admin command"] [command="cmd_type: UpdateGcPeer update_gc_peers { peer_id: 319307 }"] [index=12577] [term=7] [peer_id=319309] [region_id=319305]
[2023/07/30 22:12:10.945 +08:00] [INFO] [command.rs:169] ["can't flush data, filter CompactLog"] [compact_term=8] [compact_index=12875] [term=8] [index=12877] [region_epoch="conf_ver: 31 version: 167"] [region_id=319305]The region epoch on store 29 is advanced to { conf_ver: 31 version: 167 }
[2023/07/30 21:18:38.465 +08:00] [INFO] [apply.rs:2284] ["exec ConfChangeV2"] [epoch="conf_ver: 30 version: 167"] [kind=Simple] [peer_id=319310] [region_id=319305]
[2023/07/30 21:18:38.465 +08:00] [INFO] [apply.rs:2465] ["conf change successfully"] ["current region"="id: 319305 start_key: 7480000000000000FFFE5F728000000000FF0100D20000000000FA end_key: 7480000000000000FFFE5F728000000000FF01678C0000000000FA region_epoch { conf_ver: 31 version: 167 } peers { id: 319306 store_id: 4 } peers { id: 319308 store_id: 1 } peers { id: 319309 store_id: 31 role: Learner } peers { id: 319310 store_id: 29 role: Learner } peers { id: 347199 store_id: 5 }"] ["original region"="id: 319305 start_key: 7480000000000000FFFE5F728000000000FF0100D20000000000FA end_key: 7480000000000000FFFE5F728000000000FF01678C0000000000FA region_epoch { conf_ver: 30 version: 167 } peers { id: 319306 store_id: 4 } peers { id: 319307 store_id: 6 role: Learner } peers { id: 319308 store_id: 1 } peers { id: 319309 store_id: 31 role: Learner } peers { id: 319310 store_id: 29 role: Learner } peers { id: 347199 store_id: 5 }"] [changes="[change_type: RemoveNode peer { id: 319307 store_id: 6 role: Learner }]"] [peer_id=319310] [region_id=319305]
[2023/07/30 22:12:12.446 +08:00] [INFO] [command.rs:169] ["can't flush data, filter CompactLog"] [compact_term=8] [compact_index=12875] [term=8] [index=12877] [region_epoch="conf_ver: 31 version: 167"] [region_id=319305]However
[2023/07/30 23:27:04.667 +08:00] [INFO] [FlashService.cpp:169] ["Handling coprocessor request, is_remote_read: true, start ts: 443214871671341074, region info: 319305, region epoch: conf_ver: 31\nversion: 167\n"] [source=FlashService] [thread_id=2249]
[2023/07/30 23:27:04.667 +08:00] [INFO] [FlashService.cpp:221] ["Begin process cop request after wait 0 ms, start ts: 443214871671341074, region info: 319305, region epoch: conf_ver: 31\nversion: 167\n"] [source=FlashService] [thread_id=322]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [CoprocessorHandler.cpp:91] ["Handling DAG request: time_zone_offset: 28800\noutput_offsets: 0\nencode_type: TypeCHBlock\ntime_zone_name: \"Asia/Shanghai\"\ncollect_execution_summaries: false\nroot_executor {\n tp: TypeTableScan\n tbl_scan {\n table_id: 254\n columns {\n column_id: -1\n tp: 8\n collation: -63\n columnLen: 20\n decimal: 0\n flag: 3\n pk_handle: true\n }\n desc: false\n next_read_engine: Local\n keep_order: false\n is_fast_scan: false\n max_wait_time_ms: 0\n }\n executor_id: \"TableFullScan_16\"\n}\nforce_encode_type: true\n"] [source=CoprocessorHandler] [thread_id=322]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [executeQuery.cpp:386] ["(from 10.233.105.28:56294, query_id: c1352e2a-a220-493d-90e1-601003bcc055) time_zone_offset: 28800 output_offsets: 0 encode_type: TypeCHBlock time_zone_name: \"Asia/Shanghai\" collect_execution_summaries: false root_executor { tp: TypeTableScan tbl_scan { table_id: 254 columns { column_id: -1 tp: 8 collation: -63 columnLen: 20 decimal: 0 flag: 3 pk_handle: true } desc: false next_read_engine: Local keep_order: false is_fast_scan: false max_wait_time_ms: 0 } executor_id: \"TableFullScan_16\" } force_encode_type: true "] [source=CoprocessorHandler] [thread_id=322]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [DeltaValueSpace.cpp:338] ["Update index start, delta=<delta_id=165>"] [source="keyspace=4294967295 table_id=261 segment_id=164 epoch=2"] [thread_id=369]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [PhysicalPlan.cpp:80] ["tidb table scan has runtime filter size:0"] [source=CoprocessorHandler] [thread_id=322]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [DeltaValueSpace.cpp:340] ["Update index done, delta=<delta_id=165>"] [source="keyspace=4294967295 table_id=261 segment_id=164 epoch=2"] [thread_id=369]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [PhysicalPlan.cpp:261] ["build unoptimized physical plan: \n<Projection, TableFullScan_16> | is_tidb_operator: false, schema: <TableFullScan_16__tidb_rowid, Int64>\n <TableScan, TableFullScan_16> | is_tidb_operator: true, schema: <_tidb_rowid, Int64>\n"] [source=CoprocessorHandler] [thread_id=322]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [PhysicalPlan.cpp:267] ["build optimized physical plan: \n<Projection, TableFullScan_16> | is_tidb_operator: false, schema: <TableFullScan_16__tidb_rowid, Int64>\n <TableScan, TableFullScan_16> | is_tidb_operator: true, schema: <_tidb_rowid, Int64>\n"] [source=CoprocessorHandler] [thread_id=322]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [LearnerRead.cpp:287] ["Batch read index, original size 1, send & get 1 message, cost 0ms"] [source=CoprocessorHandler] [thread_id=322]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [LearnerRead.cpp:409] ["Finish wait index | resolve locks, wait_cost=0ms n_regions=1 n_unavailable=1"] [source=CoprocessorHandler] [thread_id=322]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [ColumnFilePersistedSet.cpp:256] ["ColumnFilePersistedSet [165]: 24 column files, 97137 rows, 27781182 bytes, 0 deletes., after append 1 column files, persisted column files: [T_4863,T_4137,T_4137,T_4726,T_4863,T_4137,T_4137,T_4863,T_4137,T_4863,T_4137,T_4863,T_4137,T_4863,T_4137,T_4863,T_3137,T_4863,T_3000,T_137,T_1000,T_4863,T_4137,T_4137]"] [source="keyspace=4294967295 table_id=261 segment_id=164 epoch=2"] [thread_id=369]
[2023/07/30 23:27:04.667 +08:00] [WARN] [CoprocessorHandler.cpp:152] ["RegionException: region_id=319305, message: Region error NOT_FOUND"] [source=CoprocessorHandler] [thread_id=322]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [DeltaValueSpace.cpp:373] ["Flush end, flush_tasks=1 flush_rows=4137 flush_deletes=0 delta=MemTableSet: 0 column files, 0 rows, 0 bytes, 0 deletes. ColumnFilePersistedSet [165]: 24 column files, 97137 rows, 27781182 bytes, 0 deletes."] [source="keyspace=4294967295 table_id=261 segment_id=164 epoch=2"] [thread_id=369]
[2023/07/30 23:27:04.667 +08:00] [INFO] [FlashService.cpp:238] ["Handle coprocessor request done: 0, "] [source=FlashService] [thread_id=2249]
[2023/07/30 23:27:04.667 +08:00] [DEBUG] [DeltaValueSpace.h:210] ["Cannot get update lock because DeltaValueSpace is updating. Current update operation will be discarded, delta=<delta_id=165>"] [source="keyspace=4294967295 table_id=261 segment_id=164 epoch=2"] [thread_id=369]
JaySon-Huang
Bug Report
Please answer these questions before submitting your issue. Thanks!
1. Minimal reproduce step (Required)
consistency test
2. What did you expect to see? (Required)
3. What did you see instead (Required)
4. What is your TiFlash version? (Required)
master