<p dir="auto"><a href="http://build-us-00.elastic.co/job/es_core_master_centos/8910/testReport/junit/org.elasticsearch.action.admin.indices.create/CreateIndexIT/testCreateAndDeleteIndexConcurrently/" rel="nofollow">http://build-us-00.elastic.co/job/es_core_master_centos/8910/testReport/junit/org.elasticsearch.action.admin.indices.create/CreateIndexIT/testCreateAndDeleteIndexConcurrently/</a></p>
<p dir="auto">Stacktrace:</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="UnavailableShardsException[[test][1] Primary shard is not active or isn't assigned to a known node. Timeout: [1m], request: index {[test][test][AVGADS6IhWB4gLTwZw1z], source[{&quot;index_version&quot;:1}]}]
    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryPhase.retryBecauseUnavailable(TransportReplicationAction.java:665)
    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryPhase.doRun(TransportReplicationAction.java:381)
    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryPhase$3.onTimeout(TransportReplicationAction.java:522)
    at org.elasticsearch.cluster.ClusterStateObserver$ObserverClusterStateListener.onTimeout(ClusterStateObserver.java:236)
    at org.elasticsearch.cluster.service.InternalClusterService$NotifyTimeout.run(InternalClusterService.java:628)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)"><pre class="notranslate"><code class="notranslate">UnavailableShardsException[[test][1] Primary shard is not active or isn't assigned to a known node. Timeout: [1m], request: index {[test][test][AVGADS6IhWB4gLTwZw1z], source[{"index_version":1}]}]
    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryPhase.retryBecauseUnavailable(TransportReplicationAction.java:665)
    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryPhase.doRun(TransportReplicationAction.java:381)
    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
    at org.elasticsearch.action.support.replication.TransportReplicationAction$PrimaryPhase$3.onTimeout(TransportReplicationAction.java:522)
    at org.elasticsearch.cluster.ClusterStateObserver$ObserverClusterStateListener.onTimeout(ClusterStateObserver.java:236)
    at org.elasticsearch.cluster.service.InternalClusterService$NotifyTimeout.run(InternalClusterService.java:628)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
</code></pre></div>
<p dir="auto">Interesting log lines:</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="[2015-12-08 05:25:16,274][WARN ][org.elasticsearch.indices.cluster] [node_t0] [[test][1]] marking and sending shard failed due to [failed to create shard]
org.apache.lucene.store.LockObtainFailedException: Can't lock shard [test][1], timed out after 5000ms
    at org.elasticsearch.env.NodeEnvironment$InternalShardLock.acquire(NodeEnvironment.java:556)
    at org.elasticsearch.env.NodeEnvironment.shardLock(NodeEnvironment.java:485)
    at org.elasticsearch.index.IndexService.createShard(IndexService.java:236)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyInitializingShard(IndicesClusterStateService.java:591)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyNewOrUpdatedShards(IndicesClusterStateService.java:491)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.clusterChanged(IndicesClusterStateService.java:185)
    at org.elasticsearch.cluster.service.InternalClusterService.runTasksForExecutor(InternalClusterService.java:526)
    at org.elasticsearch.cluster.service.InternalClusterService$UpdateTask.run(InternalClusterService.java:596)
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:231)
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:194)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

...

[2015-12-08 05:25:26,295][DEBUG][org.elasticsearch.cluster.routing.allocation] [node_t0] [test][0] ignoring shard failure, unknown allocation id in [test][0], node[w7ZOpTaqRi6UI-q9EjfG2Q], [P], v[1], s[INITIALIZING], a[id=WmeldM5ORfuNr8rWhbHvYQ], unassigned_info[[reason=INDEX_CREATED], at[2015-12-08T05:25:11.268Z]] ([reason=ALLOCATION_FAILED], at[2015-12-08T05:25:26.295Z], details[master {node_t0}{w7ZOpTaqRi6UI-q9EjfG2Q}{local}{local[182]}[mode=&gt;local] marked shard as initializing, but shard is marked as failed, resend shard failure])

...

[2015-12-08 05:25:26,303][DEBUG][org.elasticsearch.gateway] [node_t0] [test][0] found 0 allocations of [test][0], node[null], [P], v[2], s[UNASSIGNED], unassigned_info[[reason=ALLOCATION_FAILED], at[2015-12-08T05:25:26.294Z], details[failed to create shard, failure LockObtainFailedException[Can't lock shard [test][0], timed out after 5000ms]]], highest version: [-1]"><pre class="notranslate"><code class="notranslate">[2015-12-08 05:25:16,274][WARN ][org.elasticsearch.indices.cluster] [node_t0] [[test][1]] marking and sending shard failed due to [failed to create shard]
org.apache.lucene.store.LockObtainFailedException: Can't lock shard [test][1], timed out after 5000ms
    at org.elasticsearch.env.NodeEnvironment$InternalShardLock.acquire(NodeEnvironment.java:556)
    at org.elasticsearch.env.NodeEnvironment.shardLock(NodeEnvironment.java:485)
    at org.elasticsearch.index.IndexService.createShard(IndexService.java:236)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyInitializingShard(IndicesClusterStateService.java:591)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyNewOrUpdatedShards(IndicesClusterStateService.java:491)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.clusterChanged(IndicesClusterStateService.java:185)
    at org.elasticsearch.cluster.service.InternalClusterService.runTasksForExecutor(InternalClusterService.java:526)
    at org.elasticsearch.cluster.service.InternalClusterService$UpdateTask.run(InternalClusterService.java:596)
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:231)
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:194)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

...

[2015-12-08 05:25:26,295][DEBUG][org.elasticsearch.cluster.routing.allocation] [node_t0] [test][0] ignoring shard failure, unknown allocation id in [test][0], node[w7ZOpTaqRi6UI-q9EjfG2Q], [P], v[1], s[INITIALIZING], a[id=WmeldM5ORfuNr8rWhbHvYQ], unassigned_info[[reason=INDEX_CREATED], at[2015-12-08T05:25:11.268Z]] ([reason=ALLOCATION_FAILED], at[2015-12-08T05:25:26.295Z], details[master {node_t0}{w7ZOpTaqRi6UI-q9EjfG2Q}{local}{local[182]}[mode=&gt;local] marked shard as initializing, but shard is marked as failed, resend shard failure])

...

[2015-12-08 05:25:26,303][DEBUG][org.elasticsearch.gateway] [node_t0] [test][0] found 0 allocations of [test][0], node[null], [P], v[2], s[UNASSIGNED], unassigned_info[[reason=ALLOCATION_FAILED], at[2015-12-08T05:25:26.294Z], details[failed to create shard, failure LockObtainFailedException[Can't lock shard [test][0], timed out after 5000ms]]], highest version: [-1]
</code></pre></div>
<p dir="auto">Analysis:</p>
<p dir="auto">What's happening is that index creation fails as locks cannot be obtained for allocating shards (I'm not sure why that is). Shards are marked as failed: This changes UnassignedInfo of the ShardRouting objects by setting reason from INDEX_CREATED to ALLOCATION_FAILED. What this entails is that the PrimaryShardAllocator does not treat these unassigned shards as "new index creation" anymore, but requires that shard data is available before assigning them. Relates to <a class="issue-link js-issue-link" data-error-text="Failed to load title" data-id="120410083" data-permission-text="Title is private" data-url="https://github.com/elastic/elasticsearch/issues/15241" data-hovercard-type="issue" data-hovercard-url="/elastic/elasticsearch/issues/15241/hovercard" href="https://github.com/elastic/elasticsearch/issues/15241">#15241</a>.</p>
<p dir="auto">Test failure: <a href="http://build-us-00.elastic.co/job/es_core_master_window-2008/2553/testReport/junit/org.elasticsearch.indices.state/RareClusterStateIT/testDeleteCreateInOneBulk/" rel="nofollow">http://build-us-00.elastic.co/job/es_core_master_window-2008/2553/testReport/junit/org.elasticsearch.indices.state/RareClusterStateIT/testDeleteCreateInOneBulk/</a></p>
<p dir="auto">The test fails due to a race in acquiring <code class="notranslate">ShardLock</code> locks.</p>
<p dir="auto">When an index is deleted, an asynchronous process is started to process pending deletes on shards of that index. This process first acquires all <code class="notranslate">ShardLock</code> locks for the given index in numeric shard order. Meanwhile, the new index can already have been created, and some shard locks can already be held due to shard creation in <code class="notranslate">IndicesClusterStateService.applyInitializingShard</code>. For example, shard 0 is locked by <code class="notranslate">processPendingDeletes</code> but shard 1 is locked by <code class="notranslate">applyInitializingShard</code>. In that case, <code class="notranslate">processPendingDeletes</code> cannot lock shard 1 and blocks (and will hold lock on shard 0 for 30 minutes). This means that shard 0 cannot be initialised for 30 minutes.</p>
<p dir="auto">Interesting bits of stack trace:</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="&quot;elasticsearch[node_t1][generic][T#2]&quot; ID=602 TIMED_WAITING on java.util.concurrent.Semaphore$NonfairSync@2fc45c3b
    at sun.misc.Unsafe.park(Native Method)
    - timed waiting on java.util.concurrent.Semaphore$NonfairSync@2fc45c3b
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
    at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:409)
    at org.elasticsearch.env.NodeEnvironment$InternalShardLock.acquire(NodeEnvironment.java:555)
    at org.elasticsearch.env.NodeEnvironment.shardLock(NodeEnvironment.java:485)
    at org.elasticsearch.env.NodeEnvironment.lockAllForIndex(NodeEnvironment.java:429)
    at org.elasticsearch.indices.IndicesService.processPendingDeletes(IndicesService.java:649)
    at org.elasticsearch.cluster.action.index.NodeIndexDeletedAction.lockIndexAndAck(NodeIndexDeletedAction.java:101)
    at org.elasticsearch.cluster.action.index.NodeIndexDeletedAction.access$300(NodeIndexDeletedAction.java:46)
    at org.elasticsearch.cluster.action.index.NodeIndexDeletedAction$1.doRun(NodeIndexDeletedAction.java:90)
    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
    Locked synchronizers:
    - java.util.concurrent.ThreadPoolExecutor$Worker@b17810e


&quot;elasticsearch[node_t1][clusterService#updateTask][T#1]&quot; ID=591 TIMED_WAITING on java.util.concurrent.Semaphore$NonfairSync@7fdcd730
    at sun.misc.Unsafe.park(Native Method)
    - timed waiting on java.util.concurrent.Semaphore$NonfairSync@7fdcd730
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
    at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:409)
    at org.elasticsearch.env.NodeEnvironment$InternalShardLock.acquire(NodeEnvironment.java:555)
    at org.elasticsearch.env.NodeEnvironment.shardLock(NodeEnvironment.java:485)
    at org.elasticsearch.index.IndexService.createShard(IndexService.java:234)
    - locked org.elasticsearch.index.IndexService@707e1798
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyInitializingShard(IndicesClusterStateService.java:628)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyNewOrUpdatedShards(IndicesClusterStateService.java:528)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.clusterChanged(IndicesClusterStateService.java:185)
    - locked java.lang.Object@773b911a
    at org.elasticsearch.cluster.service.InternalClusterService$UpdateTask.run(InternalClusterService.java:517)
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:231)
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:194)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
    Locked synchronizers:
    - java.util.concurrent.ThreadPoolExecutor$Worker@26f887da"><pre class="notranslate"><code class="notranslate">"elasticsearch[node_t1][generic][T#2]" ID=602 TIMED_WAITING on java.util.concurrent.Semaphore$NonfairSync@2fc45c3b
    at sun.misc.Unsafe.park(Native Method)
    - timed waiting on java.util.concurrent.Semaphore$NonfairSync@2fc45c3b
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
    at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:409)
    at org.elasticsearch.env.NodeEnvironment$InternalShardLock.acquire(NodeEnvironment.java:555)
    at org.elasticsearch.env.NodeEnvironment.shardLock(NodeEnvironment.java:485)
    at org.elasticsearch.env.NodeEnvironment.lockAllForIndex(NodeEnvironment.java:429)
    at org.elasticsearch.indices.IndicesService.processPendingDeletes(IndicesService.java:649)
    at org.elasticsearch.cluster.action.index.NodeIndexDeletedAction.lockIndexAndAck(NodeIndexDeletedAction.java:101)
    at org.elasticsearch.cluster.action.index.NodeIndexDeletedAction.access$300(NodeIndexDeletedAction.java:46)
    at org.elasticsearch.cluster.action.index.NodeIndexDeletedAction$1.doRun(NodeIndexDeletedAction.java:90)
    at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
    Locked synchronizers:
    - java.util.concurrent.ThreadPoolExecutor$Worker@b17810e


"elasticsearch[node_t1][clusterService#updateTask][T#1]" ID=591 TIMED_WAITING on java.util.concurrent.Semaphore$NonfairSync@7fdcd730
    at sun.misc.Unsafe.park(Native Method)
    - timed waiting on java.util.concurrent.Semaphore$NonfairSync@7fdcd730
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
    at java.util.concurrent.Semaphore.tryAcquire(Semaphore.java:409)
    at org.elasticsearch.env.NodeEnvironment$InternalShardLock.acquire(NodeEnvironment.java:555)
    at org.elasticsearch.env.NodeEnvironment.shardLock(NodeEnvironment.java:485)
    at org.elasticsearch.index.IndexService.createShard(IndexService.java:234)
    - locked org.elasticsearch.index.IndexService@707e1798
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyInitializingShard(IndicesClusterStateService.java:628)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.applyNewOrUpdatedShards(IndicesClusterStateService.java:528)
    at org.elasticsearch.indices.cluster.IndicesClusterStateService.clusterChanged(IndicesClusterStateService.java:185)
    - locked java.lang.Object@773b911a
    at org.elasticsearch.cluster.service.InternalClusterService$UpdateTask.run(InternalClusterService.java:517)
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.runAndClean(PrioritizedEsThreadPoolExecutor.java:231)
    at org.elasticsearch.common.util.concurrent.PrioritizedEsThreadPoolExecutor$TieBreakingPrioritizedRunnable.run(PrioritizedEsThreadPoolExecutor.java:194)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
    Locked synchronizers:
    - java.util.concurrent.ThreadPoolExecutor$Worker@26f887da
</code></pre></div>