[
https://issues.apache.org/jira/browse/SOLR-18525?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Amrit Sarkar updated SOLR-18525:
--------------------------------
Description:
If a replica is removed from state.json while the node hosting it is still
inside {{CoreContainer.create}} for that core, the create never returns and the
core name stays locked on that node.
h3. When it happens
{{ZkController.register}} checks that the replica exists in cluster state,
joins leader election and waits for a leader (up to leaderVoteWait + 10 min),
replays any tlog, and only then installs {{UnloadCoreOnDeletedWatcher}}. If the
replica is removed in that window, the watcher sees it gone and calls
{{CoreContainer.unload}} on a core that is still being created.
Since SOLR-17700, {{unload}} waits on the per-core pending op. The create
already holds that op, so:
# *Node already hosts a replica of the collection:* the create thread runs the
watcher inline from {{registerDocCollectionWatcher}} and waits on itself.
# *First replica of the collection on the node:* registering the watcher also
queues an async notification. The notification thread takes the watcher monitor
({{onStateChanged}} is synchronized) and waits for the pending op. The create
thread holds the op and waits for the monitor.
The JVM doesn't flag either as a deadlock, because the per-core lock is the
{{pendingCoreOps}} set, not a monitor. The node just looks stuck.
It takes a slow register to hit this with the Collection API. I reproduced it
with a plain DELETEREPLICA on default timeouts: DELETEREPLICA waits for the
shard lock until ADDREPLICA gives up (90s), its core UNLOAD then parks behind
the create's pending op until the request times out (90s more), and after
another 30s it removes the replica from state.json. If register is still
waiting for a leader at that point (around 210s in), the create deadlocks. That
wait can last leaderVoteWait + 10 min when the shard has no live leader. A
failed ADDREPLICA followed by a DELETEREPLICA cleanup is a likely way to get
there. I haven't tested split rollback (DELETESHARD).
Startup load releases the pending op before registering in the background, so
only {{CoreContainer.create}} is affected (ADDREPLICA, collection create, split
sub-shards). That's why
{{DeleteReplicaTest.raceConditionOnDeleteAndRegisterReplica}}, which covers the
restart path, doesn't catch it.
h3. Repro
I found this while going through the core create and unload locking, and
reproduced it locally with a test that forces the race. The test is attached
({{SOLR-18525-repro-test.patch}}, applies on main):
{noformat}
git apply SOLR-18525-repro-test.patch
./gradlew :solr:core:test --tests
"org.apache.solr.cloud.CoreCreateReplicaRemovedDeadlockTest"
{noformat}
It stretches the window with a test {{UpdateLog}} that blocks in
{{recoverFromLog()}}, the last hook point after the existence check, removes
the replica while register is paused, then lets the create continue. Five
tests, all fail every time, with and without the Overseer (seeds
BAE60C1D1A3FBB96 and 814077321E33EF2E):
* both variants with the replica removed by a DELETECORE state update (fast,
about 45s each)
* both variants with the replica removed by a real DELETEREPLICA on default
timeouts (about 4 min each)
* follow-up core admin calls on the stuck core name
On timeout each test fails with the stacks of the stuck threads.
h3. Stack (variant 1, main @ 22a8cfebbbd)
{noformat}
"qtp1724204461-60-null-8" WAITING on java.lang.Object@142135dd
(SolrCores.modifyLock)
at o.a.s.core.SolrCores.waitAddPendingCoreOps(SolrCores.java:291)
at o.a.s.core.CoreContainer.unload(CoreContainer.java:2064)
at
o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher.onStateChanged(ZkController.java:2970)
- locked o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher@439e24f4
at
o.a.s.common.cloud.ZkStateReader.registerDocCollectionWatcher(ZkStateReader.java:1626)
at o.a.s.cloud.ZkController.register(ZkController.java:1572)
at o.a.s.cloud.ZkController.register(ZkController.java:1385)
at o.a.s.core.ZkContainer.lambda$registerInZk$0(ZkContainer.java:261)
at o.a.s.core.ZkContainer.registerInZk(ZkContainer.java:290)
at o.a.s.core.CoreContainer.registerCore(CoreContainer.java:1465)
at o.a.s.core.CoreContainer.createFromDescriptor(CoreContainer.java:1692)
at o.a.s.core.CoreContainer.create(CoreContainer.java:1548)
{noformat}
Variant 2:
{noformat}
"qtp1724204461-52-null-4" BLOCKED on
ZkController$UnloadCoreOnDeletedWatcher@26c37a27 owned by
"watches-44-thread-1-..."
at
o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher.onStateChanged(ZkController.java:2964)
at
o.a.s.common.cloud.ZkStateReader.registerDocCollectionWatcher(ZkStateReader.java:1626)
at o.a.s.cloud.ZkController.register(ZkController.java:1572)
... down to CoreContainer.create(CoreContainer.java:1548)
"watches-44-thread-1-..." WAITING on java.lang.Object@142135dd
at o.a.s.core.SolrCores.waitAddPendingCoreOps(SolrCores.java:291)
at o.a.s.core.CoreContainer.unload(CoreContainer.java:2064)
at
o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher.onStateChanged(ZkController.java:2970)
- locked ZkController$UnloadCoreOnDeletedWatcher@26c37a27
at o.a.s.common.cloud.ZkStateReader$Notification.run(ZkStateReader.java:1950)
{noformat}
h3. Impact
* The core admin CREATE never returns. ADDREPLICA fails after the 90s shard
request timeout.
* The core stays loaded, and its state updates are rejected ("Failed to update
state because the replica does not exist").
* Every later state.json change for the collection starts another watcher
thread that blocks on the same monitor.
* On that node, core admin UNLOAD and RELOAD of the same core name block (no
response within the test's 20s bound, threads parked in
{{waitAddPendingCoreOps}}), and CREATE with the same name fails with "Already
creating a core with name ...". DELETEREPLICA's own UNLOAD thread stays parked
after its request times out.
* Stopping the node releases everything (shutdown completes in about half a
second). I found no other way to clear it.
h3. Where it came from
SOLR-17700 (fix version 9.9) made the public {{unload}} take the core op lock
and moved the old body to {{unloadWithoutCoreOp}}. It switched the
{{NotInClusterStateException}} path inside {{createFromDescriptor}} to
{{unloadWithoutCoreOp}}, but the watcher path through {{register}} still calls
{{unload}}. 9.8.1's {{unload}} doesn't take the lock, so it doesn't hang here.
Reverting SOLR-17700 isn't the answer though: before it, the watcher would
likely unload the core in the middle of the create.
Related: SOLR-12187 (added the watcher), SOLR-16497 (finer grained locking in
SolrCores).
I'm working on a fix.
was:
If a replica is removed from state.json while the node hosting it is still
inside {{CoreContainer.create}} for that core, the create never returns and the
core name stays locked on that node.
h3. When it happens
{{ZkController.register}} checks that the replica exists in cluster state,
joins leader election and waits for a leader (up to leaderVoteWait + 10 min),
replays any tlog, and only then installs {{UnloadCoreOnDeletedWatcher}}. If the
replica is removed in that window, the watcher sees it gone and calls
{{CoreContainer.unload}} on a core that is still being created.
Since SOLR-17700, {{unload}} waits on the per-core pending op. The create
already holds that op, so:
# *Node already hosts a replica of the collection:* the create thread runs the
watcher inline from {{registerDocCollectionWatcher}} and waits on itself.
# *First replica of the collection on the node:* registering the watcher also
queues an async notification. The notification thread takes the watcher monitor
({{onStateChanged}} is synchronized) and waits for the pending op. The create
thread holds the op and waits for the monitor.
The JVM doesn't flag either as a deadlock, because the per-core lock is the
{{pendingCoreOps}} set, not a monitor. The node just looks stuck.
It takes a slow register to hit this with the Collection API. I reproduced it
with a plain DELETEREPLICA on default timeouts: DELETEREPLICA waits for the
shard lock until ADDREPLICA gives up (90s), its core UNLOAD then parks behind
the create's pending op until the request times out (90s more), and after
another 30s it removes the replica from state.json. If register is still
waiting for a leader at that point (around 210s in), the create deadlocks. That
wait can last leaderVoteWait + 10 min when the shard has no live leader. A
failed ADDREPLICA followed by a DELETEREPLICA cleanup is a likely way to get
there. I haven't tested split rollback (DELETESHARD).
Startup load releases the pending op before registering in the background, so
only {{CoreContainer.create}} is affected (ADDREPLICA, collection create, split
sub-shards). That's why
{{DeleteReplicaTest.raceConditionOnDeleteAndRegisterReplica}}, which covers the
restart path, doesn't catch it.
h3. Repro
I found this while going through the core create and unload locking, and
reproduced it locally with a test that forces the race. The test is attached
({{SOLR-XXXXX-repro-test.patch}}, applies on main):
{noformat}
git apply SOLR-XXXXX-repro-test.patch
./gradlew :solr:core:test --tests
"org.apache.solr.cloud.CoreCreateReplicaRemovedDeadlockTest"
{noformat}
It stretches the window with a test {{UpdateLog}} that blocks in
{{recoverFromLog()}}, the last hook point after the existence check, removes
the replica while register is paused, then lets the create continue. Five
tests, all fail every time, with and without the Overseer (seeds
BAE60C1D1A3FBB96 and 814077321E33EF2E):
* both variants with the replica removed by a DELETECORE state update (fast,
about 45s each)
* both variants with the replica removed by a real DELETEREPLICA on default
timeouts (about 4 min each)
* follow-up core admin calls on the stuck core name
On timeout each test fails with the stacks of the stuck threads.
h3. Stack (variant 1, main @ 22a8cfebbbd)
{noformat}
"qtp1724204461-60-null-8" WAITING on java.lang.Object@142135dd
(SolrCores.modifyLock)
at o.a.s.core.SolrCores.waitAddPendingCoreOps(SolrCores.java:291)
at o.a.s.core.CoreContainer.unload(CoreContainer.java:2064)
at
o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher.onStateChanged(ZkController.java:2970)
- locked o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher@439e24f4
at
o.a.s.common.cloud.ZkStateReader.registerDocCollectionWatcher(ZkStateReader.java:1626)
at o.a.s.cloud.ZkController.register(ZkController.java:1572)
at o.a.s.cloud.ZkController.register(ZkController.java:1385)
at o.a.s.core.ZkContainer.lambda$registerInZk$0(ZkContainer.java:261)
at o.a.s.core.ZkContainer.registerInZk(ZkContainer.java:290)
at o.a.s.core.CoreContainer.registerCore(CoreContainer.java:1465)
at o.a.s.core.CoreContainer.createFromDescriptor(CoreContainer.java:1692)
at o.a.s.core.CoreContainer.create(CoreContainer.java:1548)
{noformat}
Variant 2:
{noformat}
"qtp1724204461-52-null-4" BLOCKED on
ZkController$UnloadCoreOnDeletedWatcher@26c37a27 owned by
"watches-44-thread-1-..."
at
o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher.onStateChanged(ZkController.java:2964)
at
o.a.s.common.cloud.ZkStateReader.registerDocCollectionWatcher(ZkStateReader.java:1626)
at o.a.s.cloud.ZkController.register(ZkController.java:1572)
... down to CoreContainer.create(CoreContainer.java:1548)
"watches-44-thread-1-..." WAITING on java.lang.Object@142135dd
at o.a.s.core.SolrCores.waitAddPendingCoreOps(SolrCores.java:291)
at o.a.s.core.CoreContainer.unload(CoreContainer.java:2064)
at
o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher.onStateChanged(ZkController.java:2970)
- locked ZkController$UnloadCoreOnDeletedWatcher@26c37a27
at o.a.s.common.cloud.ZkStateReader$Notification.run(ZkStateReader.java:1950)
{noformat}
h3. Impact
* The core admin CREATE never returns. ADDREPLICA fails after the 90s shard
request timeout.
* The core stays loaded, and its state updates are rejected ("Failed to update
state because the replica does not exist").
* Every later state.json change for the collection starts another watcher
thread that blocks on the same monitor.
* On that node, core admin UNLOAD and RELOAD of the same core name block (no
response within the test's 20s bound, threads parked in
{{waitAddPendingCoreOps}}), and CREATE with the same name fails with "Already
creating a core with name ...". DELETEREPLICA's own UNLOAD thread stays parked
after its request times out.
* Stopping the node releases everything (shutdown completes in about half a
second). I found no other way to clear it.
h3. Where it came from
SOLR-17700 (fix version 9.9) made the public {{unload}} take the core op lock
and moved the old body to {{unloadWithoutCoreOp}}. It switched the
{{NotInClusterStateException}} path inside {{createFromDescriptor}} to
{{unloadWithoutCoreOp}}, but the watcher path through {{register}} still calls
{{unload}}. 9.8.1's {{unload}} doesn't take the lock, so it doesn't hang here.
Reverting SOLR-17700 isn't the answer though: before it, the watcher would
likely unload the core in the middle of the create.
Related: SOLR-12187 (added the watcher), SOLR-16497 (finer grained locking in
SolrCores).
I'm working on a fix.
> Core create hangs forever if its replica is removed from cluster state during
> registration
> ------------------------------------------------------------------------------------------
>
> Key: SOLR-18525
> URL: https://issues.apache.org/jira/browse/SOLR-18525
> Project: Solr
> Issue Type: Bug
> Components: SolrCloud
> Affects Versions: 9.9, 9.10, 10.0, 9.11, 9.10.1
> Reporter: Amrit Sarkar
> Priority: Major
> Attachments: SOLR-18525-repro-test.patch
>
>
> If a replica is removed from state.json while the node hosting it is still
> inside {{CoreContainer.create}} for that core, the create never returns and
> the core name stays locked on that node.
> h3. When it happens
> {{ZkController.register}} checks that the replica exists in cluster state,
> joins leader election and waits for a leader (up to leaderVoteWait + 10 min),
> replays any tlog, and only then installs {{UnloadCoreOnDeletedWatcher}}. If
> the replica is removed in that window, the watcher sees it gone and calls
> {{CoreContainer.unload}} on a core that is still being created.
> Since SOLR-17700, {{unload}} waits on the per-core pending op. The create
> already holds that op, so:
> # *Node already hosts a replica of the collection:* the create thread runs
> the watcher inline from {{registerDocCollectionWatcher}} and waits on itself.
> # *First replica of the collection on the node:* registering the watcher also
> queues an async notification. The notification thread takes the watcher
> monitor ({{onStateChanged}} is synchronized) and waits for the pending op.
> The create thread holds the op and waits for the monitor.
> The JVM doesn't flag either as a deadlock, because the per-core lock is the
> {{pendingCoreOps}} set, not a monitor. The node just looks stuck.
> It takes a slow register to hit this with the Collection API. I reproduced it
> with a plain DELETEREPLICA on default timeouts: DELETEREPLICA waits for the
> shard lock until ADDREPLICA gives up (90s), its core UNLOAD then parks behind
> the create's pending op until the request times out (90s more), and after
> another 30s it removes the replica from state.json. If register is still
> waiting for a leader at that point (around 210s in), the create deadlocks.
> That wait can last leaderVoteWait + 10 min when the shard has no live leader.
> A failed ADDREPLICA followed by a DELETEREPLICA cleanup is a likely way to
> get there. I haven't tested split rollback (DELETESHARD).
> Startup load releases the pending op before registering in the background, so
> only {{CoreContainer.create}} is affected (ADDREPLICA, collection create,
> split sub-shards). That's why
> {{DeleteReplicaTest.raceConditionOnDeleteAndRegisterReplica}}, which covers
> the restart path, doesn't catch it.
> h3. Repro
> I found this while going through the core create and unload locking, and
> reproduced it locally with a test that forces the race. The test is attached
> ({{SOLR-18525-repro-test.patch}}, applies on main):
> {noformat}
> git apply SOLR-18525-repro-test.patch
> ./gradlew :solr:core:test --tests
> "org.apache.solr.cloud.CoreCreateReplicaRemovedDeadlockTest"
> {noformat}
> It stretches the window with a test {{UpdateLog}} that blocks in
> {{recoverFromLog()}}, the last hook point after the existence check, removes
> the replica while register is paused, then lets the create continue. Five
> tests, all fail every time, with and without the Overseer (seeds
> BAE60C1D1A3FBB96 and 814077321E33EF2E):
> * both variants with the replica removed by a DELETECORE state update (fast,
> about 45s each)
> * both variants with the replica removed by a real DELETEREPLICA on default
> timeouts (about 4 min each)
> * follow-up core admin calls on the stuck core name
> On timeout each test fails with the stacks of the stuck threads.
> h3. Stack (variant 1, main @ 22a8cfebbbd)
> {noformat}
> "qtp1724204461-60-null-8" WAITING on java.lang.Object@142135dd
> (SolrCores.modifyLock)
> at o.a.s.core.SolrCores.waitAddPendingCoreOps(SolrCores.java:291)
> at o.a.s.core.CoreContainer.unload(CoreContainer.java:2064)
> at
> o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher.onStateChanged(ZkController.java:2970)
> - locked o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher@439e24f4
> at
> o.a.s.common.cloud.ZkStateReader.registerDocCollectionWatcher(ZkStateReader.java:1626)
> at o.a.s.cloud.ZkController.register(ZkController.java:1572)
> at o.a.s.cloud.ZkController.register(ZkController.java:1385)
> at o.a.s.core.ZkContainer.lambda$registerInZk$0(ZkContainer.java:261)
> at o.a.s.core.ZkContainer.registerInZk(ZkContainer.java:290)
> at o.a.s.core.CoreContainer.registerCore(CoreContainer.java:1465)
> at o.a.s.core.CoreContainer.createFromDescriptor(CoreContainer.java:1692)
> at o.a.s.core.CoreContainer.create(CoreContainer.java:1548)
> {noformat}
> Variant 2:
> {noformat}
> "qtp1724204461-52-null-4" BLOCKED on
> ZkController$UnloadCoreOnDeletedWatcher@26c37a27 owned by
> "watches-44-thread-1-..."
> at
> o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher.onStateChanged(ZkController.java:2964)
> at
> o.a.s.common.cloud.ZkStateReader.registerDocCollectionWatcher(ZkStateReader.java:1626)
> at o.a.s.cloud.ZkController.register(ZkController.java:1572)
> ... down to CoreContainer.create(CoreContainer.java:1548)
> "watches-44-thread-1-..." WAITING on java.lang.Object@142135dd
> at o.a.s.core.SolrCores.waitAddPendingCoreOps(SolrCores.java:291)
> at o.a.s.core.CoreContainer.unload(CoreContainer.java:2064)
> at
> o.a.s.cloud.ZkController$UnloadCoreOnDeletedWatcher.onStateChanged(ZkController.java:2970)
> - locked ZkController$UnloadCoreOnDeletedWatcher@26c37a27
> at
> o.a.s.common.cloud.ZkStateReader$Notification.run(ZkStateReader.java:1950)
> {noformat}
> h3. Impact
> * The core admin CREATE never returns. ADDREPLICA fails after the 90s shard
> request timeout.
> * The core stays loaded, and its state updates are rejected ("Failed to
> update state because the replica does not exist").
> * Every later state.json change for the collection starts another watcher
> thread that blocks on the same monitor.
> * On that node, core admin UNLOAD and RELOAD of the same core name block (no
> response within the test's 20s bound, threads parked in
> {{waitAddPendingCoreOps}}), and CREATE with the same name fails with "Already
> creating a core with name ...". DELETEREPLICA's own UNLOAD thread stays
> parked after its request times out.
> * Stopping the node releases everything (shutdown completes in about half a
> second). I found no other way to clear it.
> h3. Where it came from
> SOLR-17700 (fix version 9.9) made the public {{unload}} take the core op lock
> and moved the old body to {{unloadWithoutCoreOp}}. It switched the
> {{NotInClusterStateException}} path inside {{createFromDescriptor}} to
> {{unloadWithoutCoreOp}}, but the watcher path through {{register}} still
> calls {{unload}}. 9.8.1's {{unload}} doesn't take the lock, so it doesn't
> hang here. Reverting SOLR-17700 isn't the answer though: before it, the
> watcher would likely unload the core in the middle of the create.
> Related: SOLR-12187 (added the watcher), SOLR-16497 (finer grained locking in
> SolrCores).
> I'm working on a fix.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
