[ https://issues.apache.org/jira/browse/SOLR-11686?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16457809#comment-16457809 ]
Varun Thacker commented on SOLR-11686: -------------------------------------- The main motivation of the patch here is to remove some logging redundancies For example, all the collection command APIs will print this at the end: date time INFO (qtp1911006827-256685) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params=\{action=CREATE¶ms} status=0 QTime=2 So I don't see a point in Solr printing an INFO message saying "invoking CREATE" as well. So all messages like those were changed to DEBUG When create collection calls the underlying core admin calls we'll get two more messages One through date time INFO (qtp1911006827-273564) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params=\{action=CREATE¶ms} status=0 QTime=0 And a message like "core create command..." for CoreAdminOperation So the "core create command" type messages have been changed to DEBUG > 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 > Attachments: SOLR-11686.patch > > > 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