[
https://issues.apache.org/jira/browse/OAK-3436?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14907888#comment-14907888
]
Chetan Mehrotra edited comment on OAK-3436 at 9/25/15 11:37 AM:
----------------------------------------------------------------
[testcase patch|^OAK-3436-0.patch] for reproducing the scenario.
Had to modify {{AsyncIndexUpdate}} to allow configuring the lease timeout
easily. Whats happening is like this
{{AsyncIndexUpdate}} maintains an array of temp checkpoints which are released
before indexing is done. Upon each indexing cycle new checkpoint that gets
created is pushed to this array.
Now assume you have 2 cluster nodes and each running AsyncIndexUpdate (N1 and
N2).
# Base state - Indexing done and current checkpoint stored in {{:async}} is CP1
# Async indexer starts on N2 and creates a new checkpoint CP2. At time T1 - It
updates the tmp checkpoint array with CP2 and proceed for
indexing. Indexing is yet not complete
# At this stage async indexer starts on N1 and sees base checkpoint as CP1 with
CP2 in tmp checkpoint array. Also due to some reason default 15 min lease time
has also expired. So at time T2 this run proceeds further and removed the tmp
checkpoint CP2
# Now async indexer on N2 completes and releases CP1 (base checkpoint) and
updates the {{:async}} node with lease status
# Now async indexer on N1 also proceeds but commit fails due to concurrent
update on {{:async}}
# Now at some point async indexer on N2 starts again and looks for CP2 but its
has already been removed!
If we move cleanup of tmp checkpoint to finally clause in run method this then
current working checkpoint would not get lost
[~alex.parvulescu] [~amitj_76] Thoughts?
{noformat}
15:28:56.420 INFO [main] DocumentNodeStore.java:545 Initialized
DocumentNodeStore with clusterNodeId: 1 (no cluster node info)
15:28:56.444 INFO [main] DocumentNodeStore.java:545 Initialized
DocumentNodeStore with clusterNodeId: 2 (no cluster node info)
15:28:56.595 DEBUG [main] AsyncIndexUpdate.java:268 [async] Running
background index task
15:28:56.611 INFO [main] AsyncIndexUpdate.java:307 [async] Initial
index update
15:28:56.679 INFO [aysnc-index-update-async] IndexUpdate.java:117 Reindexing
will be performed for following indexes: [/oak:index/rootIndex]
15:28:56.692 INFO [aysnc-index-update-async] IndexUpdate.java:226 Indexing
report
- /oak:index/rootIndex*(1)
15:28:56.712 INFO [aysnc-index-update-async] AsyncIndexUpdate.java:449 [async]
Reindexing completed for indexes: [/oak:index/rootIndex*(1)] in 94.72 ms
15:28:56.744 INFO [main] AsyncIndexUpdateClusterTest.java:108 ===== Phase 1 -
Created base setup
15:28:56.759 DEBUG [Thread-1] AsyncIndexUpdate.java:268 [async] Running
background index task
15:28:56.793 INFO [main] AsyncIndexUpdateClusterTest.java:128 ===== Phase 2 -
async2 now waiting for signal
15:28:56.797 DEBUG [Thread-2] AsyncIndexUpdate.java:268 [async] Running
background index task
15:28:56.805 DEBUG [aysnc-index-update-async] AsyncIndexUpdate.java:224 [async]
Releasing temporary checkpoint r15003f0fde9-0-2: true
15:28:56.811 INFO [main] AsyncIndexUpdateClusterTest.java:141 ===== Phase 3 -
async1 now waiting for signal
15:28:56.812 DEBUG [aysnc-index-update-async] IndexUpdate.java:228 Indexing
report
- /oak:index/rootIndex(1)
15:28:56.822 DEBUG [aysnc-index-update-async] AsyncIndexUpdate.java:463 [async]
AsyncIndex update run completed in 43.90 ms. Indexed 1 nodes
15:28:56.824 DEBUG [aysnc-index-update-async] IndexUpdate.java:228 Indexing
report
- /oak:index/rootIndex(2)
15:28:56.860 WARN [aysnc-index-update-async] AsyncIndexUpdate.java:359 [async]
The index update failed
org.apache.jackrabbit.oak.plugins.document.FailedWithConflictException:
OakMerge0004: The node 1:/:async was changed in revision
r15003f0fe30-0-2, which was applied after the base revision
r15003f0fe26-0-1, before
r15003f0fe52-0-1
at
org.apache.jackrabbit.oak.plugins.document.ConflictException.asCommitFailedException(ConflictException.java:59)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch$InMemory.merge(DocumentNodeStoreBranch.java:494)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.merge0(DocumentNodeStoreBranch.java:173)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.merge(DocumentNodeStoreBranch.java:129)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.DocumentRootBuilder.merge(DocumentRootBuilder.java:158)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.merge(DocumentNodeStore.java:1556)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.mergeWithConcurrencyCheck(AsyncIndexUpdate.java:493)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.access$400(AsyncIndexUpdate.java:76)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate$AsyncUpdateCallback.close(AsyncIndexUpdate.java:242)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.updateIndex(AsyncIndexUpdate.java:454)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.run(AsyncIndexUpdate.java:336)
~[classes/:na]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
Caused by: org.apache.jackrabbit.oak.plugins.document.ConflictException: The
node 1:/:async was changed in revision
r15003f0fe30-0-2, which was applied after the base revision
r15003f0fe26-0-1, before
r15003f0fe52-0-1
at
org.apache.jackrabbit.oak.plugins.document.Commit.checkConflicts(Commit.java:579)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.Commit.createOrUpdateNode(Commit.java:485)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.Commit.applyToDocumentStore(Commit.java:369)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.Commit.applyToDocumentStore(Commit.java:263)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.Commit.applyInternal(Commit.java:232)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.Commit.apply(Commit.java:217)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.persist(DocumentNodeStoreBranch.java:282)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.persist(DocumentNodeStoreBranch.java:252)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.access$300(DocumentNodeStoreBranch.java:54)
~[classes/:na]
at
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch$InMemory.merge(DocumentNodeStoreBranch.java:490)
~[classes/:na]
... 10 common frames omitted
15:28:56.865 INFO [main] AsyncIndexUpdateClusterTest.java:154 ===== Phase 4 -
Both async allowed to complete
15:28:56.874 DEBUG [main] AsyncIndexUpdate.java:268 [async] Running
background index task
15:28:56.875 WARN [main] AsyncIndexUpdate.java:292 [async] Failed to
retrieve previously indexed checkpoint r15003f0fde9-0-2; re-running the initial
index update
15:28:56.876 DEBUG [aysnc-index-update-async] AsyncIndexUpdate.java:224 [async]
Releasing temporary checkpoint r15003f0fd51-0-1: true
15:28:56.876 DEBUG [aysnc-index-update-async] AsyncIndexUpdate.java:224 [async]
Releasing temporary checkpoint r15003f0fde9-0-2: true
15:28:56.880 INFO [aysnc-index-update-async] IndexUpdate.java:152 Found a new
index node [rootIndex]. Reindexing is requested
15:28:56.886 INFO [aysnc-index-update-async] IndexUpdate.java:117 Reindexing
will be performed for following indexes: [/oak:index/rootIndex]
15:28:56.897 INFO [aysnc-index-update-async] IndexUpdate.java:226 Indexing
report
- /oak:index/rootIndex*(3)
15:28:56.915 INFO [aysnc-index-update-async] AsyncIndexUpdate.java:449 [async]
Reindexing completed for indexes: [/oak:index/rootIndex*(3)] in 39.43 ms
15:28:56.920 INFO [main] AsyncIndexUpdateClusterTest.java:161 ===== Phase 5 -
Triggered next cycle on async2
{noformat}
Logs from the testcase. Near end it can be seen that checkpoints have gone
missing and reindexing is being performed
was (Author: chetanm):
[testcase patch|^OAK-3436-0.patch] for reproducing the scenario.
Had to modify {{AsyncIndexUpdate}} to allow configuring the lease timeout
easily. Whats happening is like this
{{AsyncIndexUpdate}} maintains an array of temp checkpoints which are released
before indexing is done. Upon each indexing cycle new checkpoint that gets
created is pushed to this array.
Now assume you have 2 cluster nodes and each running AsyncIndexUpdate (N1 and
N2).
# Base state - Indexing done and current checkpoint stored in {{:async}} is CP1
# Async indexer starts on N2 and creates a new checkpoint CP2. At time T1 - It
updates the tmp checkpoint array with CP2 and proceed for
indexing. Indexing is yet not complete
# At this stage async indexer starts on N1 and sees base checkpoint as CP1 with
CP2 in tmp checkpoint array. Also due to some reason default 15 min lease time
has also expired. So at time T2 this run proceeds further and removed the tmp
checkpoint CP2
# Now async indexer on N2 completes and releases CP1 (base checkpoint) and
updates the {{:async}} node with lease status
# Now async indexer on N1 also proceeds but commit fails due to concurrent
update on {{:async}}
# Now at some point async indexer on N2 starts again and looks for CP2 but its
has already been removed!
If we move cleanup of tmp checkpoint to finally clause in run method this then
current working checkpoint would not get lost
[~alex.parvulescu] [~amitj_76] Thoughts?
> Prevent missing checkpoint due to unstable topology from causing complete
> reindexing
> ------------------------------------------------------------------------------------
>
> Key: OAK-3436
> URL: https://issues.apache.org/jira/browse/OAK-3436
> Project: Jackrabbit Oak
> Issue Type: Improvement
> Components: query
> Reporter: Chetan Mehrotra
> Assignee: Chetan Mehrotra
> Fix For: 1.3.7, 1.2.7, 1.0.22
>
> Attachments: AsyncIndexUpdateClusterTest.java, OAK-3436-0.patch
>
>
> Async indexing logic relies on embedding application to ensure that async
> indexing job is run as a singleton in a cluster. For Sling based apps it
> depends on Sling Discovery support. At times it is being seen that if
> topology is not stable then different cluster nodes can consider them as
> leader and execute the async indexing job concurrently.
> This can cause problem as both cluster node might not see same repository
> state (due to write skew and eventual consistency) and might remove the
> checkpoint which other cluster node is still relying upon. For e.g. consider
> a 2 node cluster N1 and N2 where both are performing async indexing.
> # Base state - CP1 is the checkpoint for "async" job
> # N2 starts indexing and removes changes CP1 to CP2. For Mongo the
> checkpoints are saved in {{settings}} collection
> # N1 also decides to execute indexing but has yet not seen the latest
> repository state so still thinks that CP1 is the base checkpoint and tries to
> read it. However CP1 is already removed from {{settings}} and this makes N1
> think that checkpoint is missing and it decides to reindex everything!
> To avoid this topology must be stable but at Oak level we should still handle
> such a case and avoid doing a full reindexing. So we would need to have a
> {{MissingCheckpointStrategy}} similar to {{MissingIndexEditorStrategy}} as
> done in OAK-2203
> Possible approaches
> # A1 - Fail the indexing run if checkpoint is missing - Checkpoint being
> missing can have valid reason and invalid reason. Need to see what are valid
> scenarios where a checkpoint can go missing
> # A2 - When a checkpoint is created also store the creation time. When a
> checkpoint is found to be missing and its a *recent* checkpoint then fail the
> run. For e.g. we would fail the run till checkpoint found to be missing is
> less than an hour old (for just started take startup time into account)
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
