Clickhouse Error : Table is in readonly mode (version 19.14.6.12)

[Kathiresh Nadar]

Recently we noticed one of our clickhouse cluster went into readonly mode and we were not able to recover it to write data into it. Below are the logs just before it went into read only. Any idea what could have triggered this.

We have a 3 server Cluster of Clickhouse with Zookeeper for monitoring.

From logs it seems server 3 clickhouse got restarted, but it was triggered automatically as there are no logs in history of restart.

Server 1 Logs : 

2022.08.20 23:23:17.238441 [ 228 ] {450cf4c4-7aac-4512-8851-8092d5ed6b83} <Error> executeQuery: Code: 289, e.displayText() = DB::Exception: Replica doesn't have part 20220820_20220820_167146_167146_0 which was successfully written to quorum of other replicas. Send query to another replica or disable 'select_sequential_consistency' setting. (version 19.14.6.12) (from 202.162.235.109:39726) (in query: SELECT lastrun_time FROM nmi_lastrun WHERE instance_id = 0 AND name = 'defpub' ORDER BY lastrun_time desc LIMIT 1 FORMAT TabSeparatedWithNamesAndTypes;), Stack trace:

0. 0x3353de0 StackTrace::StackTrace() /usr/bin/clickhouse
1. 0x335e0ff DB::Exception::Exception(std::string const&, int) /usr/bin/clickhouse
2. 0x610f73d DB::StorageReplicatedMergeTree::read(std::vector<std::string, std::allocator<std::string> > const&, DB::SelectQueryInfo const&, DB::Context const&, DB::QueryProcessingStage::Enum, unsigned long, unsigned int) /usr/bin/clickhouse
3. 0x5f0a74b void DB::InterpreterSelectQuery::executeFetchColumns<DB::InterpreterSelectQuery::Pipeline>(DB::QueryProcessingStage::Enum, DB::InterpreterSelectQuery::Pipeline&, std::shared_ptr<DB::SortingInfo> const&, std::shared_ptr<DB::PrewhereInfo> const&, std::vector<std::string, std::allocator<std::string> > const&) /usr/bin/clickhouse
4. 0x5f0e0a5 void DB::InterpreterSelectQuery::executeImpl<DB::InterpreterSelectQuery::Pipeline>(DB::InterpreterSelectQuery::Pipeline&, std::shared_ptr<DB::IBlockInputStream> const&) /usr/bin/clickhouse
5. 0x5ee9a62 DB::InterpreterSelectQuery::executeWithMultipleStreams() /usr/bin/clickhouse
6. 0x5f0fc34 DB::InterpreterSelectWithUnionQuery::executeWithMultipleStreams() /usr/bin/clickhouse
7. 0x5f117f6 DB::InterpreterSelectWithUnionQuery::execute() /usr/bin/clickhouse
8. 0x5ffaefa ? /usr/bin/clickhouse

Server 3 Logs : 

2022.08.20 23:24:14.399308 [ 6 ] {} <Trace> eaf2_low.nmi_deferredpublishtask (MergerMutator): Merged 2 parts: from 20220903_2022
0919_293516_295317_1491_293788 to 20220903_20220904_295318_295318_0
2022.08.20 23:24:14.411097 [ 277 ] {6dfa185b-b8e1-4756-943c-779e798a9572} <Error> executeQuery: Code: 394, e.displayText() = DB:
:Exception: Query was cancelled (version 19.14.6.12) (from 202.162.235.109:57558) (in query: SELECT t1.* FROM nmi_deferredpublis
htask AS t1 WHERE t1.mature_date IN ('2022-08-20') AND t1.mature_time >= toDateTime('2022-08-20 17:41:12','UTC') and t1.mature_t
ime <= toDateTime('2022-08-20 17:42:44','UTC') AND t1.id NOT IN ( SELECT t2.id FROM nmi_deferredpublishtask_published AS t2 WHER
E t2.mature_date IN ('2022-08-20')) and abs(t1.customer_id)  % 3 = 0 limit 1000000 FORMAT TabSeparatedWithNamesAndTypes;), Stack
 trace:

0. 0x3353de0 StackTrace::StackTrace() /usr/bin/clickhouse
1. 0x335e0ff DB::Exception::Exception(std::string const&, int) /usr/bin/clickhouse
2. 0x5d90ccd DB::IBlockInputStream::isCancelledOrThrowIfKilled() const /usr/bin/clickhouse
3. 0x5d93f72 DB::IBlockInputStream::read() /usr/bin/clickhouse
4. 0x6459253 DB::CreatingSetsBlockInputStream::createOne(DB::SubqueryForSet&) /usr/bin/clickhouse
5. 0x645b0bf DB::CreatingSetsBlockInputStream::readPrefixImpl() /usr/bin/clickhouse
6. 0x5d90f62 DB::IBlockInputStream::readPrefix() /usr/bin/clickhouse
7. 0x5d90e32 DB::IBlockInputStream::readPrefix() /usr/bin/clickhouse
8. 0x5d90e32 DB::IBlockInputStream::readPrefix() /usr/bin/clickhouse
9. 0x5dbb0f0 DB::copyData(DB::IBlockInputStream&, DB::IBlockOutputStream&, std::atomic<bool>*) /usr/bin/clickhouse
10. 0x5ffe137 DB::executeQuery(DB::ReadBuffer&, DB::WriteBuffer&, bool, DB::Context&, std::function<void (std::string const&)>, std::function<void (std::string const&)>) /usr/bin/clickhouse
11. 0x33cd621 DB::HTTPHandler::processQuery(Poco::Net::HTTPServerRequest&, HTMLForm&, Poco::Net::HTTPServerResponse&, DB::HTTPHandler::Output&) /usr/bin/clickhouse
12. 0x33d06e1 DB::HTTPHandler::handleRequest(Poco::Net::HTTPServerRequest&, Poco::Net::HTTPServerResponse&) /usr/bin/clickhouse
13. 0x6a91da9 Poco::Net::HTTPServerConnection::run() /usr/bin/clickhouse
14. 0x6a8d60f Poco::Net::TCPServerConnection::start() /usr/bin/clickhouse
15. 0x6a8dcf5 Poco::Net::TCPServerDispatcher::run() /usr/bin/clickhouse
16. 0x6f90421 Poco::PooledThread::run() /usr/bin/clickhouse
17. 0x6f8c1e8 Poco::ThreadImpl::runnableEntry(void*) /usr/bin/clickhouse
18. 0x766d06f ? /usr/bin/clickhouse
12. 0x33d06e1 DB::HTTPHandler::handleRequest(Poco::Net::HTTPServerRequest&, Poco::Net::HTTPServerResponse&) /usr/bin/clickhouse
13. 0x6a91da9 Poco::Net::HTTPServerConnection::run() /usr/bin/clickhouse
14. 0x6a8d60f Poco::Net::TCPServerConnection::start() /usr/bin/clickhouse
15. 0x6a8dcf5 Poco::Net::TCPServerDispatcher::run() /usr/bin/clickhouse
16. 0x6f90421 Poco::PooledThread::run() /usr/bin/clickhouse
17. 0x6f8c1e8 Poco::ThreadImpl::runnableEntry(void*) /usr/bin/clickhouse
18. 0x766d06f ? /usr/bin/clickhouse
19. 0x7f069f710dd5 start_thread /usr/lib64/libpthread-2.17.so
20. 0x7f069f02e02d __clone /usr/lib64/libc-2.17.so

2022.08.20 23:24:14.411341 [ 277 ] {6dfa185b-b8e1-4756-943c-779e798a9572} <Trace> UnionBlockInputStream: Waiting for threads to finish
2022.08.20 23:24:14.412748 [ 277 ] {6dfa185b-b8e1-4756-943c-779e798a9572} <Trace> UnionBlockInputStream: Waited for threads to finish
2022.08.20 23:24:14.564349 [ 277 ] {6dfa185b-b8e1-4756-943c-779e798a9572} <Debug> MemoryTracker: Peak memory usage (for query): 1.07 GiB.
2022.08.20 23:24:14.564553 [ 277 ] {6dfa185b-b8e1-4756-943c-779e798a9572} <Error> HTTPHandler: Code: 394, e.displayText() = DB::Exception: Query was cancelled, Stack trace:

0. 0x3353de0 StackTrace::StackTrace() /usr/bin/clickhouse
1. 0x335e0ff DB::Exception::Exception(std::string const&, int) /usr/bin/clickhouse
2. 0x5d90ccd DB::IBlockInputStream::isCancelledOrThrowIfKilled() const /usr/bin/clickhouse
3. 0x5d93f72 DB::IBlockInputStream::read() /usr/bin/clickhouse
4. 0x6459253 DB::CreatingSetsBlockInputStream::createOne(DB::SubqueryForSet&) /usr/bin/clickhouse
5. 0x645b0bf DB::CreatingSetsBlockInputStream::readPrefixImpl() /usr/bin/clickhouse
6. 0x5d90f62 DB::IBlockInputStream::readPrefix() /usr/bin/clickhouse
7. 0x5d90e32 DB::IBlockInputStream::readPrefix() /usr/bin/clickhouse
8. 0x5d90e32 DB::IBlockInputStream::readPrefix() /usr/bin/clickhouse
9. 0x5dbb0f0 DB::copyData(DB::IBlockInputStream&, DB::IBlockOutputStream&, std::atomic<bool>*) /usr/bin/clickhouse
10. 0x5ffe137 DB::executeQuery(DB::ReadBuffer&, DB::WriteBuffer&, bool, DB::Context&, std::function<void (std::string const&)>,
10. 0x5ffe137 DB::executeQuery(DB::ReadBuffer&, DB::WriteBuffer&, bool, DB::Context&, std::function<void (std::string const&)>, std::function<void (std::string const&)>) /usr/bin/clickhouse
11. 0x33cd621 DB::HTTPHandler::processQuery(Poco::Net::HTTPServerRequest&, HTMLForm&, Poco::Net::HTTPServerResponse&, DB::HTTPHandler::Output&) /usr/bin/clickhouse
12. 0x33d06e1 DB::HTTPHandler::handleRequest(Poco::Net::HTTPServerRequest&, Poco::Net::HTTPServerResponse&) /usr/bin/clickhouse
13. 0x6a91da9 Poco::Net::HTTPServerConnection::run() /usr/bin/clickhouse
14. 0x6a8d60f Poco::Net::TCPServerConnection::start() /usr/bin/clickhouse
15. 0x6a8dcf5 Poco::Net::TCPServerDispatcher::run() /usr/bin/clickhouse
16. 0x6f90421 Poco::PooledThread::run() /usr/bin/clickhouse
17. 0x6f8c1e8 Poco::ThreadImpl::runnableEntry(void*) /usr/bin/clickhouse
18. 0x766d06f ? /usr/bin/clickhouse
19. 0x7f069f710dd5 start_thread /usr/lib64/libpthread-2.17.so
20. 0x7f069f02e02d __clone /usr/lib64/libc-2.17.so
 (version 19.14.6.12)
2022.08.20 23:24:14.598903 [ 1 ] {} <Information> Application: Closed connections. But 2 remains. Tip: To increase wait time add to config: <shutdown_wait_unfinished>60</shutdown_wait_unfinished>
2022.08.20 23:24:14.600434 [ 1 ] {} <Information> Application: Will shutdown forcefully.
2022.08.20 23:30:01.551346 [ 1 ] {} <Information> : Starting ClickHouse 19.14.6.12 with revision 54425
2022.08.20 23:30:01.556149 [ 1 ] {} <Information> Application: starting up
2022.08.20 23:30:01.573444 [ 1 ] {} <Information> StatusFile: Status file /var/lib/clickhouse/status already exists - unclean restart. Contents:
PID: 11464
Started at: 2022-08-19 09:48:12
Revision: 54425

2022.08.20 23:30:01.573689 [ 1 ] {} <Debug> Application: rlimit on number of file descriptors is 262144
2022.08.20 23:30:01.573717 [ 1 ] {} <Debug> Application: Initializing DateLUT.
2022.08.20 23:30:01.573730 [ 1 ] {} <Trace> Application: Initialized DateLUT with time zone 'Asia/Kolkata'.
2022.08.20 23:30:01.741586 [ 2 ] {} <Debug> system.trace_log: Removing part from filesystem 202208_8288915_8288915_0
2022.08.20 23:30:01.743098 [ 2 ] {} <Debug> system.trace_log: Removing part from filesystem 202208_8288916_8288916_0
2022.08.20 23:30:01.743876 [ 2 ] {} <Debug> system.trace_log: Removing part from filesystem 202208_8288917_8288917_0
2022.08.20 23:30:01.744651 [ 2 ] {} <Debug> system.trace_log: Removing part from filesystem 202208_8288918_8288918_0
2022.08.20 23:30:01.745404 [ 2 ] {} <Debug> system.trace_log: Removing part from filesystem 202208_8288919_8288919_0
2022.08.20 23:30:01.746768 [ 2 ] {} <Debug> system.trace_log: Removing part from filesystem 202208_8288920_8288920_0
2022.08.20 23:30:01.748442 [ 2 ] {} <Debug> system.trace_log: Removing part from filesystem 202208_8288921_8288921_0
2022.08.20 23:30:01.749775 [ 2 ] {} <Debug> system.trace_log: Removing part from filesystem 202208_8288922_8288922_0
2022.08.20 23:30:01.751158 [ 2 ] {} <Debug> system.trace_log: Removing part from filesystem 202208_8288923_8288923_0
2022.08.20 23:30:01.758292 [ 1 ] {} <Information> DatabaseOrdinary (eaf): Total 3 tables.
2022.08.20 23:30:01.763224 [ 23 ] {} <Information> BackgroundSchedulePool: Create BackgroundSchedulePool with 16 threads
2022.08.20 23:30:01.780186 [ 11 ] {} <Trace> ZooKeeper: initialized, hosts: 202.162.247.53:2181,202.162.247.40:2181,202.162.242.92:2181,202.162.247.4:2181,202.162.247.46:2181,202.162.235.136:2181
2022.08.20 23:30:01.781428 [ 14 ] {} <Debug> eaf.nmi_deferredpublishtask_published: Loading data parts
2022.08.20 23:30:01.781540 [ 11 ] {} <Debug> eaf.nmi_deferredpublishtask: Loading data parts
2022.08.20 23:30:01.781629 [ 23 ] {} <Debug> eaf.nmi_lastrun: Loading data parts
2022.08.20 23:30:01.796159 [ 14 ] {} <Debug> eaf.nmi_deferredpublishtask_published: Loaded data parts (26 items)
2022.08.20 23:30:01.796547 [ 23 ] {} <Debug> eaf.nmi_lastrun: Loaded data parts (32 items)
2022.08.20 23:30:01.797140 [ 14 ] {} <Warning> eaf.nmi_deferredpublishtask_published: No metadata in ZooKeeper: table will be in readonly mode.
2022.08.20 23:30:01.797343 [ 11 ] {} <Debug> eaf.nmi_deferredpublishtask: Loaded data parts (53 items)
2022.08.20 23:30:01.797564 [ 23 ] {} <Warning> eaf.nmi_lastrun: No metadata in ZooKeeper: table will be in readonly mode.
2022.08.20 23:30:01.798323 [ 11 ] {} <Warning> eaf.nmi_deferredpublishtask: No metadata in ZooKeeper: table will be in readonly mode.
2022.08.20 23:30:01.798409 [ 1 ] {} <Information> DatabaseOrdinary (eaf): Starting up tables.
2022.08.20 23:30:01.798742 [ 1 ] {} <Information> DatabaseOrdinary (eaf2): Total 4 tables.
2022.08.20 23:30:01.800849 [ 85 ] {} <Debug> eaf2.nmi_lastrun: Loading data parts
2022.08.20 23:30:01.800852 [ 43 ] {} <Debug> eaf2.nmi_lastrun_bk: Loading data parts
2022.08.20 23:30:01.801216 [ 69 ] {} <Debug> eaf2.nmi_deferredpublishtask: Loading data parts
2022.08.20 23:30:01.802014 [ 83 ] {} <Debug> eaf2.nmi_deferredpublishtask_published: Loading data parts
2022.08.20 23:30:01.805080 [ 85 ] {} <Debug> eaf2.nmi_lastrun: Loaded data parts (12 items)
2022.08.20 23:30:01.805120 [ 43 ] {} <Debug> eaf2.nmi_lastrun_bk: Loaded data parts (3 items)