Understanding Index creation!

roshni · June 7, 2018, 12:43pm

While creating an index on a single node using the following -
date; curl -X PUT "localhost:9200/test" -H 'Content-Type: application/json' -d' { "settings" : { "number_of_shards" : "4", "number_of_replicas" : "0" }, "mappings": { "type1": { "properties": { "name": { "type": "text" } } } } }';date

Im getting the following logs -

    `[2018-06-07T17:24:21,177][DEBUG][o.e.c.s.ClusterService   ] [node2] processing [create-index [test], cause [api]]: execute
[2018-06-07T17:24:21,181][DEBUG][o.e.i.IndicesService     ] [node2] creating Index [[test/eS6b3EHwRlqMkO0PIoXt6w]], shards [4]/[0] - reason [create index]
[2018-06-07T17:24:21,181][DEBUG][o.e.i.s.IndexStore       ] [node2] [test] using index.store.throttle.type [NONE], with index.store.throttle.max_bytes_per_sec [null]
[2018-06-07T17:24:21,182][DEBUG][o.e.i.m.MapperService    ] [node2] [test] using dynamic[true]
[2018-06-07T17:24:21,215][INFO ][o.e.c.m.MetaDataCreateIndexService] [node2] [test] creating index, cause [api], templates [], shards [4]/[0], mappings [type1]
[2018-06-07T17:24:21,218][DEBUG][o.e.i.IndicesService     ] [node2] [test] closing ... (reason [NO_LONGER_ASSIGNED])
[2018-06-07T17:24:21,218][DEBUG][o.e.i.IndicesService     ] [node2] [test/eS6b3EHwRlqMkO0PIoXt6w] closing index service (reason [NO_LONGER_ASSIGNED][cleaning up after validating index on master])
[2018-06-07T17:24:21,218][DEBUG][o.e.i.c.b.BitsetFilterCache] [node2] [test] clearing all bitsets because [close]
[2018-06-07T17:24:21,219][DEBUG][o.e.i.c.q.IndexQueryCache] [node2] [test] full cache clear, reason [close]
[2018-06-07T17:24:21,219][DEBUG][o.e.i.c.b.BitsetFilterCache] [node2] [test] clearing all bitsets because [close]
[2018-06-07T17:24:21,219][DEBUG][o.e.i.IndicesService     ] [node2] [test/eS6b3EHwRlqMkO0PIoXt6w] closed... (reason [NO_LONGER_ASSIGNED][cleaning up after validating index on master])
[2018-06-07T17:24:21,219][DEBUG][o.e.c.s.ClusterService   ] [node2] cluster state updated, version [7], source [create-index [test], cause [api]]
[2018-06-07T17:24:21,219][DEBUG][o.e.c.s.ClusterService   ] [node2] publishing cluster state version [7]
[2018-06-07T17:24:21,219][DEBUG][o.e.c.s.ClusterService   ] [node2] applying cluster state version 7
[2018-06-07T17:24:21,219][DEBUG][o.e.c.s.ClusterService   ] [node2] set local cluster state to version 7
[2018-06-07T17:24:21,219][DEBUG][o.e.i.c.IndicesClusterStateService] [node2] [[test/eS6b3EHwRlqMkO0PIoXt6w]] creating index
[2018-06-07T17:24:21,220][DEBUG][o.e.i.IndicesService     ] [node2] creating Index [[test/eS6b3EHwRlqMkO0PIoXt6w]], shards [4]/[0] - reason [create index]
[2018-06-07T17:24:21,220][DEBUG][o.e.i.s.IndexStore       ] [node2] [test] using index.store.throttle.type [NONE], with index.store.throttle.max_bytes_per_sec [null]
[2018-06-07T17:24:21,227][DEBUG][o.e.i.m.MapperService    ] [node2] [test] using dynamic[true]
[2018-06-07T17:24:21,229][DEBUG][o.e.i.m.MapperService    ] [node2] [test] [[test/eS6b3EHwRlqMkO0PIoXt6w]] added mapping [type1], source [{"type1":{"properties":{"name":{"type":"text"}}}}]

`

I m not able to understand this part (towards the beginning )

[2018-06-07T17:24:21,215][INFO ][o.e.c.m.MetaDataCreateIndexService] [node2] [test] creating index, cause [api], templates [], shards [4]/[0], mappings [type1]
[2018-06-07T17:24:21,218][DEBUG][o.e.i.IndicesService     ] [node2] [test] closing ... (reason [NO_LONGER_ASSIGNED])
[2018-06-07T17:24:21,218][DEBUG][o.e.i.IndicesService     ] [node2] [test/eS6b3EHwRlqMkO0PIoXt6w] closing index service (reason [NO_LONGER_ASSIGNED][cleaning up after validating index on master])
[2018-06-07T17:24:21,218][DEBUG][o.e.i.c.b.BitsetFilterCache] [node2] [test] clearing all bitsets because [close]
[2018-06-07T17:24:21,219][DEBUG][o.e.i.c.q.IndexQueryCache] [node2] [test] full cache clear, reason [close]
[2018-06-07T17:24:21,219][DEBUG][o.e.i.c.b.BitsetFilterCache] [node2] [test] clearing all bitsets because [close]
[2018-06-07T17:24:21,219][DEBUG][o.e.i.IndicesService     ] [node2] [test/eS6b3EHwRlqMkO0PIoXt6w] closed... (reason [NO_LONGER_ASSIGNED][cleaning up after validating index on master])

The reason for this closing and cleaning index on master ???

The last logs recieved for index creation are

T17:24:21,678][DEBUG][o.e.i.s.IndexShard       ] [node2] [test][0] state: [POST_RECOVERY]->[STARTED], reason [global state is [STARTED]]
[2018-06-07T17:24:21,710][DEBUG][o.e.c.s.ClusterService   ] [node2] processing [shard-started[shard id [[test][3]], allocation id [NM1vVi1gQW2-5v9_MWW2Kw], primary term [0], message [after new shard recovery], shard id [[test][0]], allocation id [CV1E5LL6ScSIp2oxYM1tOg], primary term [0], message [after new shard recovery], shard id [[test][3]], allocation id [NM1vVi1gQW2-5v9_MWW2Kw], primary term [0], message [master {node2}{prwtCCGCRxKgBpW1MvpyVQ}{8dQ7rZanTkeNvC4GBuRSTw}{127.0.0.1}{127.0.0.1:9300} marked shard as initializing, but shard state is [POST_RECOVERY], mark shard as started], shard id [[test][0]], allocation id [CV1E5LL6ScSIp2oxYM1tOg], primary term [0], message [master {node2}{prwtCCGCRxKgBpW1MvpyVQ}{8dQ7rZanTkeNvC4GBuRSTw}{127.0.0.1}{127.0.0.1:9300} marked shard as initializing, but shard state is [POST_RECOVERY], mark shard as started]]]: took [33ms] done applying updated cluster_state (version: 9, uuid: DeKOGswFTTGOxVl7zZ4Phw)

Why is the shard in POST RECOVERY state ???

cbuescher · June 15, 2018, 10:28am

I'm also not very familiar with this but did a quick code search for parts of these log messages and found these locations that are likely to be the source for this output:

github.com

elastic/elasticsearch/blob/6.2/server/src/main/java/org/elasticsearch/cluster/metadata/MetaDataCreateIndexService.java#L548


      
                      RoutingTable.Builder routingTableBuilder = RoutingTable.builder(updatedState.routingTable())
                          .addAsNew(updatedState.metaData().index(request.index()));
                      updatedState = allocationService.reroute(
                          ClusterState.builder(updatedState).routingTable(routingTableBuilder.build()).build(),
                          "index [" + request.index() + "] created");
                  }
                  removalExtraInfo = "cleaning up after validating index on master";
                  removalReason = IndexRemovalReason.NO_LONGER_ASSIGNED;
                  return updatedState;
              } finally {
                  if (createdIndex != null) {
                      // Index was already partially created - need to clean up
                      indicesService.removeIndex(createdIndex, removalReason, removalExtraInfo);
                  }
              }
          }
          
          @Override
          public void onFailure(String source, Exception e) {
              if (e instanceof ResourceAlreadyExistsException) {
                  logger.trace((Supplier<?>) () -> new ParameterizedMessage("[{}] failed to create", request.index()), e);

This condition is met when createdIndex is set here:

github.com

elastic/elasticsearch/blob/6.2/server/src/main/java/org/elasticsearch/cluster/metadata/MetaDataCreateIndexService.java#L440


      
          if (waitForActiveShards == ActiveShardCount.DEFAULT) {
              waitForActiveShards = tmpImd.getWaitForActiveShards();
          }
          if (waitForActiveShards.validate(tmpImd.getNumberOfReplicas()) == false) {
              throw new IllegalArgumentException("invalid wait_for_active_shards[" + request.waitForActiveShards() +
                  "]: cannot be greater than number of shard copies [" +
                  (tmpImd.getNumberOfReplicas() + 1) + "]");
          }
          // create the index here (on the master) to validate it can be created, as well as adding the mapping
          final IndexService indexService = indicesService.createIndex(tmpImd, Collections.emptyList());
          createdIndex = indexService.index();
          // now add the mappings
          MapperService mapperService = indexService.mapperService();
          try {
              mapperService.merge(mappings, MergeReason.MAPPING_UPDATE, request.updateAllTypes());
          } catch (Exception e) {
              removalExtraInfo = "failed on parsing default mapping/mappings on index creation";
              throw e;
          }
          
          if (request.recoverFrom() == null) {

From the comment two lines above to me it looks like this part of the code creates the index for validation purposes and then removes it again. Not sure if this helps but just wanted to let you know.

DavidTurner · June 15, 2018, 12:45pm

@cbuescher is right here. These are DEBUG logs and it's best to read them alongside the code - they're not designed to be meaningful on their own. However ...

... this actually is mentioned in these logs:

[2018-06-07T17:24:21,219][DEBUG][o.e.i.IndicesService     ] [node2] [test/eS6b3EHwRlqMkO0PIoXt6w] closed... 
(reason [NO_LONGER_ASSIGNED][cleaning up after validating index on master])

The index is first created in a kind of sandbox in order to check that it's valid, and the messages you are asking about are when the sandbox is cleaned up.

That's one of the states that all shards go through while they're starting. A newly-created shard is treated as "recovering" from an empty store.

system · July 13, 2018, 12:45pm

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Index logic documentation? Elasticsearch	12	763	July 2, 2018
Index creation templates Elasticsearch	3	355	October 25, 2018
8.2 closing connection when creating an index Elasticsearch	6	903	July 13, 2022
Creating an Index via Java API and JSON String Elasticsearch	5	315	July 6, 2017
Creation Index Elasticsearch	2	332	June 23, 2018

Understanding Index creation!

Related topics