It happened again this morning.
Attached is an excerpt from solr.log (with port #s & IP addresses redacted) and
below is the current CLUSTERSTATUS (with port #s redacted)
Is there yet any explanation?
{
"responseHeader":{
"status":0,
"QTime":10},
"cluster":{
"collections":{
"ipg_report_large":{
"pullReplicas":"0",
"replicationFactor":"1",
"shards":{"shard1":{
"range":"80000000-7fffffff",
"state":"active",
"replicas":{
"core_node8":{
"core":"ipg_report_large_shard1_replica_n7",
"base_url":"http://solrdbprod26.be-md:####/solr";,
"node_name":"solrdbprod26.be-md:####_solr",
"state":"active",
"type":"NRT",
"force_set_state":"false",
"leader":"true"},
"core_node10":{
"core":"ipg_report_large_shard1_replica_n9",
"base_url":"http://solrdbprod25.be-md:####/solr";,
"node_name":"solrdbprod25.be-md:####_solr",
"state":"active",
"type":"NRT",
"force_set_state":"false"}}}},
"router":{"name":"compositeId"},
"maxShardsPerNode":"1",
"autoAddReplicas":"false",
"nrtReplicas":"1",
"tlogReplicas":"0",
"znodeVersion":741,
"configName":"ipg_report_large"}},
"live_nodes":["solrdbprod26.be-md:####_solr",
"solrdbprod25.be-md:####_solr"]}}
-----Original Message-----
From: Oakley, Craig (NIH/NLM/NCBI) [C] <[email protected]>
Sent: Monday, May 17, 2021 5:01 PM
To: [email protected]
Subject: RE: Cores renamed
The entire directory for the old core gets removed
Here is CLUSTERSTATUS (again with port numbers redacted). I ran CLUSTERSTATUS
on both nodes, and the only difference was QTime (that is, there was no real
difference):
{
"responseHeader":{
"status":0,
"QTime":5},
"cluster":{
"collections":{
"ipg_report_large":{
"pullReplicas":"0",
"replicationFactor":"1",
"shards":{"shard1":{
"range":"80000000-7fffffff",
"state":"active",
"replicas":{
"core_node4":{
"core":"ipg_report_large_shard1_replica_n3",
"base_url":"http://solrdbprod26.be-md:####/solr";,
"node_name":"solrdbprod26.be-md:####_solr",
"state":"active",
"type":"NRT",
"force_set_state":"false"},
"core_node6":{
"core":"ipg_report_large_shard1_replica_n5",
"base_url":"http://solrdbprod25.be-md:####/solr";,
"node_name":"solrdbprod25.be-md:####_solr",
"state":"active",
"type":"NRT",
"force_set_state":"false",
"leader":"true"}}}},
"router":{"name":"compositeId"},
"maxShardsPerNode":"1",
"autoAddReplicas":"false",
"nrtReplicas":"1",
"tlogReplicas":"0",
"znodeVersion":710,
"configName":"ipg_report_large"}},
"live_nodes":["solrdbprod26.be-md:####_solr",
"solrdbprod25.be-md:####_solr"]}}
-----Original Message-----
From: matthew sporleder <[email protected]>
Sent: Monday, May 17, 2021 4:34 PM
To: [email protected]
Subject: Re: Cores renamed
Can you verify all of your zkHost connection params across the entire
cluster, and share the replicationFactor, autoAddReplicas, etc for the
collection?
My theory is that you have two zookeeper configs conflicting as master
elections happens, causing new replicas to get created on-the-fly.
Also -- do these cores get deleted from the filesystem or left around?
On Mon, May 17, 2021 at 4:11 PM Oakley, Craig (NIH/NLM/NCBI) [C]
<[email protected]> wrote:
>
> > What does the core renames itself to, that would probably be the biggest
> > hint.
>
> At 4:01pm 1/14/21, Solr decided on its own to drop the core
> ipg_report_large_shard1_replica_n1 and to create the core
> ipg_report_large_shard1_replica_n7 in its place
>
> At 4:33am 1/16/21, Solr decided on its own to drop the core
> ipg_report_large_shard1_replica_n5 (on another node of the same SolrCloud)
> and to create the core ipg_report_large_shard1_replica_n9 in its place
>
> At about 4:10pm 1/26/21, Solr decided on its own to drop this core
> ipg_report_large_shard1_replica_n9 and to create the core
> ipg_report_large_shard1_replica_n13 in its place
>
> In March, we created a new SolrCloud for the same collection, and reloaded
> the data
>
> At 7:59am 5/12/21, Solr decided on its own to drop the core
> ipg_report_large_shard1_replica_n1 and to create the core
> ipg_report_large_shard1_replica_n5 in its place
>
> I am attaching an excerpt from solr.log for the most recent problem (with IP
> addresses and port numbers redacted)
>
> Please not that Master/Slave replication breaks when a core is renamed, so
> this can be a major problem
>
>
> Any ideas?
>
> -----Original Message-----
> From: Alexandre Rafalovitch <[email protected]>
> Sent: Wednesday, May 12, 2021 2:10 PM
> To: [email protected]
> Subject: Re: Cores renamed
>
> This is truly a shot in the dark, but is it possible you have
> something in core.properties file (which is where the core name is for
> non-Cloud setup)?
>
> What does the core renames itself to, that would probably be the biggest hint.
>
> Regards,
> Alex.
>
> On Wed, 12 May 2021 at 14:00, Oakley, Craig (NIH/NLM/NCBI) [C]
> <[email protected]> wrote:
> >
> > This phenomenon has happened again (this time without any REQUESTRECOVERY)
> >
> > Does anyone yet have any explanation of this?
> >
> > -----Original Message-----
> > From: Oakley, Craig (NIH/NLM/NCBI) [C] <[email protected]>
> > Sent: Thursday, January 28, 2021 10:57 AM
> > To: [email protected]
> > Subject: Cores renamed
> >
> > We recently have had a few occasions when cores for one specific collection
> > were renamed (or more likely dropped and recreated, and thus ended up with
> > a different core name).
> >
> > Is this a known phenomenon? Is there any explanation?
> >
> > It may be relevant that we just recently started running this SolrCloud on
> > version 8.5.2, although the collection was created under Solr7.4. Also,
> > this collection seems to experience some heavy updates such that the
> > non-Leader replica has trouble keeping up. One of these renames occurred at
> > 4:33am, so I highly suspect that the rename (or drop and recreate) was done
> > by some internal Solr thread rather than by any of my coworkers. One other
> > potential clue is that I can see that
> > /solr/admin/cores?action=REQUESTRECOVERY was usually run on the new core a
> > moment after it was created.
> >
> > Does anyone have any insights?
2021-06-02 01:36:08.394 DEBUG (qtp1374026904-8113) [ ] o.a.s.s.HttpSolrCall
PkiAuthenticationPlugin says authorization required : true
2021-06-02 01:36:08.394 DEBUG (qtp1374026904-8113) [ ] o.a.s.s.HttpSolrCall
AuthorizationContext : userPrincipal: [[principal: subsolr]] type: [UNKNOWN],
collections: [ipg_report_large_shard1_replica_n5,], Path:
[/ipg_report_large_shard1_replica_n5/update] path :
/ipg_report_large_shard1_replica_n5/update params :null
2021-06-02 01:36:08.394 DEBUG (qtp1374026904-8113) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Attempting to authorize request to
[/ipg_report_large_shard1_replica_n5/update] of type: [UNKNOWN], associated
with collections [[CollectionRequest(ipg_report_large_shard1_replica_n5)]]
2021-06-02 01:36:08.394 DEBUG (qtp1374026904-8113) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Authorizing collection-aware request,
checking perms applicable to specific collection
[ipg_report_large_shard1_replica_n5]
2021-06-02 01:36:08.394 DEBUG (qtp1374026904-8113) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Authorizing collection-aware request,
checking perms applicable to all (*) collections
2021-06-02 01:36:08.394 DEBUG (qtp1374026904-8113) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Found perm [{
"name":"all-core-handlers",
"path":"/*",
"role":"allgen",
"index":11}] to govern resource [/ipg_report_large_shard1_replica_n5/update]
2021-06-02 01:36:08.394 DEBUG (qtp1374026904-8113) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Governing permission [{
"name":"all-core-handlers",
"path":"/*",
"role":"allgen",
"index":11}] allows access to role [allgen]; permitting access
2021-06-02 01:36:09.206 INFO (qtp1374026904-8102) [
x:ipg_report_large_shard1_replica_n5] o.a.s.c.ZkShardTerms Successful update of
terms at /collections/ipg_report_large/terms/shard1 to
Terms{values={core_node8=21, core_node4=21}, version=68}
2021-06-02 01:36:09.207 DEBUG (qtp1374026904-8102) [
x:ipg_report_large_shard1_replica_n5] o.a.s.c.ElectionContext Canceling
election
/collections/ipg_report_large/leader_elect/shard1/election/936748756074394654-core_node6-n_0000000029
2021-06-02 01:36:09.238 INFO (qtp1374026904-8102) [
x:ipg_report_large_shard1_replica_n5] o.a.s.s.HttpSolrCall [admin] webapp=null
path=/admin/cores
params={deleteInstanceDir=true&core=ipg_report_large_shard1_replica_n5&deleteMetricsHistory=true&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2&deleteIndex=true}
status=0 QTime=43086
2021-06-02 01:36:09.238 DEBUG (qtp1374026904-8102) [ ] o.a.s.s.HttpSolrCall
Closing out SolrRequest:
{deleteInstanceDir=true&core=ipg_report_large_shard1_replica_n5&deleteMetricsHistory=true&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2&deleteIndex=true}
2021-06-02 01:36:09.246 INFO (zkCallback-10-thread-89) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged
path:/collections/ipg_report_large/state.json] for collection
[ipg_report_large] has occurred - updating... (live nodes size: [2])
2021-06-02 01:36:09.247 INFO (zkCallback-10-thread-91) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged
path:/collections/ipg_report_large/state.json] for collection
[ipg_report_large] has occurred - updating... (live nodes size: [2])
2021-06-02 01:36:09.247 INFO (zkCallback-10-thread-90) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged
path:/collections/ipg_report_large/state.json] for collection
[ipg_report_large] has occurred - updating... (live nodes size: [2])
2021-06-02 01:36:09.247 INFO (zkCallback-10-thread-93) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged
path:/collections/ipg_report_large/state.json] for collection
[ipg_report_large] has occurred - updating... (live nodes size: [2])
2021-06-02 01:36:09.247 INFO (zkCallback-10-thread-92) [ ]
o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent
state:SyncConnected type:NodeDataChanged
path:/collections/ipg_report_large/state.json] for collection
[ipg_report_large] has occurred - updating... (live nodes size: [2])
2021-06-02 01:36:09.268 INFO
(OverseerThreadFactory-9-thread-5-processing-n:solrdbprod25.be-md:####_solr)
[c:ipg_report_large s:shard1 r:core_node6 ] o.a.s.c.OverseerTaskQueue Response
ZK path: /overseer/collection-queue-work/qnr-0000000079 doesn't exist.
Requestor may have disconnected from ZooKeeper
2021-06-02 01:36:10.258 INFO
(OverseerCollectionConfigSetProcessor-936748756074394654-solrdbprod25.be-md:####_solr-n_0000000031)
[ ] o.a.s.c.OverseerTaskQueue Response ZK path:
/overseer/collection-queue-work/qnr-0000000079 doesn't exist. Requestor may
have disconnected from ZooKeeper
2021-06-02 01:36:10.295 INFO
(OverseerThreadFactory-9-thread-5-processing-n:solrdbprod25.be-md:####_solr)
[c:ipg_report_large s:shard1 ] o.a.s.c.a.c.AddReplicaCmd Node Identified
solrdbprod25.be-md:####_solr for creating new replica of shard shard1 for
collection ipg_report_large
2021-06-02 01:36:10.316 INFO
(OverseerThreadFactory-9-thread-5-processing-n:solrdbprod25.be-md:####_solr)
[c:ipg_report_large s:shard1 ] o.a.s.c.a.c.AddReplicaCmd Returning
CreateReplica command.
2021-06-02 01:36:10.327 INFO
(OverseerStateUpdate-936748756074394654-solrdbprod25.be-md:####_solr-n_0000000031)
[ ] o.a.s.c.o.SliceMutator createReplica() {
"operation":"addreplica",
"collection":"ipg_report_large",
"shard":"shard1",
"core":"ipg_report_large_shard1_replica_n9",
"state":"down",
"base_url":"http://solrdbprod25.be-md:####/solr";,
"node_name":"solrdbprod25.be-md:####_solr",
"type":"NRT"}
2021-06-02 01:36:10.405 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.SolrDispatchFilter Request to authenticate:
org.apache.solr.servlet.SolrDispatchFilter$1@6299fef2, domain: #.#.#.#, port:
####
2021-06-02 01:36:10.406 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.SolrDispatchFilter User principal: [principal: subsolr]
2021-06-02 01:36:10.411 DEBUG (qtp1374026904-8126) [ ] o.a.s.s.HttpSolrCall
PkiAuthenticationPlugin says authorization required : true
2021-06-02 01:36:10.411 DEBUG (qtp1374026904-8126) [ ] o.a.s.s.HttpSolrCall
AuthorizationContext : userPrincipal: [[principal: subsolr]] type: [UNKNOWN],
collections: [ipg_report_large_shard1_replica_n5,], Path:
[/ipg_report_large_shard1_replica_n5/update] path :
/ipg_report_large_shard1_replica_n5/update params :null
2021-06-02 01:36:10.411 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Attempting to authorize request to
[/ipg_report_large_shard1_replica_n5/update] of type: [UNKNOWN], associated
with collections [[CollectionRequest(ipg_report_large_shard1_replica_n5)]]
2021-06-02 01:36:10.411 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Authorizing collection-aware request,
checking perms applicable to specific collection
[ipg_report_large_shard1_replica_n5]
2021-06-02 01:36:10.411 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Authorizing collection-aware request,
checking perms applicable to all (*) collections
2021-06-02 01:36:10.412 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Found perm [{
"name":"all-core-handlers",
"path":"/*",
"role":"allgen",
"index":11}] to govern resource [/ipg_report_large_shard1_replica_n5/update]
2021-06-02 01:36:10.412 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Governing permission [{
"name":"all-core-handlers",
"path":"/*",
"role":"allgen",
"index":11}] allows access to role [allgen]; permitting access
2021-06-02 01:36:10.412 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.SolrDispatchFilter Request to authenticate:
org.apache.solr.security.PKIAuthenticationPlugin$1@7dc2be6c, domain: #.#.#.#,
port: ####
2021-06-02 01:36:10.412 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.SolrDispatchFilter User principal: [principal: subsolr]
2021-06-02 01:36:10.413 DEBUG (qtp1374026904-8126) [ ] o.a.s.s.HttpSolrCall
no handler or core retrieved for /ipg_report_large_shard1_replica_n5/update,
follow through...
2021-06-02 01:36:10.413 DEBUG (qtp1374026904-8126) [ ] o.a.s.s.HttpSolrCall
PkiAuthenticationPlugin says authorization required : true
2021-06-02 01:36:10.413 DEBUG (qtp1374026904-8126) [ ] o.a.s.s.HttpSolrCall
AuthorizationContext : userPrincipal: [[principal: subsolr]] type: [UNKNOWN],
collections: [ipg_report_large_shard1_replica_n5,], Path:
[/ipg_report_large_shard1_replica_n5/update] path :
/ipg_report_large_shard1_replica_n5/update params :null
2021-06-02 01:36:10.413 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Attempting to authorize request to
[/ipg_report_large_shard1_replica_n5/update] of type: [UNKNOWN], associated
with collections [[CollectionRequest(ipg_report_large_shard1_replica_n5)]]
2021-06-02 01:36:10.413 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Authorizing collection-aware request,
checking perms applicable to specific collection
[ipg_report_large_shard1_replica_n5]
2021-06-02 01:36:10.413 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Authorizing collection-aware request,
checking perms applicable to all (*) collections
2021-06-02 01:36:10.413 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Found perm [{
"name":"all-core-handlers",
"path":"/*",
"role":"allgen",
"index":11}] to govern resource [/ipg_report_large_shard1_replica_n5/update]
2021-06-02 01:36:10.413 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.RuleBasedAuthorizationPlugin Governing permission [{
"name":"all-core-handlers",
"path":"/*",
"role":"allgen",
"index":11}] allows access to role [allgen]; permitting access
2021-06-02 01:36:10.546 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.SolrDispatchFilter Request to authenticate:
org.apache.solr.servlet.SolrDispatchFilter$1@7cdf4d04, domain: #.#.#.#, port:
####
2021-06-02 01:36:10.546 DEBUG (qtp1374026904-8126) [ ]
o.a.s.s.SolrDispatchFilter User principal: [principal: $]
2021-06-02 01:36:10.546 DEBUG (qtp1374026904-8126) [ ] o.a.s.s.HttpSolrCall
PkiAuthenticationPlugin says authorization required : false
2021-06-02 01:36:10.546 INFO (qtp1374026904-8126) [
x:ipg_report_large_shard1_replica_n9] o.a.s.h.a.CoreAdminOperation core create
command
qt=/admin/cores&coreNodeName=core_node10&collection.configName=ipg_report_large&name=ipg_report_large_shard1_replica_n9&action=CREATE&collection=ipg_report_large&shard=shard1&wt=javabin&version=2&replicaType=NRT
2021-06-02 01:36:10.553 DEBUG (qtp1374026904-8126) [c:ipg_report_large s:shard1
r:core_node10 x:ipg_report_large_shard1_replica_n9] o.a.s.c.ZkController
publishing state=down
2021-06-02 01:36:10.553 DEBUG (qtp1374026904-8126) [c:ipg_report_large s:shard1
r:core_node10 x:ipg_report_large_shard1_replica_n9] o.a.s.c.ZkController
numShards not found on descriptor - reading it from system property
2021-06-02 01:36:10.558 DEBUG (qtp1374026904-8126) [c:ipg_report_large s:shard1
r:core_node10 x:ipg_report_large_shard1_replica_n9] o.a.s.c.ZkController
Registering watch for collection ipg_report_large
2021-06-02 01:36:10.558 DEBUG (qtp1374026904-8126) [c:ipg_report_large s:shard1
r:core_node10 x:ipg_report_large_shard1_replica_n9] o.a.s.c.ZkController
waiting to find shard id in clusterstate for ipg_report_large_shard1_replica_n9
2021-06-02 01:36:10.584 INFO (qtp1374026904-8126) [c:ipg_report_large s:shard1
r:core_node10 x:ipg_report_large_shard1_replica_n9] o.a.s.c.SolrConfig Using
Lucene MatchVersion: 8.5.2
