Failed to Start TiFlash When Launching the Cluster

translator_bot · June 22, 2024, 9:23pm

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

Original topic: 启动集群tiflash启动失败

| username: TiDBer_okKdCMUu

【TiDB Usage Environment】Production Environment / Testing / Poc
【TiDB Version】V6.4.0
【Reproduction Path】tiup cluster start tidb-cluster
【Encountered Problem: Problem Phenomenon and Impact】
Startup failed, error in red

Error: failed to start tiflash: failed to start: xxx.xx.xx.xx tiflash-9000.service, please check the instance’s log(/tidb-deploy/tiflash-9000/log) for more detail.: timed out waiting for port 9000 to be started after 2m0s
【Attachments: Screenshot/Log/Monitoring】

[2022/12/16 21:44:44.831 +08:00] [INFO] [RegionPersister.cpp:336] ["RegionPersister running. Current Run Mode is 2"] [thread_id=1]
[2022/12/16 21:44:44.831 +08:00] [INFO] [KVStore.cpp:66] ["Restored 0 regions"] [thread_id=1]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=10]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=12]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=281474976710652]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=14]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=281474976710654]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=16]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=18]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=20]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=281474976710651]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=46]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=34]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=22]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [RegionTable.cpp:169] ["Start to restore"] [thread_id=1]
[2022/12/16 21:44:44.831 +08:00] [INFO] [RegionTable.cpp:175] ["Restore 0 tables"] [thread_id=1]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=24]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=26]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=28]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=281474976710653]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=48]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=36]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=30]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=32]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=38]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=4]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=40]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=42]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=44]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=50]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=52]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=54]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=56]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=58]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=6]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=60]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=62]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=64]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=66]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:492] ["Storage inited done [table_id=8]"] [thread_id=3]
[2022/12/16 21:44:44.831 +08:00] [INFO] [BackgroundService.cpp:44] ["Start background storage gc worker with interval 60 seconds."] [source=BackgroundService] [thread_id=1]
[2022/12/16 21:44:44.831 +08:00] [INFO] [Server.cpp:505] ["Storage inited finish. [total_count=36] [init_count=0] [error_count=0]"] [thread_id=3]
[2022/12/16 21:44:44.848 +08:00] [INFO] [BlobStore.cpp:1037] ["BlobStore gc get status done. gc info: Read-Only Blob: [null]. No GC Blob: [null]. Full GC Blob: [null]. Truncated Blob: [null]."] [source=RegionPersister] [thread_id=4]
[2022/12/16 21:44:44.881 +08:00] [INFO] [FlashService.cpp:81] ["Use a thread pool with 4 threads to handle cop requests."] [source=FlashService] [thread_id=1]
[2022/12/16 21:44:44.881 +08:00] [INFO] [FlashService.cpp:86] ["Use a thread pool with 4 threads to handle batch cop requests."] [source=FlashService] [thread_id=1]
[2022/12/16 21:44:44.882 +08:00] [INFO] [FlashGrpcServerHolder.cpp:118] ["Flash service registered"] [thread_id=1]
[2022/12/16 21:44:44.882 +08:00] [INFO] [FlashGrpcServerHolder.cpp:120] ["Diagnostics service registered"] [thread_id=1]
[2022/12/16 21:44:44.882 +08:00] [INFO] [Server.cpp:310] ["/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tics/contrib/grpc/src/cpp/server/server_builder.cc, line number: 327, log msg : Synchronous server. Num CQs: 1, Min pollers: 1, Max Pollers: 200, CQ timeout (msec): 10000"] [source=grpc] [thread_id=1]
[2022/12/16 21:44:44.882 +08:00] [INFO] [Server.cpp:310] ["/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tics/contrib/grpc/src/core/lib/iomgr/socket_utils_common_posix.cc, line number: 353, log msg : TCP_USER_TIMEOUT is available. TCP_USER_TIMEOUT will be used thereafter"] [source=grpc] [thread_id=1]
[2022/12/16 21:44:44.882 +08:00] [ERROR] [Server.cpp:314] ["/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tics/contrib/grpc/src/core/ext/transport/chttp2/server/insecure/server_chttp2.cc, line number: 48, log msg : {\"created\":\"@1671198284.882528026\",\"description\":\"No address added out of total 1 resolved\",\"file\":\"/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tics/contrib/grpc/src/core/ext/transport/chttp2/server/chttp2_server.cc\",\"file_line\":936,\"referenced_errors\":[{\"created\":\"@1671198284.882521469\",\"description\":\"Unable to configure socket\",\"fd\":34,\"file\":\"/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tics/contrib/grpc/src/core/lib/iomgr/tcp_server_utils_posix_common.cc\",\"file_line\":218,\"referenced_errors\":[{\"created\":\"@1671198284.882517089\",\"description\":\"Cannot assign requested address\",\"errno\":99,\"file\":\"/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tics/contrib/grpc/src/core/lib/iomgr/tcp_server_utils_posix_common.cc\",\"file_line\":191,\"os_error\":\"Cannot assign requested address\",\"syscall\":\"bind\"}]}]}"] [source=grpc] [thread_id=1]
[2022/12/16 21:44:44.982 +08:00] [INFO] [Server.cpp:1226] ["Shutting down storages."] [thread_id=1]
[2022/12/16 21:44:44.982 +08:00] [INFO] [SegmentReader.cpp:94] ["Pop fail, stop=true"] [source=SegmentReader] [thread_id=5]
[2022/12/16 21:44:44.982 +08:00] [INFO] [SegmentReader.cpp:94] ["Pop fail, stop=true"] [source=SegmentReader] [thread_id=6]
[2022/12/16 21:44:44.982 +08:00] [INFO] [SegmentReader.cpp:94] ["Pop fail, stop=true"] [source=SegmentReader] [thread_id=7]
[2022/12/16 21:44:44.982 +08:00] [INFO] [SegmentReader.cpp:94] ["Pop fail, stop=true"] [source=SegmentReader] [thread_id=8]
[2022/12/16 21:44:46.733 +08:00] [INFO] [Server.cpp:867] ["Let tiflash proxy shutdown"] [thread_id=1]
[2022/12/16 21:44:46.733 +08:00] [INFO] [Server.cpp:870] ["Wait for tiflash proxy thread to join"] [thread_id=1]
[2022/12/16 21:44:46.952 +08:00] [INFO] [Server.cpp:872] ["tiflash proxy thread is joined"] [thread_id=1]
[2022/12/16 21:44:46.952 +08:00] [ERROR] [<unknown>] ["DB::Exception: Exception happens when start grpc server, the flash.service_addr may be invalid, flash.service_addr is xxx.xx.xx.xx:3930"] [source=Application] [thread_id=1]
[2022/12/16 21:44:46.952 +08:00] [INFO] [<unknown>] ["shutting down"] [source=Application] [thread_id=1]
[2022/12/16 21:44:46.952 +08:00] [INFO] [BaseDaemon.cpp:315] ["Stop SignalListener thread"] [source=BaseDaemon] [thread_id=9]
[2022/12/16 21:45:02.189 +08:00] [INFO] [<unknown>] ["Welcome to TiFlash"] [thread_id=1]
[2022/12/16 21:45:02.189 +08:00] [INFO] [<unknown>] ["Starting daemon with revision 54381"] [thread_id=1]
[2022/12/16 21:45:02.189 +08:00] [INFO] [<unknown>] ["TiFlash build info: TiFlash\nRelease Version: v6.4.0\nEdition:         Community\nGit Commit Hash: 301561b850ca3545ae359b5430321cee3523f90c\nGit Branch:      heads/refs/tags/v6.4.0\nUTC Build Time:  2022-11-07 10:12:06\nEnable Features: jemalloc sm4(GmSSL) avx avx512 unwind thinlto\nProfile:         RELWITHDEBINFO\n"] [thread_id=1]
[2022/12/16 21:45:02.189 +08:00] [INFO] [<unknown>] ["starting up"] [source=Application] [thread_id=1]
[2022/12/16 21:45:02.190 +08:00] [INFO] [Server.cpp:367] ["Got jemalloc version: 5.3-RC"] [thread_id=1]
[2022/12/16 21:45:02.190 +08:00] [INFO] [Server.cpp:376] ["Not found environment variable MALLOC_CONF"] [thread_id=1]
[2022/12/16 21:45:02.190 +08:00] [INFO] [Server.cpp:382] ["Got jemalloc config: opt.background_thread false, opt.max_background_threads 4"] [thread_id=1]