[SOLR-11686] Make collection creation logging less verbose - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Improvement
Status: Open
Priority: Major
Resolution: Unresolved
Affects Version/s: None
Fix Version/s: None
Component/s: logging
Labels:
None

Description

Here's roughly what get's logged :

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

I'll comment on the Jira with what all lines should we potentially change to DEBUG

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending

SOLR-11686.patch
28/Apr/18 21:11
17 kB
Varun Thacker

Activity

People

Assignee:: Varun Thacker

Reporter:: Varun Thacker

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 27/Nov/17 21:59

Updated:: 02/Oct/19 17:24