search

pingcap / tiflash

The analytical engine for TiDB and TiDB Cloud. Try free: https://tidbcloud.com/free-trial
https://docs.pingcap.com/tidb/stable/tiflash-overview
Apache License 2.0
944 stars 410 forks source link

RegionKVStoreTest.KVStoreFailRecovery failed in Darwin #8937

Open Lloyd-Pottiger opened 5 months ago

Lloyd-Pottiger commented 5 months ago

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

% ./dbms/gtests_dbms --gtest_filter="RegionKVStoreTest.KVStoreFailRecovery"
[2024/04/11 16:41:45.485 +08:00] [INFO] [ComputeLabelHolder.cpp:47] ["get cluster id: unknown"] [thread_id=1]
[2024/04/11 16:41:45.486 +08:00] [INFO] [ComputeLabelHolder.cpp:55] ["get process id: unknown"] [thread_id=1]
[2024/04/11 16:41:45.486 +08:00] [INFO] [ComputeLabelHolder.cpp:47] ["get cluster id: unknown"] [thread_id=1]
[2024/04/11 16:41:45.486 +08:00] [INFO] [ComputeLabelHolder.cpp:55] ["get process id: unknown"] [thread_id=1]
[2024/04/11 16:41:45.486 +08:00] [INFO] [ComputeLabelHolder.cpp:47] ["get cluster id: unknown"] [thread_id=1]
[2024/04/11 16:41:45.486 +08:00] [INFO] [ComputeLabelHolder.cpp:55] ["get process id: unknown"] [thread_id=1]
[2024/04/11 16:41:45.486 +08:00] [INFO] [ComputeLabelHolder.cpp:47] ["get cluster id: unknown"] [thread_id=1]
[2024/04/11 16:41:45.486 +08:00] [INFO] [ComputeLabelHolder.cpp:55] ["get process id: unknown"] [thread_id=1]
[2024/04/11 16:41:45.491 +08:00] [INFO] [BackgroundProcessingPool.cpp:90] ["Create BackgroundProcessingPool, prefix=bg- n_threads=2"] [thread_id=1]
[2024/04/11 16:41:45.492 +08:00] [INFO] [BackgroundProcessingPool.cpp:90] ["Create BackgroundProcessingPool, prefix=bg-block- n_threads=2"] [thread_id=1]
[2024/04/11 16:41:45.493 +08:00] [INFO] [PathCapacityMetrics.cpp:93] ["Init capacity [path=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/] [capacity=0.00 B]"] [thread_id=1]
[2024/04/11 16:41:45.495 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.log] [thread_id=1]
[2024/04/11 16:41:45.495 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.data] [thread_id=1]
[2024/04/11 16:41:45.495 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.meta] [thread_id=1]
[2024/04/11 16:41:45.496 +08:00] [INFO] [BlobStore.cpp:131] ["Ignore not blob file [dir=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/page/log] [file=wal] [err_msg=]"] [source=__global__.log] [thread_id=1]
[2024/04/11 16:41:45.497 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.log] [thread_id=1]
[2024/04/11 16:41:45.498 +08:00] [INFO] [BlobStore.cpp:131] ["Ignore not blob file [dir=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/page/data] [file=wal] [err_msg=]"] [source=__global__.data] [thread_id=1]
[2024/04/11 16:41:45.499 +08:00] [DEBUG] [WALReader.cpp:176] ["Open log file for reading, file=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/page/data/wal/log_1_0 size=852"] [source=__global__.data] [thread_id=1]
[2024/04/11 16:41:45.503 +08:00] [DEBUG] [WALReader.cpp:176] ["Open log file for reading, file=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/page/data/wal/log_2_0 size=2812"] [source=__global__.data] [thread_id=1]
[2024/04/11 16:41:45.504 +08:00] [DEBUG] [PageDirectory.cpp:2206] ["After MVCC gc in memory [lowest_seq=62] clean [invalid_snapshot_nums=0] [invalid_page_nums=29] [total_deref_counter=0] [all_del_entries=0]. Still exist [snapshot_nums=0], [page_nums=0]. Longest alive snapshot: [longest_alive_snapshot_time=0] [longest_alive_snapshot_seq=0] [stale_snapshot_nums=0]"] [source=__global__.data] [thread_id=1]
[2024/04/11 16:41:45.504 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=33 max_applied_ver=62"] [source=__global__.data] [thread_id=1]
[2024/04/11 16:41:45.504 +08:00] [INFO] [BlobStore.cpp:131] ["Ignore not blob file [dir=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/page/meta] [file=wal] [err_msg=]"] [source=__global__.meta] [thread_id=1]
[2024/04/11 16:41:45.504 +08:00] [INFO] [BlobStat.cpp:146] ["Created a new BlobStat [blob_id=10] [capacity=268435456]"] [source=__global__.meta] [thread_id=1]
[2024/04/11 16:41:45.505 +08:00] [DEBUG] [WALReader.cpp:176] ["Open log file for reading, file=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/page/meta/wal/log_1_0 size=1748"] [source=__global__.meta] [thread_id=1]
[2024/04/11 16:41:45.505 +08:00] [DEBUG] [WALReader.cpp:176] ["Open log file for reading, file=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/page/meta/wal/log_2_0 size=8672"] [source=__global__.meta] [thread_id=1]
[2024/04/11 16:41:45.506 +08:00] [DEBUG] [PageDirectory.cpp:2206] ["After MVCC gc in memory [lowest_seq=104] clean [invalid_snapshot_nums=0] [invalid_page_nums=17] [total_deref_counter=0] [all_del_entries=0]. Still exist [snapshot_nums=0], [page_nums=0]. Longest alive snapshot: [longest_alive_snapshot_time=0] [longest_alive_snapshot_seq=0] [stale_snapshot_nums=0]"] [source=__global__.meta] [thread_id=1]
[2024/04/11 16:41:45.506 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=17 max_applied_ver=104"] [source=__global__.meta] [thread_id=1]
[2024/04/11 16:41:45.506 +08:00] [INFO] [TiFlashTestEnv.cpp:161] ["Storage mode : 2"] [thread_id=1]
[2024/04/11 16:41:45.507 +08:00] [INFO] [KVStore.cpp:70] ["KVStore inited, eager_raft_log_gc_enabled=false"] [thread_id=1]
[2024/04/11 16:41:45.507 +08:00] [INFO] [MinTSOScheduler.cpp:73] ["thread_hard_limit is 10000, thread_soft_limit is 5000, and active_set_soft_limit is 16 in MinTSOScheduler."] [thread_id=1]
[2024/04/11 16:41:45.508 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.509 +08:00] [INFO] [BlobStore.cpp:131] ["Ignore not blob file [dir=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/page/kvstore] [file=wal] [err_msg=]"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.509 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.509 +08:00] [INFO] [RegionPersister.cpp:381] ["RegionPersister running. Current Run Mode is ONLY_V3"] [thread_id=1]
[2024/04/11 16:41:45.509 +08:00] [INFO] [KVStore.cpp:95] ["Restored 0 regions"] [thread_id=1]
[2024/04/11 16:41:45.509 +08:00] [INFO] [RegionTable.cpp:122] ["RegionTable restore start"] [thread_id=1]
[2024/04/11 16:41:45.509 +08:00] [INFO] [RegionTable.cpp:127] ["RegionTable restore end, n_tables=0"] [thread_id=1]
[2024/04/11 16:41:45.510 +08:00] [WARN] [CPU.cpp:120] ["Cannot recognize the CPU NUMA infomation, use the CPU as 'one numa node'"] [thread_id=1]
[2024/04/11 16:41:45.510 +08:00] [INFO] [SegmentReader.cpp:146] ["Create start, thread_count=16 cpus=[]"] [thread_id=1]
[2024/04/11 16:41:45.510 +08:00] [INFO] [SegmentReader.cpp:151] ["Create end, thread_count=16 cpus=[]"] [thread_id=1]
[2024/04/11 16:41:45.510 +08:00] [INFO] [SegmentReader.cpp:194] ["numa_nodes=[[]] number_of_readers=16"] [thread_id=1]
[2024/04/11 16:41:45.511 +08:00] [DEBUG] [S3Common.cpp:295] ["Aws::InitAPI start"] [thread_id=1]
[2024/04/11 16:41:45.568 +08:00] [TRACE] [S3Common.cpp:151] ["tag=ClientConfiguration message=Request Compression enabled"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.568 +08:00] [TRACE] [S3Common.cpp:151] ["tag=ClientConfiguration message=ClientConfiguration will use MinReqCompression: 10240"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.568 +08:00] [TRACE] [S3Common.cpp:151] ["tag=ClientConfiguration message=ClientConfiguration will use SDK Auto Resolved profile: [default] if not specified by users."] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.568 +08:00] [INFO] [S3Common.cpp:151] ["tag=ClientConfiguration message=Retry Strategy will use the default max attempts."] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.571 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Environment value for variable HOME is /Users/lloyd"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.571 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Home directory is missing the final / appending one to normalize"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.571 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Final Home Directory is /Users/lloyd/"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.571 +08:00] [INFO] [S3Common.cpp:151] ["tag=Aws::Config::AWSConfigFileProfileConfigLoader message=Initializing config loader against fileName /Users/lloyd/.aws/credentials and using profilePrefix = 0"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.571 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Environment value for variable HOME is /Users/lloyd"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.571 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Home directory is missing the final / appending one to normalize"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.571 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Final Home Directory is /Users/lloyd/"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.571 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Environment value for variable HOME is /Users/lloyd"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Home directory is missing the final / appending one to normalize"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Final Home Directory is /Users/lloyd/"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [INFO] [S3Common.cpp:151] ["tag=ProfileConfigFileAWSCredentialsProvider message=Setting provider to read credentials from /Users/lloyd/.aws/credentials for credentials file and /Users/lloyd/.aws/config for the config file , for use with profile default"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [INFO] [S3Common.cpp:151] ["tag=ProcessCredentialsProvider message=Setting process credentials provider to read config from default"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [WARN] [S3Common.cpp:151] ["tag=STSAssumeRoleWithWebIdentityCredentialsProvider message=Token file must be specified to use STS AssumeRole web identity creds provider."] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [INFO] [S3Common.cpp:151] ["tag=SSOBearerTokenProvider message=Setting sso bearerToken provider to read config from default"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [INFO] [S3Common.cpp:151] ["tag=SSOCredentialsProvider message=Setting sso credentials provider to read config from default"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=DefaultAWSCredentialsProviderChain message=The environment variable value AWS_CONTAINER_CREDENTIALS_RELATIVE_URI is "] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=DefaultAWSCredentialsProviderChain message=The environment variable value AWS_CONTAINER_CREDENTIALS_FULL_URI is "] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=DefaultAWSCredentialsProviderChain message=The environment variable value AWS_EC2_METADATA_DISABLED is true"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [INFO] [S3Common.cpp:151] ["tag=Aws::Config::AWSConfigFileProfileConfigLoader message=Unable to open config file /Users/lloyd/.aws/credentials for reading."] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [INFO] [S3Common.cpp:151] ["tag=Aws::Config::AWSProfileConfigLoaderBase message=Failed to reload configuration."] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [INFO] [S3Common.cpp:151] ["tag=ProcessCredentialsProvider message=Failed to find credential process's profile: default"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Environment value for variable HOME is /Users/lloyd"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Home directory is missing the final / appending one to normalize"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Final Home Directory is /Users/lloyd/"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=SSOCredentialsProvider message=Loading token from: /Users/lloyd/.aws/sso/cache/9fbb7fe9bc1e4757bf0cebfd346f3c2011277705.json"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.572 +08:00] [TRACE] [S3Common.cpp:151] ["tag=SSOCredentialsProvider message=Preparing to load token from: /Users/lloyd/.aws/sso/cache/9fbb7fe9bc1e4757bf0cebfd346f3c2011277705.json"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.573 +08:00] [TRACE] [S3Common.cpp:151] ["tag=SSOCredentialsProvider message=Reading content from token file: /Users/lloyd/.aws/sso/cache/9fbb7fe9bc1e4757bf0cebfd346f3c2011277705.json"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.574 +08:00] [ERROR] [S3Common.cpp:151] ["tag=SSOCredentialsProvider message=Cached Token expired at 2023-09-12T11:11:20Z"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.574 +08:00] [INFO] [S3Common.cpp:151] ["tag=ProcessCredentialsProvider message=Failed to find credential process's profile: default"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.574 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Environment value for variable HOME is /Users/lloyd"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.574 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Home directory is missing the final / appending one to normalize"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.574 +08:00] [TRACE] [S3Common.cpp:151] ["tag=FileSystemUtils message=Final Home Directory is /Users/lloyd/"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.574 +08:00] [TRACE] [S3Common.cpp:151] ["tag=SSOCredentialsProvider message=Loading token from: /Users/lloyd/.aws/sso/cache/9fbb7fe9bc1e4757bf0cebfd346f3c2011277705.json"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.574 +08:00] [TRACE] [S3Common.cpp:151] ["tag=SSOCredentialsProvider message=Preparing to load token from: /Users/lloyd/.aws/sso/cache/9fbb7fe9bc1e4757bf0cebfd346f3c2011277705.json"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.574 +08:00] [TRACE] [S3Common.cpp:151] ["tag=SSOCredentialsProvider message=Reading content from token file: /Users/lloyd/.aws/sso/cache/9fbb7fe9bc1e4757bf0cebfd346f3c2011277705.json"] [source=AWSClient] [thread_id=1]
[2024/04/11 16:41:45.575 +08:00] [ERROR] [S3Common.cpp:151] ["tag=SSOCredentialsProvider message=Cached Token expired at 2023-09-12T11:11:20Z"] [source=AWSClient] [thread_id=1]
Note: Google Test filter = RegionKVStoreTest.KVStoreFailRecovery
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from RegionKVStoreTest
[ RUN      ] RegionKVStoreTest.KVStoreFailRecovery
[2024/04/11 16:41:45.584 +08:00] [INFO] [TiFlashTestEnv.cpp:260] ["Clean path /Users/lloyd/projects/tiflash/cmake-build-debug/tmp/region_kvs_test for bootstrap"] [source=Test] [thread_id=1]
[2024/04/11 16:41:45.600 +08:00] [WARN] [ProxyFFI.cpp:917] ["Set mock rust ptr gc function"] [source=MockSetRustGcHelper] [thread_id=1]
[2024/04/11 16:41:45.601 +08:00] [INFO] [KVStore.cpp:70] ["KVStore inited, eager_raft_log_gc_enabled=false"] [thread_id=1]
[2024/04/11 16:41:45.601 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.601 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.601 +08:00] [INFO] [RegionPersister.cpp:381] ["RegionPersister running. Current Run Mode is ONLY_V3"] [thread_id=1]
[2024/04/11 16:41:45.601 +08:00] [INFO] [KVStore.cpp:95] ["Restored 0 regions"] [thread_id=1]
[2024/04/11 16:41:45.607 +08:00] [INFO] [KVStore.cpp:142] ["Parsed proxy config snap_handle_pool_size 4"] [thread_id=1]
[2024/04/11 16:41:45.612 +08:00] [INFO] [KVStore.cpp:390] ["Set store info id: 1234"] [thread_id=1]
[2024/04/11 16:41:45.612 +08:00] [INFO] [kvstore_helper.h:102] ["Finished setup"] [source=RegionKVStoreTest] [thread_id=1]
[2024/04/11 16:41:45.616 +08:00] [INFO] [RegionTable.cpp:57] ["get new table, keyspace=4294967295 table_id=1"] [thread_id=1]
[2024/04/11 16:41:45.620 +08:00] [INFO] [Persistence.cpp:49] ["Start to persist [region_id=1 index=6 table_id=1 ver=6 conf_ver=0 state=Normal peer=id: 2 range=[7480000000000000FF015F728000000000FF0000000000000000FA,7480000000000000FF015F728000000000FF00000A0000000000FA]], cache size: 37 bytes for `debug `"] [thread_id=1]
[2024/04/11 16:41:45.622 +08:00] [INFO] [BlobStat.cpp:146] ["Created a new BlobStat [blob_id=10] [capacity=268435456]"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.624 +08:00] [INFO] [WALStore.cpp:143] ["Creating log file for writing [fullname=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/region_kvs_test/page/kvstore/wal/log_1_0]"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.624 +08:00] [DEBUG] [Persistence.cpp:51] ["Persist [region_id=1] done, cache size: 37 bytes"] [thread_id=1]
[2024/04/11 16:41:45.624 +08:00] [INFO] [KVStore.cpp:438] ["Destroy KVStore"] [thread_id=1]
[2024/04/11 16:41:45.625 +08:00] [INFO] [KVStore.cpp:70] ["KVStore inited, eager_raft_log_gc_enabled=false"] [thread_id=1]
[2024/04/11 16:41:45.625 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.625 +08:00] [INFO] [BlobStore.cpp:131] ["Ignore not blob file [dir=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/region_kvs_test/page/kvstore] [file=wal] [err_msg=]"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.625 +08:00] [INFO] [BlobStat.cpp:146] ["Created a new BlobStat [blob_id=10] [capacity=268435456]"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.625 +08:00] [DEBUG] [WALReader.cpp:176] ["Open log file for reading, file=/Users/lloyd/projects/tiflash/cmake-build-debug/tmp/region_kvs_test/page/kvstore/wal/log_1_0 size=127"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.625 +08:00] [DEBUG] [PageDirectory.cpp:2206] ["After MVCC gc in memory [lowest_seq=1] clean [invalid_snapshot_nums=0] [invalid_page_nums=0] [total_deref_counter=0] [all_del_entries=0]. Still exist [snapshot_nums=0], [page_nums=1]. Longest alive snapshot: [longest_alive_snapshot_time=0] [longest_alive_snapshot_seq=0] [stale_snapshot_nums=0]"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.625 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=1 max_applied_ver=1"] [source=RegionPersister] [thread_id=1]
[2024/04/11 16:41:45.625 +08:00] [INFO] [RegionPersister.cpp:381] ["RegionPersister running. Current Run Mode is ONLY_V3"] [thread_id=1]
[2024/04/11 16:41:45.627 +08:00] [INFO] [KVStore.cpp:95] ["Restored 1 regions"] [thread_id=1]
[2024/04/11 16:41:45.627 +08:00] [INFO] [KVStore.cpp:119] ["[region_id=1 index=6 table_id=1 ver=6 conf_ver=0 state=Normal peer=id: 2 range=[7480000000000000FF015F728000000000FF0000000000000000FA,7480000000000000FF015F728000000000FF00000A0000000000FA]];"] [thread_id=1]
[2024/04/11 16:41:45.627 +08:00] [INFO] [KVStore.cpp:142] ["Parsed proxy config snap_handle_pool_size 4"] [thread_id=1]
[2024/04/11 16:41:45.635 +08:00] [ERROR] [Exception.cpp:96] ["std::exception. Code: 1001, type: std::__1::system_error, e.what() = mutex lock failed: Invalid argument"] [source="virtual void DB::tests::RegionKVStoreTest_KVStoreFailRecovery_Test::TestBody()"] [thread_id=1]
/Users/lloyd/projects/tiflash/dbms/src/Storages/KVStore/tests/gtest_new_kvstore.cpp:372: Failure
Failed
[2024/04/11 16:41:45.637 +08:00] [INFO] [KVStore.cpp:438] ["Destroy KVStore"] [thread_id=1]
[  FAILED  ] RegionKVStoreTest.KVStoreFailRecovery (54 ms)
[----------] 1 test from RegionKVStoreTest (54 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (54 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] RegionKVStoreTest.KVStoreFailRecovery

 1 FAILED TEST
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=2]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=5]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=6]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=7]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=8]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=10]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=11]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=12]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=13]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=14]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=15]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=16]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=17]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=4]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=3]
[2024/04/11 16:41:45.641 +08:00] [INFO] [SegmentReader.cpp:60] ["Pop fail, stop=true"] [thread_id=9]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:45.642 +08:00] [DEBUG] [SegmentReader.cpp:45] [Stopped] [thread_id=1]
[2024/04/11 16:41:46.513 +08:00] [INFO] [KVStore.cpp:438] ["Destroy KVStore"] [thread_id=1]

2. What did you expect to see? (Required)

3. What did you see instead (Required)

4. What is your TiFlash version? (Required)

master

CalvinNeo commented 5 months ago

std::__1::system_error, e.what() = mutex lock failed: Invalid argument