Deadlock logging

doc/internal-options.md

@@ -34,4 +34,6 @@
 * `MANTICORE_BINLOG_COMMON` - if present, and nothing set in config, binlog will be common for all tables 
 * `MANTICORE_LOG_ES_COMPAT` - verbose logging compat events, ruled by this env variable
 * `MANTICORE_TRACK_RT_ERRORS` - check newborn disk chunks, and if it is damaged, report up to this N of errors.
-* `MANTICORE_BUDDY_TIMEOUT` - (default 3 seconds) daemon's wait duration for a buddy message at startup
+* `MANTICORE_BUDDY_TIMEOUT` - (default 3 seconds) daemon's wait duration for a buddy message at startup
+* `MANTICORE_SHUTDOWN_ALONES_DEADLINE` - (default 30 seconds) daemon's deadline to wait until all alone (i.e. not in thread-pool) threads are finished.
+* `MANTICORE_SHUTDOWN_ALONES_POLL` - (default 10 seconds) - how long daemon wait alone threads to finish. On shutdown, daemon sends to all alone threads 'TERM' signal, then wait up to 10 seconds, polling these threads to be finished. Then, if 'ALONES_DELTA' is achieved, and some stalled threads are still detected, it reports about them and continue shutdown. Otherwise, it starts the loop - again, from sending signal to the rest of the threads.

src/searchdha.cpp

@@ -3714,8 +3714,8 @@ class LazyNetEvents_c : ISphNoncopyable, protected NetEventsFlavour_c
 			m_dInternalTasks.Add ( pTask );
 		} else
 		{
-			sphLogDebugL ( "- AddToQueue, ext=%d", m_pEnqueuedTasks ? m_pEnqueuedTasks->GetLength () + 1 : 1 );
 			ScopedMutex_t tLock ( m_dActiveLock );
+			sphLogDebugL ( "- AddToQueue, ext=%d", m_pEnqueuedTasks ? m_pEnqueuedTasks->GetLength () + 1 : 1 );
 			if ( !m_pEnqueuedTasks )
 				m_pEnqueuedTasks = new VectorTask_c;
 			m_pEnqueuedTasks->Add ( pTask );
@@ -3799,8 +3799,8 @@ class LazyNetEvents_c : ISphNoncopyable, protected NetEventsFlavour_c
 
 		if ( bRemoveClosingFromEpoll )
 			events_change_io (pTask);
-		else
-			AddToQueue ( pTask, pConnection->InNetLoop () );
+
+		AddToQueue ( pTask, pConnection->InNetLoop () );
 	}
 
 	void DisableWrite ( AgentConn_t * pConnection )

src/searchdreplication.cpp

@@ -2427,8 +2427,8 @@ StrVec_t ReplicationCluster_t::GetIndexes() const noexcept
 			dIndexes.Add ( tIndex.first );
 		for ( const auto & tIndex : hIndexesLoaded )
 		{
-			assert ( !hIndexes[tIndex.first] );
-			dIndexes.Add ( tIndex.first );
+			if ( !hIndexes[tIndex.first] )
+				dIndexes.Add ( tIndex.first );
 		}
 	});
 	return dIndexes;
@@ -2682,6 +2682,8 @@ static bool SendIndex ( const CSphString & sIndex, ReplicationClusterRefPtr_c pC
 	int64_t tmStart = sphMicroTimer();
 	while ( true )
 	{
+		if ( sphInterrupted() )
+			return TlsMsg::Err ("Abort SendIndex() due to daemon's shutdown");
 		pCluster->m_pSstProgress->StageBegin ( SstStage_e::WAIT_NODES );
 		if ( HasNotReadyNodes ( pCluster ) )
 		{

src/threads_detached.cpp

@@ -63,7 +63,8 @@ void Detached::MakeAloneIteratorAvailable ()
 //#endif
 }
 
-static int64_t g_tmShutdownAllAlonesDelta = 3; // max allowed wait in seconds
+static int64_t g_tmShutdownAllAlonesDelta = env_long ("MANTICORE_SHUTDOWN_ALONES_DEADLINE").value_or(30); // max allowed wait in seconds
+static int64_t g_tmShutdownAllAlonesBetweenTries = env_long("MANTICORE_SHUTDOWN_ALONES_POLL").value_or(10);
 
 void Detached::SetNotifier ( ShutdownNotifierFn fnNotifier ) noexcept
 {
@@ -113,7 +114,7 @@ void Detached::ShutdownAllAlones()
 
 			sphSleepMsec ( 50 );
 			iStart += 50;
-			if ( iStart >= 10000 ) // wait 10 seconds between tries
+			if ( iStart >= 1000*g_tmShutdownAllAlonesBetweenTries ) // wait 10 seconds between tries
 			{
 				sphWarning ( "ShutdownAllAlones catch still has %d alone threads", iThreads );
 				break;

test/clt-tests/sharding/rollback/daemon-shutdown-deadlock.rec

@@ -0,0 +1,70 @@
+Daemon shutdown deadlock: graceful `searchd --stopwait` of a node hangs in ThreadPool_c::StopAll() during a sharded-table rebalance on rejoin. Pure daemon bug (no Buddy involved). Expected: graceful stop returns 0; buggy daemon never returns (timeout -> exit 124).
+
+––– comment –––
+Start 3-node cluster
+––– input –––
+export INSTANCE=1
+––– output –––
+––– block: ../../base/replication/start-searchd-precach –––
+––– input –––
+export INSTANCE=2
+––– output –––
+––– block: ../../base/replication/start-searchd-precach –––
+––– input –––
+export INSTANCE=3
+––– output –––
+––– block: ../../base/replication/start-searchd-precach –––
+––– input –––
+export CLUSTER_NAME=c TABLE_NAME=t
+––– output –––
+––– block: ../../base/replication/create-cluster –––
+––– block: ../../base/replication/join-cluster-on-all-nodes –––
+––– comment –––
+Create sharded table with RF=2 (shards spread across nodes; node1 holds both shards)
+––– input –––
+mysql -h0 -P1306 -e "CREATE TABLE ${CLUSTER_NAME}:${TABLE_NAME} (id bigint, account string, amount float, ts int) shards='2' rf='2'"; echo $?
+––– output –––
+0
+––– input –––
+mysql -h0 -P1306 -e "INSERT INTO ${TABLE_NAME} (id, account, amount, ts) VALUES (1, 'ACC001', 100.50, 1000), (2, 'ACC002', 200.75, 2000), (3, 'ACC003', 150.25, 3000), (4, 'ACC001', 300.00, 4000), (5, 'ACC002', 250.50, 5000)"; echo $?
+––– output –––
+0
+––– comment –––
+First failure: kill node 1 gracefully (this stop works), insert during outage, restart node 1
+––– input –––
+export INSTANCE=1; stdbuf -oL searchd --stopwait -c test/clt-tests/base/searchd-with-flexible-ports.conf > /dev/null; echo "Node 1 killed"
+––– output –––
+Node 1 killed
+––– input –––
+timeout 30 bash -c 'while lsof -i :${INSTANCE}306 &>/dev/null; do sleep 1; done'
+––– output –––
+––– input –––
+timeout 10 grep -qm1 'becoming master' <(tail -n 1000 -f /var/log/manticore-{2,3}/searchd.log 2>/dev/null); echo $?
+––– output –––
+0
+––– input –––
+mysql -h0 -P2306 -e "INSERT INTO ${TABLE_NAME} (id, account, amount, ts) VALUES (6, 'ACC003', 175.00, 6000), (7, 'ACC001', 225.75, 7000)"; echo $?
+––– output –––
+0
+––– input –––
+export INSTANCE=1
+––– output –––
+––– block: ../../base/replication/start-searchd-precach –––
+––– comment –––
+Wait for node 1 to rejoin and cluster to reach primary on all nodes
+––– input –––
+timeout 60 bash -c 'until for i in 1 2 3; do mysql -h0 -P${i}306 -e "SHOW STATUS LIKE '"'"'cluster_c_status'"'"'\G" 2>/dev/null | grep -q "Value: primary" || exit 1; done; do sleep 1; done'; echo "rejoined=$?"
+––– output –––
+rejoined=0
+––– comment –––
+Second failure: stop node 2 GRACEFULLY during the sharded rebalance. This is where the daemon deadlocks: searchd --stopwait enters Shutdown() -> ThreadPool_c::StopAll() and blocks forever joining a worker thread that was never signalled to exit (a galera ServiceThd outlives provider destruction). Guarded with timeout 40 so the test fails fast instead of hanging. A healthy daemon returns exit 0; the buggy daemon yields exit 124 (timed out = deadlocked).
+––– input –––
+export INSTANCE=2; timeout 40 searchd --stopwait -c test/clt-tests/base/searchd-with-flexible-ports.conf >/dev/null 2>&1; echo "node2_stopwait_exit=$?"
+––– output –––
+node2_stopwait_exit=0
+––– comment –––
+Cleanup (force-kill any deadlocked node so the container exits cleanly)
+––– input –––
+pkill -9 searchd 2>/dev/null; sleep 1; echo done
+––– output –––
+done