Understanding Index creation!


(R_C) #1

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 ???


(Christoph) #2

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:

This condition is met when createdIndex is set here:

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.


(David Turner) #3

@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) #4

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