[
https://issues.apache.org/jira/browse/SOLR-13486?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17007007#comment-17007007
]
Chris M. Hostetter commented on SOLR-13486:
-------------------------------------------
Ok, I'm playing catchup on all the comments from the last 2 weeks – most of
which are confusing hte hell out of me – so forgive me if this is all over the
place...
----
This Jira is *NOT* a generic tracker for "TestCloudConsistency can sometimes
fail" ... it is tracking a very specific bug, that can impact real world solr
instances in the wild.
The fact that it was discovered via TestCloudConsistency, and that that test
appears to be (AFAICT) the only test we currently have in the code base for
reproducing this _code_ bug does not mean we should use this jira to discuss
every possible failure people encounter w/TestCloudConsistency. Please pay
attention to the specifics of the failures you encounter, and when in doubt
file a new jira (they can always be linked later, but confusing off topic
comments are hard to de-tangle from a jira after the fact)
----
[~erickerickson] : if you are seeing NPEs in your logs when you run
TestCloudConsistency then that most certainly has nothing to do with the this
specific bug being tracked here.
(BUt it's impossible to be certain since you dind't attach any logs or
specifics)
Please open a new jira and move the disucssion of this unrelated problem you
have found to that jira. (or open multiple new jiras if you think you've found
multiple new problems)
----
{quote}The cluster setup and teardown is done for each test 'cause they're
annotated with `@Before` and `@After`. Changing these to `@BeforeClass` and
`@AfterClass`, which at least lessens the confusion. I don't think this is a
real fix given the comments from Chris and Dat, so I'll see if I can still
generate errors with this change.
{quote}
Please *DO NOT* change this test to setup/teardown the cluster in
{{@BeforeClass}} and {{@AfterClass}} – the fact that this test (and others like
it) uses a "pristine" cluster for each test method is very specific – because
the test is mucking with the collection nodes, and this way a failure from one
test (that might leve the cluster in a bad state) won't "bleed over" into
another test and cause spurrious failures.
{quote}What Hoss saw may be an artifact of the fact that the cluster was being
created/destroyed between tests. So far when I only run a single test at a time
I'm not seeing failures, but that's not very conclusive at this point.
{quote}
The bug being tracked here has *NOTHING* to do with a new cluster being
recreated for each test. please note all of the logs & analysis i've already
posted – everything about this bug has to do with when/how the leader is
partitioned & shutdown _during_ the test, and the race condition thta exists as
a result when nodes are trying to recover from that leader while it is trying
to recover from it's tlog.
----
Dawid's {{org.apache.solr.cloud.TestCloudConsistency.zip}} attachment includes
a log that does in fact show the specific problem tracked in this isssue – note
the time stamps of the log messages in the last 2 grep comments...
{noformat}
# here's the replica that is failing to locate doc#4...
hossman@slate:~/tmp$ grep outOfSyncReplicasCannotBecomeLeader-false
org.apache.solr.cloud.TestCloudConsistency.html | grep 'Doc with id=4 not found'
<pre>java.lang.AssertionError: Doc with id=4 not found in
http://127.0.0.1:40399/solr/outOfSyncReplicasCannotBecomeLeader-false due to:
Path not found: /id; rsp={doc=null}
# here's the recovery via replication logging from that replica showing who the
leader is...
hossman@slate:~/tmp$ grep outOfSyncReplicasCannotBecomeLeader-false
org.apache.solr.cloud.TestCloudConsistency.html | grep 'n:127.0.0.1:40399_solr'
| grep recoveryExecutor | grep 'Attempting to replicate from'
1500569 INFO
(recoveryExecutor-10537-thread-1-processing-n:127.0.0.1:40399_solr
x:outOfSyncReplicasCannotBecomeLeader-false_shard1_replica_n3
c:outOfSyncReplicasCannotBecomeLeader-false s:shard1 r:core_node4)
[n:127.0.0.1:40399_solr c:outOfSyncReplicasCannotBecomeLeader-false s:shard1
r:core_node4 x:outOfSyncReplicasCannotBecomeLeader-false_shard1_replica_n3 ]
o.a.s.c.RecoveryStrategy Attempting to replicate from
[http://127.0.0.1:33461/solr/outOfSyncReplicasCannotBecomeLeader-false_shard1_replica_n1/].
# here's when that leader is doing it's tlog replay...
hossman@slate:~/tmp$ grep outOfSyncReplicasCannotBecomeLeader-false
org.apache.solr.cloud.TestCloudConsistency.html | grep 'n:127.0.0.1:33461_solr'
| grep 'Replaying tlog'
1515376 INFO (coreZkRegister-10093-thread-1-processing-n:127.0.0.1:33461_solr
x:outOfSyncReplicasCannotBecomeLeader-false_shard1_replica_n1
c:outOfSyncReplicasCannotBecomeLeader-false s:shard1 r:core_node2)
[n:127.0.0.1:33461_solr c:outOfSyncReplicasCannotBecomeLeader-false s:shard1
r:core_node2 x:outOfSyncReplicasCannotBecomeLeader-false_shard1_replica_n1 ]
o.a.s.c.ZkController Replaying tlog for
http://127.0.0.1:33461/solr/outOfSyncReplicasCannotBecomeLeader-false_shard1_replica_n1/
during startup... NOTE: This can take a while.
{noformat}
...so in that case at least, we are in fact still on topic talking about the
correct bug.
[~dweiss] : if you've encountered other failures that don't match this pattern,
then please file new jiras for those failure patterns – I honestly can't tell
if the other failures you mentioned seeing are the same as the other failures
Erick mentioned seeing or not.
----
{quote}I propose that I open a new JIRA for the test failures and push my
changes from there, then rename this one because what I'm doing does nothing to
address the analysis Hoss did.
{quote}
[~erickerickson] : you haven't attached any logs showing the errors you got,
nor have you attached any patch showing what changes you are suggesting – but
unless those changes address the underlying bug I identified in the description
of this jira, then yes, as i said before: you should open a new jira.
But i really can't understand why you think this jira should be renamed – this
jira tracks a bug and the summary/description make it very clera what that bug
is. If you have unrelated improvements for the test, or have found an unreltaed
bug that manifests in the same test, then those belong in a new jira.
> race condition between leader's "replay on startup" and non-leader's "recover
> from leader" can leave replicas out of sync (TestCloudConsistency)
> ------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: SOLR-13486
> URL: https://issues.apache.org/jira/browse/SOLR-13486
> Project: Solr
> Issue Type: Bug
> Reporter: Chris M. Hostetter
> Assignee: Erick Erickson
> Priority: Major
> Attachments:
> apache_Lucene-Solr-BadApples-NightlyTests-master_61.log.txt.gz,
> apache_Lucene-Solr-BadApples-Tests-8.x_102.log.txt.gz,
> org.apache.solr.cloud.TestCloudConsistency.zip
>
>
> I've been investigating some jenkins failures from TestCloudConsistency,
> which at first glance suggest a problem w/replica(s) recovering after a
> network partition from the leader - but in digging into the logs the root
> cause acturally seems to be a thread race conditions when a replica (the
> leader) is first registered...
> * The {{ZkContainer.registerInZk(...)}} method (which is called by
> {{CoreContainer.registerCore(...)}} & {{CoreContainer.load()}}) is typically
> run in a background thread (via the {{ZkContainer.coreZkRegister}}
> ExecutorService)
> * {{ZkContainer.registerInZk(...)}} delegates to
> {{ZKController.register(...)}} which is ultimately responsible for checking
> if there are any "old" tlogs on disk, and if so handling the "Replaying tlog
> for <URL> during startup" logic
> * Because this happens in a background thread, other logic/requests can be
> handled by this core/replica in the meantime - before it starts (or while in
> the middle of) replaying the tlogs
> ** Notably: *leader's that have not yet replayed tlogs on startup will
> erroneously respond to RTG / Fingerprint / PeerSync requests from other
> replicas w/incomplete data*
> ...In general, it seems scary / fishy to me that a replica can (aparently)
> become *ACTIVE* before it's finished it's {{registerInZk}} + "Replaying tlog
> ... during startup" logic ... particularly since this can happen even for
> replicas that are/become leaders. It seems like this could potentially cause
> a whole host of problems, only one of which manifests in this particular test
> failure:
> * *BEFORE* replicaX's "coreZkRegister" thread reaches the "Replaying tlog
> ... during startup" check:
> ** replicaX can recognize (via zk terms) that it should be the leader(X)
> ** this leaderX can then instruct some other replicaY to recover from it
> ** replicaY can send RTG / PeerSync / FetchIndex requests to the leaderX
> (either on it's own volition, or because it was instructed to by leaderX) in
> an attempt to recover
> *** the responses to these recovery requests will not include updates in the
> tlog files that existed on leaderX prior to startup that hvae not yet been
> replayed
> * *AFTER* replicaY has finished it's recovery, leaderX's "Replaying tlog ...
> during startup" can finish
> ** replicaY now thinks it is in sync with leaderX, but leaderX has
> (replayed) updates the other replicas know nothing about
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-unsubscr...@lucene.apache.org
For additional commands, e-mail: issues-h...@lucene.apache.org
