[
https://issues.apache.org/jira/browse/SOLR-11686?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Cassandra Targett updated SOLR-11686:
-------------------------------------
Component/s: SolrCloud
> Make collection creation logging less verbose
> ---------------------------------------------
>
> Key: SOLR-11686
> URL: https://issues.apache.org/jira/browse/SOLR-11686
> Project: Solr
> Issue Type: Improvement
> Security Level: Public(Default Security Level. Issues are Public)
> Components: SolrCloud
> Reporter: Varun Thacker
> Assignee: Varun Thacker
> Priority: Major
>
> Here's roughly what get's logged :
> {code}
> INFO - 2017-11-27 21:55:09.685; [ ]
> org.apache.solr.handler.admin.CollectionsHandler; Invoked Collection Action
> :create with params
> replicationFactor=1&maxShardsPerNode=-1&collection.configName=test&name=test&action=CREATE&numShards=1&wt=json
> and sendToOCPQueue=true
> INFO - 2017-11-27 21:55:09.719; [ ]
> org.apache.solr.cloud.CreateCollectionCmd; Create collection test
> INFO - 2017-11-27 21:55:09.928; [ ]
> org.apache.solr.cloud.overseer.SliceMutator; createReplica() {
> "operation":"ADDREPLICA",
> "collection":"test",
> "shard":"shard1",
> "core":"test_shard1_replica_n1",
> "state":"down",
> "base_url":"http://172.16.0.83:8983/solr";,
> "type":"NRT"}
> INFO - 2017-11-27 21:55:10.187; [ ]
> org.apache.solr.handler.admin.CoreAdminOperation; core create command
> qt=/admin/cores&coreNodeName=core_node2&collection.configName=test&newCollection=true&name=test_shard1_replica_n1&action=CREATE&numShards=1&collection=test&shard=shard1&wt=javabin&version=2&replicaType=NRT
> INFO - 2017-11-27 21:55:10.190; [ ]
> org.apache.solr.core.TransientSolrCoreCacheDefault; Allocating transient
> cache for 2147483647 transient cores
> INFO - 2017-11-27 21:55:10.357; [ ]
> org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state
> change: [WatchedEvent state:SyncConnected type:NodeDataChanged
> path:/collections/test/state.json] for collection [test] has occurred -
> updating... (live nodes size: [1])
> INFO - 2017-11-27 21:55:10.357; [ ]
> org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state
> change: [WatchedEvent state:SyncConnected type:NodeDataChanged
> path:/collections/test/state.json] for collection [test] has occurred -
> updating... (live nodes size: [1])
> INFO - 2017-11-27 21:55:11.256; [ ] org.apache.solr.core.RequestParams;
> conf resource params.json loaded . version : 0
> INFO - 2017-11-27 21:55:11.257; [ ] org.apache.solr.core.RequestParams;
> request params refreshed to version 0
> INFO - 2017-11-27 21:55:11.272; [ ]
> org.apache.solr.core.SolrResourceLoader; [test_shard1_replica_n1] Added 53
> libs to classloader, from paths:
> [/Users/varunthacker/solr-7.1.0/contrib/clustering/lib,
> /Users/varunthacker/solr-7.1.0/contrib/extraction/lib,
> /Users/varunthacker/solr-7.1.0/contrib/langid/lib,
> /Users/varunthacker/solr-7.1.0/contrib/velocity/lib,
> /Users/varunthacker/solr-7.1.0/dist]
> INFO - 2017-11-27 21:55:11.479; [ ] org.apache.solr.core.SolrConfig; Using
> Lucene MatchVersion: 7.1.0
> INFO - 2017-11-27 21:55:11.616; [ ] org.apache.solr.schema.IndexSchema;
> [test_shard1_replica_n1] Schema name=default-config
> INFO - 2017-11-27 21:55:12.161; [ ] org.apache.solr.schema.IndexSchema;
> Loaded schema default-config/1.6 with uniqueid field id
> INFO - 2017-11-27 21:55:12.206; [ ] org.apache.solr.core.CoreContainer;
> Creating SolrCore 'test_shard1_replica_n1' using configuration from
> collection test, trusted=true
> INFO - 2017-11-27 21:55:12.230; [ ] org.apache.solr.core.SolrCore;
> solr.RecoveryStrategy.Builder
> INFO - 2017-11-27 21:55:12.235; [ ] org.apache.solr.core.SolrCore;
> [[test_shard1_replica_n1] ] Opening new SolrCore at
> [/Users/varunthacker/solr-7.1.0/example/cloud/node1/solr/test_shard1_replica_n1],
>
> dataDir=[/Users/varunthacker/solr-7.1.0/example/cloud/node1/solr/test_shard1_replica_n1/data/]
> INFO - 2017-11-27 21:55:12.338; [ ]
> org.apache.solr.response.XSLTResponseWriter; xsltCacheLifetimeSeconds=5
> INFO - 2017-11-27 21:55:12.641; [ ] org.apache.solr.update.UpdateHandler;
> Using UpdateLog implementation: org.apache.solr.update.UpdateLog
> INFO - 2017-11-27 21:55:12.641; [ ] org.apache.solr.update.UpdateLog;
> Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100
> maxNumLogsToKeep=10 numVersionBuckets=65536
> INFO - 2017-11-27 21:55:12.649; [ ] org.apache.solr.update.CommitTracker;
> Hard AutoCommit: if uncommited for 15000ms;
> INFO - 2017-11-27 21:55:12.649; [ ] org.apache.solr.update.CommitTracker;
> Soft AutoCommit: disabled
> INFO - 2017-11-27 21:55:12.668; [ ]
> org.apache.solr.search.SolrIndexSearcher; Opening
> [Searcher@70fa64c2[test_shard1_replica_n1] main]
> INFO - 2017-11-27 21:55:12.681; [ ]
> org.apache.solr.rest.ManagedResourceStorage$ZooKeeperStorageIO; Configured
> ZooKeeperStorageIO with znodeBase: /configs/test
> INFO - 2017-11-27 21:55:12.694; [ ]
> org.apache.solr.rest.ManagedResourceStorage; Loaded null at path
> _rest_managed.json using ZooKeeperStorageIO:path=/configs/test
> INFO - 2017-11-27 21:55:12.695; [ ]
> org.apache.solr.schema.ZkIndexSchemaReader; Creating ZooKeeper watch for the
> managed schema at /configs/test/managed-schema
> INFO - 2017-11-27 21:55:12.696; [ ]
> org.apache.solr.schema.ZkIndexSchemaReader; Current schema version 0 is
> already the latest
> INFO - 2017-11-27 21:55:12.703; [ ]
> org.apache.solr.handler.component.SpellCheckComponent; Initializing spell
> checkers
> INFO - 2017-11-27 21:55:12.708; [ ]
> org.apache.solr.spelling.DirectSolrSpellChecker; init:
> {name=default,field=_text_,classname=solr.DirectSolrSpellChecker,distanceMeasure=internal,accuracy=0.5,maxEdits=2,minPrefix=1,maxInspections=5,minQueryLength=4,maxQueryFrequency=0.01}
> INFO - 2017-11-27 21:55:12.717; [ ]
> org.apache.solr.handler.ReplicationHandler; Commits will be reserved for
> 10000ms.
> INFO - 2017-11-27 21:55:12.789; [ ]
> org.apache.solr.core.QuerySenderListener; QuerySenderListener sending
> requests to Searcher@70fa64c2[test_shard1_replica_n1]
> main{ExitableDirectoryReader(UninvertingDirectoryReader())}
> INFO - 2017-11-27 21:55:12.789; [ ]
> org.apache.solr.core.QuerySenderListener; QuerySenderListener done.
> INFO - 2017-11-27 21:55:12.789; [ ]
> org.apache.solr.handler.component.SpellCheckComponent$SpellCheckerListener;
> Loading spell index for spellchecker: default
> INFO - 2017-11-27 21:55:12.796; [ ] org.apache.solr.update.UpdateLog;
> Could not find max version in index or recent updates, using new clock
> 1585257867164778496
> INFO - 2017-11-27 21:55:12.797; [ ] org.apache.solr.core.SolrCore;
> [test_shard1_replica_n1] Registered new searcher
> Searcher@70fa64c2[test_shard1_replica_n1]
> main{ExitableDirectoryReader(UninvertingDirectoryReader())}
> INFO - 2017-11-27 21:55:12.861; [ ]
> org.apache.solr.cloud.ShardLeaderElectionContext; Enough replicas found to
> continue.
> INFO - 2017-11-27 21:55:12.861; [ ]
> org.apache.solr.cloud.ShardLeaderElectionContext; I may be the new leader -
> try and sync
> INFO - 2017-11-27 21:55:12.862; [ ] org.apache.solr.cloud.SyncStrategy;
> Sync replicas to http://172.16.0.83:8983/solr/test_shard1_replica_n1/
> INFO - 2017-11-27 21:55:12.863; [ ] org.apache.solr.cloud.SyncStrategy;
> Sync Success - now sync replicas to me
> INFO - 2017-11-27 21:55:12.863; [ ] org.apache.solr.cloud.SyncStrategy;
> http://172.16.0.83:8983/solr/test_shard1_replica_n1/ has no replicas
> INFO - 2017-11-27 21:55:12.863; [ ]
> org.apache.solr.cloud.ShardLeaderElectionContext; Found all replicas
> participating in election, clear LIR
> INFO - 2017-11-27 21:55:12.930; [ ]
> org.apache.solr.cloud.ShardLeaderElectionContext; I am the new leader:
> http://172.16.0.83:8983/solr/test_shard1_replica_n1/ shard1
> INFO - 2017-11-27 21:55:12.967; [ ]
> org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state
> change: [WatchedEvent state:SyncConnected type:NodeDataChanged
> path:/collections/test/state.json] for collection [test] has occurred -
> updating... (live nodes size: [1])
> INFO - 2017-11-27 21:55:12.967; [ ]
> org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state
> change: [WatchedEvent state:SyncConnected type:NodeDataChanged
> path:/collections/test/state.json] for collection [test] has occurred -
> updating... (live nodes size: [1])
> INFO - 2017-11-27 21:55:12.986; [ ] org.apache.solr.cloud.ZkController; I
> am the leader, no recovery necessary
> INFO - 2017-11-27 21:55:13.001; [ ] org.apache.solr.servlet.HttpSolrCall;
> [admin] webapp=null path=/admin/cores
> params={qt=/admin/cores&coreNodeName=core_node2&collection.configName=test&newCollection=true&name=test_shard1_replica_n1&action=CREATE&numShards=1&collection=test&shard=shard1&wt=javabin&version=2&replicaType=NRT}
> status=0 QTime=2815
> INFO - 2017-11-27 21:55:13.090; [ ]
> org.apache.solr.handler.admin.CollectionsHandler; Wait for new collection to
> be active for at most 30 seconds. Check all shard replicas
> INFO - 2017-11-27 21:55:13.146; [ ]
> org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state
> change: [WatchedEvent state:SyncConnected type:NodeDataChanged
> path:/collections/test/state.json] for collection [test] has occurred -
> updating... (live nodes size: [1])
> INFO - 2017-11-27 21:55:13.146; [ ]
> org.apache.solr.common.cloud.ZkStateReader$StateWatcher; A cluster state
> change: [WatchedEvent state:SyncConnected type:NodeDataChanged
> path:/collections/test/state.json] for collection [test] has occurred -
> updating... (live nodes size: [1])
> INFO - 2017-11-27 21:55:13.735; [ ]
> org.apache.solr.cloud.OverseerTaskQueue; Response ZK path:
> /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may
> have disconnected from ZooKeeper
> INFO - 2017-11-27 21:55:14.095; [ ] org.apache.solr.servlet.HttpSolrCall;
> [admin] webapp=null path=/admin/collections
> params={replicationFactor=1&maxShardsPerNode=-1&collection.configName=test&name=test&action=CREATE&numShards=1&wt=json}
> status=0 QTime=4410
> INFO - 2017-11-27 21:55:14.175; [ ]
> org.apache.solr.handler.SolrConfigHandler$Command; Executed config commands
> successfully and persisted to ZK
> [{"set-property":{"updateHandler.autoSoftCommit.maxTime":"3000"}}]
> INFO - 2017-11-27 21:55:14.176; [ ] org.apache.solr.core.SolrCore; config
> update listener called for core test_shard1_replica_n1
> INFO - 2017-11-27 21:55:14.177; [ ]
> org.apache.solr.handler.SolrConfigHandler; Waiting up to 30 secs for 1
> replicas to set the property overlay to be of version 0 for collection test
> INFO - 2017-11-27 21:55:14.177; [ ] org.apache.solr.core.SolrCore; core
> reload test_shard1_replica_n1
> INFO - 2017-11-27 21:55:14.178; [ ]
> org.apache.solr.handler.SolrConfigHandler$PerReplicaCallable; Time elapsed :
> 0 secs, maxWait 30
> INFO - 2017-11-27 21:55:14.195; [ ] org.apache.solr.core.RequestParams;
> conf resource params.json loaded . version : 0
> INFO - 2017-11-27 21:55:14.195; [ ] org.apache.solr.core.RequestParams;
> request params refreshed to version 0
> INFO - 2017-11-27 21:55:14.198; [ ]
> org.apache.solr.core.SolrResourceLoader; [test_shard1_replica_n1] Added 53
> libs to classloader, from paths:
> [/Users/varunthacker/solr-7.1.0/contrib/clustering/lib,
> /Users/varunthacker/solr-7.1.0/contrib/extraction/lib,
> /Users/varunthacker/solr-7.1.0/contrib/langid/lib,
> /Users/varunthacker/solr-7.1.0/contrib/velocity/lib,
> /Users/varunthacker/solr-7.1.0/dist]
> INFO - 2017-11-27 21:55:14.222; [ ] org.apache.solr.core.SolrConfig; Using
> Lucene MatchVersion: 7.1.0
> INFO - 2017-11-27 21:55:14.256; [ ] org.apache.solr.schema.IndexSchema;
> [test_shard1_replica_n1] Schema name=default-config
> INFO - 2017-11-27 21:55:14.289; [ ]
> org.apache.solr.handler.SolrConfigHandler$Command; expecting overlay version
> 0 but my version is -1
> INFO - 2017-11-27 21:55:14.291; [ ] org.apache.solr.core.SolrCore;
> [test_shard1_replica_n1] webapp=/solr path=/config/znodeVersion
> params={overlay=0&wt=javabin&version=2} status=0 QTime=1
> INFO - 2017-11-27 21:55:14.291; [ ]
> org.apache.solr.handler.SolrConfigHandler$Command; Another reload is in
> progress . Not doing anything
> INFO - 2017-11-27 21:55:14.292; [ ]
> org.apache.solr.handler.SolrConfigHandler$PerReplicaCallable; Could not get
> expectedVersion 0 from http://172.16.0.83:8983/solr/test_shard1_replica_n1/
> for prop overlay after 1 attempts
> INFO - 2017-11-27 21:55:14.293; [ ]
> org.apache.solr.handler.SolrConfigHandler$PerReplicaCallable; Time elapsed :
> 0 secs, maxWait 30
> INFO - 2017-11-27 21:55:14.398; [ ]
> org.apache.solr.handler.SolrConfigHandler$Command; expecting overlay version
> 0 but my version is -1
> INFO - 2017-11-27 21:55:14.399; [ ]
> org.apache.solr.handler.SolrConfigHandler$Command; Another reload is in
> progress . Not doing anything
> INFO - 2017-11-27 21:55:14.399; [ ] org.apache.solr.core.SolrCore;
> [test_shard1_replica_n1] webapp=/solr path=/config/znodeVersion
> params={overlay=0&wt=javabin&version=2} status=0 QTime=0
> INFO - 2017-11-27 21:55:14.400; [ ]
> org.apache.solr.handler.SolrConfigHandler$PerReplicaCallable; Could not get
> expectedVersion 0 from http://172.16.0.83:8983/solr/test_shard1_replica_n1/
> for prop overlay after 2 attempts
> INFO - 2017-11-27 21:55:14.400; [ ]
> org.apache.solr.handler.SolrConfigHandler$PerReplicaCallable; Time elapsed :
> 0 secs, maxWait 30
> INFO - 2017-11-27 21:55:14.428; [ ] org.apache.solr.schema.IndexSchema;
> Loaded schema default-config/1.6 with uniqueid field id
> INFO - 2017-11-27 21:55:14.465; [ ] org.apache.solr.core.CoreContainer;
> Reloading SolrCore 'test_shard1_replica_n1' using configuration from
> collection test
> INFO - 2017-11-27 21:55:14.466; [ ] org.apache.solr.core.SolrCore;
> [[test_shard1_replica_n1] ] Opening new SolrCore at
> [/Users/varunthacker/solr-7.1.0/example/cloud/node1/solr/test_shard1_replica_n1],
>
> dataDir=[/Users/varunthacker/solr-7.1.0/example/cloud/node1/solr/test_shard1_replica_n1/data/]
> INFO - 2017-11-27 21:55:14.468; [ ]
> org.apache.solr.response.XSLTResponseWriter; xsltCacheLifetimeSeconds=5
> INFO - 2017-11-27 21:55:14.498; [ ] org.apache.solr.update.CommitTracker;
> Hard AutoCommit: if uncommited for 15000ms;
> INFO - 2017-11-27 21:55:14.499; [ ] org.apache.solr.update.CommitTracker;
> Soft AutoCommit: if uncommited for 3000ms;
> INFO - 2017-11-27 21:55:14.501; [ ]
> org.apache.solr.search.SolrIndexSearcher; Opening
> [Searcher@78ca9301[test_shard1_replica_n1] main]
> INFO - 2017-11-27 21:55:14.503; [ ]
> org.apache.solr.rest.ManagedResourceStorage$ZooKeeperStorageIO; Configured
> ZooKeeperStorageIO with znodeBase: /configs/test
> INFO - 2017-11-27 21:55:14.504; [ ]
> org.apache.solr.rest.ManagedResourceStorage; Loaded null at path
> _rest_managed.json using ZooKeeperStorageIO:path=/configs/test
> INFO - 2017-11-27 21:55:14.504; [ ]
> org.apache.solr.schema.ZkIndexSchemaReader; Creating ZooKeeper watch for the
> managed schema at /configs/test/managed-schema
> INFO - 2017-11-27 21:55:14.505; [ ]
> org.apache.solr.handler.SolrConfigHandler$Command; expecting overlay version
> 0 but my version is -1
> INFO - 2017-11-27 21:55:14.505; [ ]
> org.apache.solr.schema.ZkIndexSchemaReader; Current schema version 0 is
> already the latest
> INFO - 2017-11-27 21:55:14.505; [ ] org.apache.solr.core.SolrCore;
> [test_shard1_replica_n1] webapp=/solr path=/config/znodeVersion
> params={overlay=0&wt=javabin&version=2} status=0 QTime=0
> INFO - 2017-11-27 21:55:14.505; [ ]
> org.apache.solr.handler.SolrConfigHandler$Command; Another reload is in
> progress . Not doing anything
> INFO - 2017-11-27 21:55:14.505; [ ]
> org.apache.solr.handler.component.SpellCheckComponent; Initializing spell
> checkers
> INFO - 2017-11-27 21:55:14.506; [ ]
> org.apache.solr.spelling.DirectSolrSpellChecker; init:
> {name=default,field=_text_,classname=solr.DirectSolrSpellChecker,distanceMeasure=internal,accuracy=0.5,maxEdits=2,minPrefix=1,maxInspections=5,minQueryLength=4,maxQueryFrequency=0.01}
> INFO - 2017-11-27 21:55:14.507; [ ]
> org.apache.solr.handler.SolrConfigHandler$PerReplicaCallable; Could not get
> expectedVersion 0 from http://172.16.0.83:8983/solr/test_shard1_replica_n1/
> for prop overlay after 3 attempts
> INFO - 2017-11-27 21:55:14.507; [ ]
> org.apache.solr.handler.SolrConfigHandler$PerReplicaCallable; Time elapsed :
> 0 secs, maxWait 30
> INFO - 2017-11-27 21:55:14.508; [ ]
> org.apache.solr.handler.ReplicationHandler; Commits will be reserved for
> 10000ms.
> INFO - 2017-11-27 21:55:14.509; [ ]
> org.apache.solr.core.QuerySenderListener; QuerySenderListener sending
> requests to Searcher@78ca9301[test_shard1_replica_n1]
> main{ExitableDirectoryReader(UninvertingDirectoryReader())}
> INFO - 2017-11-27 21:55:14.510; [ ]
> org.apache.solr.core.QuerySenderListener; QuerySenderListener done.
> INFO - 2017-11-27 21:55:14.510; [ ]
> org.apache.solr.handler.component.SpellCheckComponent$SpellCheckerListener;
> Loading spell index for spellchecker: default
> INFO - 2017-11-27 21:55:14.510; [ ] org.apache.solr.update.UpdateLog;
> Could not find max version in index or recent updates, using new clock
> 1585257868962037760
> INFO - 2017-11-27 21:55:14.510; [ ] org.apache.solr.core.SolrCore;
> [test_shard1_replica_n1] Registered new searcher
> Searcher@78ca9301[test_shard1_replica_n1]
> main{ExitableDirectoryReader(UninvertingDirectoryReader())}
> INFO - 2017-11-27 21:55:14.517; [ ]
> org.apache.solr.update.DefaultSolrCoreState; New IndexWriter is ready to be
> used.
> INFO - 2017-11-27 21:55:14.518; [ ]
> org.apache.solr.search.SolrIndexSearcher; Opening
> [Searcher@26ed891f[test_shard1_replica_n1] main]
> INFO - 2017-11-27 21:55:14.521; [ ]
> org.apache.solr.core.QuerySenderListener; QuerySenderListener sending
> requests to Searcher@26ed891f[test_shard1_replica_n1]
> main{ExitableDirectoryReader(UninvertingDirectoryReader())}
> INFO - 2017-11-27 21:55:14.521; [ ]
> org.apache.solr.core.QuerySenderListener; QuerySenderListener done.
> INFO - 2017-11-27 21:55:14.522; [ ] org.apache.solr.core.SolrCore;
> [test_shard1_replica_n1] Registered new searcher
> Searcher@26ed891f[test_shard1_replica_n1]
> main{ExitableDirectoryReader(UninvertingDirectoryReader())}
> INFO - 2017-11-27 21:55:14.614; [ ]
> org.apache.solr.handler.SolrConfigHandler$Command; I already have the
> expected version 0 of config
> INFO - 2017-11-27 21:55:14.614; [ ]
> org.apache.solr.handler.SolrConfigHandler$Command; isStale false ,
> resourceloader org.apache.solr.cloud.ZkSolrResourceLoader
> INFO - 2017-11-27 21:55:14.615; [ ] org.apache.solr.core.SolrCore;
> [test_shard1_replica_n1] webapp=/solr path=/config/znodeVersion
> params={overlay=0&wt=javabin&version=2} status=0 QTime=1
> INFO - 2017-11-27 21:55:14.618; [ ]
> org.apache.solr.handler.SolrConfigHandler; Took 442.0ms to set the property
> overlay to be of version 0 for collection test
> INFO - 2017-11-27 21:55:14.618; [ ] org.apache.solr.core.SolrCore;
> [test_shard1_replica_n1] webapp=/solr path=/config
> params={wt=javabin&version=2} status=0 QTime=494
> INFO - 2017-11-27 21:55:14.619; [ ] org.apache.solr.core.SolrCore;
> [test_shard1_replica_n1] CLOSING SolrCore
> org.apache.solr.core.SolrCore@7d3d636d
> INFO - 2017-11-27 21:55:14.619; [ ]
> org.apache.solr.metrics.SolrMetricManager; Closing metric reporters for
> registry=solr.core.test.shard1.replica_n1, tag=2101175149
> INFO - 2017-11-27 21:55:14.619; [ ]
> org.apache.solr.metrics.SolrMetricManager; Closing metric reporters for
> registry=solr.collection.test.shard1.leader, tag=2101175149
> {code}
> I'll comment on the Jira with what all lines should we potentially change to
> DEBUG
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
