You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/05/17 09:18:26 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1627 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1627/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:46028 returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:46028 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([EC393B27FCE6CBD8:6DDFB53F8BB9ABE4]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:679)
Build Log:
[...truncated 9524 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 1594689 T3805 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1594694 T3805 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1368774855326
[junit4:junit4] 2> 1594695 T3805 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1594696 T3806 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1594796 T3805 oasc.ZkTestServer.run start zk server on port:46021
[junit4:junit4] 2> 1594797 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1594800 T3812 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@62a9725e name:ZooKeeperConnection Watcher:127.0.0.1:46021 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1594801 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1594801 T3805 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1594820 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1594822 T3814 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4dd822d6 name:ZooKeeperConnection Watcher:127.0.0.1:46021/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1594822 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1594823 T3805 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1594832 T3805 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1594834 T3805 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1594837 T3805 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1594844 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1594845 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1594856 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1594857 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1594960 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1594961 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1594970 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1594970 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1594973 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1594974 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1594976 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1594977 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1594984 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1594985 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1594988 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1594988 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1594991 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1594992 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1595198 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1595203 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:46024
[junit4:junit4] 2> 1595203 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1595204 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1595204 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368774855633
[junit4:junit4] 2> 1595205 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368774855633/solr.xml
[junit4:junit4] 2> 1595205 T3805 oasc.CoreContainer.<init> New CoreContainer 44599227
[junit4:junit4] 2> 1595206 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368774855633/'
[junit4:junit4] 2> 1595206 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368774855633/'
[junit4:junit4] 2> 1595305 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1595305 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1595306 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1595306 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1595307 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1595307 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1595308 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1595308 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1595309 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1595309 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1595323 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1595324 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46021/solr
[junit4:junit4] 2> 1595324 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1595325 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1595328 T3825 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5613a8fe name:ZooKeeperConnection Watcher:127.0.0.1:46021 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1595328 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1595330 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1595340 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1595342 T3827 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1abe9b20 name:ZooKeeperConnection Watcher:127.0.0.1:46021/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1595342 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1595344 T3805 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1595354 T3805 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1595357 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1595363 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46024_
[junit4:junit4] 2> 1595364 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46024_
[junit4:junit4] 2> 1595372 T3805 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1595385 T3805 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1595388 T3805 oasc.Overseer.start Overseer (id=89704028918972419-127.0.0.1:46024_-n_0000000000) starting
[junit4:junit4] 2> 1595399 T3805 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1595408 T3829 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1595409 T3805 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1595411 T3805 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1595419 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1595421 T3828 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1595425 T3830 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368774855633/collection1
[junit4:junit4] 2> 1595425 T3830 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1595426 T3830 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1595426 T3830 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1595427 T3830 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368774855633/collection1/'
[junit4:junit4] 2> 1595428 T3830 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1368774855633/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1595429 T3830 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1368774855633/collection1/lib/README' to classloader
[junit4:junit4] 2> 1595477 T3830 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1595534 T3830 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1595635 T3830 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1595640 T3830 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1596198 T3830 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1596202 T3830 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1596204 T3830 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1596209 T3830 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1596228 T3830 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1596228 T3830 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368774855633/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/control/data/
[junit4:junit4] 2> 1596229 T3830 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66fbf51d
[junit4:junit4] 2> 1596229 T3830 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1596230 T3830 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/control/data
[junit4:junit4] 2> 1596230 T3830 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368774855325/control/data/index/
[junit4:junit4] 2> 1596230 T3830 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368774855325/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1596231 T3830 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/control/data/index
[junit4:junit4] 2> 1596234 T3830 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7262caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@4be15815),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1596234 T3830 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1596237 T3830 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1596237 T3830 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1596238 T3830 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1596238 T3830 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1596239 T3830 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1596239 T3830 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1596239 T3830 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1596240 T3830 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1596240 T3830 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1596247 T3830 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1596253 T3830 oass.SolrIndexSearcher.<init> Opening Searcher@27337d69 main
[junit4:junit4] 2> 1596254 T3830 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/control/data/tlog
[junit4:junit4] 2> 1596255 T3830 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1596255 T3830 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1596258 T3831 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@27337d69 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1596259 T3830 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1596259 T3830 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1596924 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1596925 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46024_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46024"}
[junit4:junit4] 2> 1596925 T3828 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1596925 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1596944 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1597261 T3830 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1597261 T3830 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46024 collection:control_collection shard:shard1
[junit4:junit4] 2> 1597262 T3830 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1597278 T3830 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1597286 T3830 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1597286 T3830 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1597286 T3830 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46024/collection1/
[junit4:junit4] 2> 1597287 T3830 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1597287 T3830 oasc.SyncStrategy.syncToMe http://127.0.0.1:46024/collection1/ has no replicas
[junit4:junit4] 2> 1597287 T3830 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46024/collection1/
[junit4:junit4] 2> 1597287 T3830 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1598448 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1598466 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1598525 T3830 oasc.ZkController.register We are http://127.0.0.1:46024/collection1/ and leader is http://127.0.0.1:46024/collection1/
[junit4:junit4] 2> 1598525 T3830 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46024
[junit4:junit4] 2> 1598525 T3830 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1598525 T3830 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1598526 T3830 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1598527 T3830 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1598528 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1598529 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1598530 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1598543 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1598545 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1598547 T3834 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@21cc2bf7 name:ZooKeeperConnection Watcher:127.0.0.1:46021/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1598547 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1598548 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1598550 T3805 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1598748 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1598752 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:46028
[junit4:junit4] 2> 1598753 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1598753 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1598754 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368774859181
[junit4:junit4] 2> 1598754 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368774859181/solr.xml
[junit4:junit4] 2> 1598755 T3805 oasc.CoreContainer.<init> New CoreContainer 327057675
[junit4:junit4] 2> 1598755 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368774859181/'
[junit4:junit4] 2> 1598756 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368774859181/'
[junit4:junit4] 2> 1598861 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1598862 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1598862 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1598863 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1598863 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1598864 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1598864 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1598865 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1598865 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1598865 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1598881 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1598881 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46021/solr
[junit4:junit4] 2> 1598882 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1598883 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1598886 T3845 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@333ee612 name:ZooKeeperConnection Watcher:127.0.0.1:46021 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1598887 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1598893 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1598906 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1598907 T3847 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@799239f name:ZooKeeperConnection Watcher:127.0.0.1:46021/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1598908 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1598920 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1599923 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46028_
[junit4:junit4] 2> 1599925 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46028_
[junit4:junit4] 2> 1599927 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1599928 T3834 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1599928 T3847 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1599944 T3827 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1599948 T3848 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368774859181/collection1
[junit4:junit4] 2> 1599949 T3848 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1599949 T3848 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1599950 T3848 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1599951 T3848 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368774859181/collection1/'
[junit4:junit4] 2> 1599952 T3848 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1368774859181/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1599953 T3848 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1368774859181/collection1/lib/README' to classloader
[junit4:junit4] 2> 1599977 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1599977 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46024_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46024"}
[junit4:junit4] 2> 1599990 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1599990 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1599990 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1600003 T3848 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1600060 T3848 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1600161 T3848 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1600166 T3848 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1600721 T3848 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1600725 T3848 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1600727 T3848 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1600732 T3848 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1600751 T3848 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1600751 T3848 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368774859181/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty1/
[junit4:junit4] 2> 1600751 T3848 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66fbf51d
[junit4:junit4] 2> 1600752 T3848 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1600752 T3848 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty1
[junit4:junit4] 2> 1600753 T3848 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty1/index/
[junit4:junit4] 2> 1600753 T3848 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1600753 T3848 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty1/index
[junit4:junit4] 2> 1600756 T3848 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20045b78 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c1f5ec9),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1600756 T3848 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1600759 T3848 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1600759 T3848 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1600760 T3848 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1600760 T3848 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1600761 T3848 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1600761 T3848 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1600762 T3848 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1600762 T3848 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1600762 T3848 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1600770 T3848 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1600775 T3848 oass.SolrIndexSearcher.<init> Opening Searcher@45e2a3d2 main
[junit4:junit4] 2> 1600776 T3848 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty1/tlog
[junit4:junit4] 2> 1600777 T3848 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1600777 T3848 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1600781 T3849 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@45e2a3d2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1600782 T3848 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1600783 T3848 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1601494 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1601495 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46028_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46028"}
[junit4:junit4] 2> 1601495 T3828 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1601495 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1601511 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1601511 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1601511 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1601785 T3848 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1601785 T3848 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46028 collection:collection1 shard:shard1
[junit4:junit4] 2> 1601786 T3848 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1601804 T3848 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1601807 T3848 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1601807 T3848 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1601807 T3848 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46028/collection1/
[junit4:junit4] 2> 1601808 T3848 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1601808 T3848 oasc.SyncStrategy.syncToMe http://127.0.0.1:46028/collection1/ has no replicas
[junit4:junit4] 2> 1601808 T3848 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46028/collection1/
[junit4:junit4] 2> 1601808 T3848 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1603015 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1603033 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1603033 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1603033 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1603037 T3848 oasc.ZkController.register We are http://127.0.0.1:46028/collection1/ and leader is http://127.0.0.1:46028/collection1/
[junit4:junit4] 2> 1603037 T3848 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46028
[junit4:junit4] 2> 1603037 T3848 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1603037 T3848 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1603038 T3848 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1603039 T3848 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1603040 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1603040 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1603041 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1603256 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1603260 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:46031
[junit4:junit4] 2> 1603261 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1603261 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1603262 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368774863686
[junit4:junit4] 2> 1603262 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368774863686/solr.xml
[junit4:junit4] 2> 1603262 T3805 oasc.CoreContainer.<init> New CoreContainer 964018916
[junit4:junit4] 2> 1603263 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368774863686/'
[junit4:junit4] 2> 1603264 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368774863686/'
[junit4:junit4] 2> 1603361 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1603362 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1603363 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1603363 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1603364 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1603364 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1603365 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1603365 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1603365 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1603366 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1603380 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1603380 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46021/solr
[junit4:junit4] 2> 1603381 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1603382 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1603385 T3861 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@782b0457 name:ZooKeeperConnection Watcher:127.0.0.1:46021 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1603386 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1603407 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1603417 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1603419 T3863 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@34450b9 name:ZooKeeperConnection Watcher:127.0.0.1:46021/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1603420 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1603430 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1604433 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46031_
[junit4:junit4] 2> 1604435 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46031_
[junit4:junit4] 2> 1604438 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1604438 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1604438 T3863 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1604438 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 1604439 T3827 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1604439 T3834 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1604452 T3847 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1604456 T3864 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368774863686/collection1
[junit4:junit4] 2> 1604457 T3864 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1604457 T3864 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1604458 T3864 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1604459 T3864 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368774863686/collection1/'
[junit4:junit4] 2> 1604460 T3864 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1368774863686/collection1/lib/README' to classloader
[junit4:junit4] 2> 1604461 T3864 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1368774863686/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1604511 T3864 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1604538 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1604539 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46028_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46028"}
[junit4:junit4] 2> 1604551 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1604551 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1604551 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1604551 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1604569 T3864 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1604670 T3864 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1604675 T3864 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1605229 T3864 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1605233 T3864 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1605236 T3864 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1605241 T3864 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1605261 T3864 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1605261 T3864 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368774863686/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty2/
[junit4:junit4] 2> 1605262 T3864 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66fbf51d
[junit4:junit4] 2> 1605262 T3864 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1605263 T3864 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty2
[junit4:junit4] 2> 1605263 T3864 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty2/index/
[junit4:junit4] 2> 1605263 T3864 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1605264 T3864 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty2/index
[junit4:junit4] 2> 1605266 T3864 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@185ad842 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17e2bce8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1605267 T3864 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1605269 T3864 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1605269 T3864 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1605270 T3864 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1605271 T3864 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1605271 T3864 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1605271 T3864 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1605272 T3864 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1605272 T3864 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1605273 T3864 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1605280 T3864 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1605286 T3864 oass.SolrIndexSearcher.<init> Opening Searcher@10191d9d main
[junit4:junit4] 2> 1605286 T3864 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty2/tlog
[junit4:junit4] 2> 1605287 T3864 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1605287 T3864 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1605291 T3865 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10191d9d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1605292 T3864 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1605292 T3864 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1606057 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1606058 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46031_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46031"}
[junit4:junit4] 2> 1606058 T3828 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1606058 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1606116 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1606116 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1606116 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1606117 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1606295 T3864 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1606295 T3864 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46031 collection:collection1 shard:shard2
[junit4:junit4] 2> 1606296 T3864 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1606336 T3864 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1606338 T3864 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1606339 T3864 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1606339 T3864 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46031/collection1/
[junit4:junit4] 2> 1606339 T3864 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1606339 T3864 oasc.SyncStrategy.syncToMe http://127.0.0.1:46031/collection1/ has no replicas
[junit4:junit4] 2> 1606340 T3864 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46031/collection1/
[junit4:junit4] 2> 1606340 T3864 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1607658 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1607678 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1607678 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1607678 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1607678 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1607722 T3864 oasc.ZkController.register We are http://127.0.0.1:46031/collection1/ and leader is http://127.0.0.1:46031/collection1/
[junit4:junit4] 2> 1607722 T3864 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46031
[junit4:junit4] 2> 1607722 T3864 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1607722 T3864 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1607723 T3864 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1607724 T3864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1607725 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1607726 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1607726 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1607939 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1607943 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:46035
[junit4:junit4] 2> 1607944 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1607944 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1607945 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368774868371
[junit4:junit4] 2> 1607945 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368774868371/solr.xml
[junit4:junit4] 2> 1607946 T3805 oasc.CoreContainer.<init> New CoreContainer 41282155
[junit4:junit4] 2> 1607946 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368774868371/'
[junit4:junit4] 2> 1607947 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368774868371/'
[junit4:junit4] 2> 1608045 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1608045 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1608046 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1608046 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1608047 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1608047 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1608048 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1608048 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1608049 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1608049 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1608064 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1608065 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46021/solr
[junit4:junit4] 2> 1608066 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1608067 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1608069 T3877 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2de2c84e name:ZooKeeperConnection Watcher:127.0.0.1:46021 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1608070 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1608084 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1608096 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1608098 T3879 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a564a78 name:ZooKeeperConnection Watcher:127.0.0.1:46021/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1608098 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1608108 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1609111 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46035_
[junit4:junit4] 2> 1609113 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46035_
[junit4:junit4] 2> 1609115 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1609115 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1609116 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1609116 T3879 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1609116 T3863 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1609117 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1609117 T3834 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1609130 T3847 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1609131 T3827 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1609135 T3880 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368774868371/collection1
[junit4:junit4] 2> 1609135 T3880 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1609136 T3880 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1609136 T3880 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1609137 T3880 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368774868371/collection1/'
[junit4:junit4] 2> 1609139 T3880 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1368774868371/collection1/lib/README' to classloader
[junit4:junit4] 2> 1609139 T3880 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1368774868371/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1609183 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1609184 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46031_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46031"}
[junit4:junit4] 2> 1609196 T3880 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1609197 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1609197 T3879 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1609197 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1609197 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1609197 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1609254 T3880 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1609355 T3880 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1609360 T3880 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1609910 T3880 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1609914 T3880 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1609916 T3880 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1609921 T3880 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1609939 T3880 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1609940 T3880 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368774868371/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/
[junit4:junit4] 2> 1609940 T3880 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66fbf51d
[junit4:junit4] 2> 1609941 T3880 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1609941 T3880 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3
[junit4:junit4] 2> 1609942 T3880 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/index/
[junit4:junit4] 2> 1609942 T3880 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1609942 T3880 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/index
[junit4:junit4] 2> 1609945 T3880 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@63aadf6e lockFactory=org.apache.lucene.store.NativeFSLockFactory@ce678b3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1609945 T3880 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1609948 T3880 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1609948 T3880 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1609949 T3880 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1609950 T3880 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1609950 T3880 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1609950 T3880 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1609951 T3880 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1609951 T3880 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1609952 T3880 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1609959 T3880 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1609965 T3880 oass.SolrIndexSearcher.<init> Opening Searcher@72202f5f main
[junit4:junit4] 2> 1609965 T3880 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/tlog
[junit4:junit4] 2> 1609966 T3880 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1609966 T3880 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1609969 T3881 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@72202f5f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1609971 T3880 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1609971 T3880 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1610702 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1610703 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46035_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46035"}
[junit4:junit4] 2> 1610703 T3828 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1610703 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1610716 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1610716 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1610716 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1610716 T3879 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1610716 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1610974 T3880 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1610974 T3880 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46035 collection:collection1 shard:shard1
[junit4:junit4] 2> 1610977 T3880 oasc.ZkController.register We are http://127.0.0.1:46035/collection1/ and leader is http://127.0.0.1:46028/collection1/
[junit4:junit4] 2> 1610977 T3880 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46035
[junit4:junit4] 2> 1610977 T3880 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1610977 T3880 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C198 name=collection1 org.apache.solr.core.SolrCore@592c46de url=http://127.0.0.1:46035/collection1 node=127.0.0.1:46035_ C198_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:46035_, base_url=http://127.0.0.1:46035}
[junit4:junit4] 2> 1610978 T3882 C198 P46035 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1610978 T3880 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1610980 T3882 C198 P46035 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1610980 T3882 C198 P46035 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1610980 T3882 C198 P46035 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1610981 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1610981 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1610982 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1611009 T3882 C198 P46035 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1611022 T3837 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1611199 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1611202 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:46039
[junit4:junit4] 2> 1611203 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1611203 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1611204 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368774871626
[junit4:junit4] 2> 1611204 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368774871626/solr.xml
[junit4:junit4] 2> 1611205 T3805 oasc.CoreContainer.<init> New CoreContainer 496399425
[junit4:junit4] 2> 1611205 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368774871626/'
[junit4:junit4] 2> 1611206 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368774871626/'
[junit4:junit4] 2> 1611307 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1611308 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1611309 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1611309 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1611310 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1611310 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1611311 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1611311 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1611311 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1611312 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1611326 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1611326 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:46021/solr
[junit4:junit4] 2> 1611327 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1611328 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1611334 T3894 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@33347ee3 name:ZooKeeperConnection Watcher:127.0.0.1:46021 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1611335 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1611349 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1611360 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1611361 T3896 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@604a703a name:ZooKeeperConnection Watcher:127.0.0.1:46021/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1611362 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1611373 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1612221 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1612222 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46035_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46035"}
[junit4:junit4] 2> 1612239 T3896 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1612239 T3879 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1612239 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1612239 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1612239 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1612239 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1612376 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46039_
[junit4:junit4] 2> 1612378 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46039_
[junit4:junit4] 2> 1612380 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1612380 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1612380 T3896 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1612380 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 1612381 T3896 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1612380 T3879 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1612380 T3863 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1612382 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1612382 T3879 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1612389 T3847 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1612389 T3827 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1612390 T3834 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1612394 T3897 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368774871626/collection1
[junit4:junit4] 2> 1612394 T3897 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1612395 T3897 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1612395 T3897 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1612396 T3897 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368774871626/collection1/'
[junit4:junit4] 2> 1612398 T3897 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1368774871626/collection1/lib/README' to classloader
[junit4:junit4] 2> 1612398 T3897 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1368774871626/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1612447 T3897 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1612504 T3897 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1612605 T3897 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1612610 T3897 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1613024 T3837 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1613024 T3837 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:46035_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 2> 1613158 T3897 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1613162 T3897 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1613164 T3897 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1613169 T3897 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1613187 T3897 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1613187 T3897 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368774871626/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/
[junit4:junit4] 2> 1613188 T3897 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@66fbf51d
[junit4:junit4] 2> 1613188 T3897 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1613189 T3897 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4
[junit4:junit4] 2> 1613189 T3897 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index/
[junit4:junit4] 2> 1613189 T3897 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1613190 T3897 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index
[junit4:junit4] 2> 1613192 T3897 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@32b779ea lockFactory=org.apache.lucene.store.NativeFSLockFactory@5007f196),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1613193 T3897 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1613195 T3897 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1613195 T3897 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1613196 T3897 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1613197 T3897 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1613197 T3897 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1613197 T3897 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1613198 T3897 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1613198 T3897 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1613199 T3897 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1613206 T3897 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1613211 T3897 oass.SolrIndexSearcher.<init> Opening Searcher@76df7589 main
[junit4:junit4] 2> 1613212 T3897 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/tlog
[junit4:junit4] 2> 1613213 T3897 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1613213 T3897 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1613217 T3898 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@76df7589 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1613218 T3897 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1613218 T3897 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1613743 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1613744 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46039_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46039"}
[junit4:junit4] 2> 1613744 T3828 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1613744 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1613767 T3896 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1613767 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1613767 T3879 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1613767 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1613767 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1613767 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1614221 T3897 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1614221 T3897 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46039 collection:collection1 shard:shard2
[junit4:junit4] 2> 1614224 T3897 oasc.ZkController.register We are http://127.0.0.1:46039/collection1/ and leader is http://127.0.0.1:46031/collection1/
[junit4:junit4] 2> 1614224 T3897 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46039
[junit4:junit4] 2> 1614224 T3897 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1614224 T3897 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C199 name=collection1 org.apache.solr.core.SolrCore@31c7b093 url=http://127.0.0.1:46039/collection1 node=127.0.0.1:46039_ C199_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:46039_, base_url=http://127.0.0.1:46039}
[junit4:junit4] 2> 1614225 T3899 C199 P46039 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1614225 T3897 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1614226 T3899 C199 P46039 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1614227 T3899 C199 P46039 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1614227 T3899 C199 P46039 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1614227 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1614228 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1614228 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1614233 T3899 C199 P46039 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1614244 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1614245 T3805 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1614245 T3853 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1614245 T3805 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1614246 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C198_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:46035_, base_url=http://127.0.0.1:46035}
[junit4:junit4] 2> 1615026 T3882 C198 P46035 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:46028/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1615026 T3882 C198 P46035 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46035 START replicas=[http://127.0.0.1:46028/collection1/] nUpdates=100
[junit4:junit4] 2> 1615027 T3882 C198 P46035 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1615027 T3882 C198 P46035 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1615027 T3882 C198 P46035 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1615027 T3882 C198 P46035 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1615027 T3882 C198 P46035 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1615027 T3882 C198 P46035 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:46028/collection1/. core=collection1
[junit4:junit4] 2> 1615028 T3882 C198 P46035 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C200 name=collection1 org.apache.solr.core.SolrCore@1149cb40 url=http://127.0.0.1:46028/collection1 node=127.0.0.1:46028_ C200_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46028_, base_url=http://127.0.0.1:46028, leader=true}
[junit4:junit4] 2> 1615034 T3838 C200 P46028 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1615038 T3839 C200 P46028 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1615042 T3839 C200 P46028 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20045b78 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c1f5ec9),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1615042 T3839 C200 P46028 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1615043 T3839 C200 P46028 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20045b78 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c1f5ec9),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20045b78 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c1f5ec9),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1615043 T3839 C200 P46028 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1615044 T3839 C200 P46028 oass.SolrIndexSearcher.<init> Opening Searcher@57842d61 realtime
[junit4:junit4] 2> 1615044 T3839 C200 P46028 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1615045 T3839 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 1615045 T3882 C198 P46035 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1615046 T3882 C198 P46035 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1615047 T3840 C200 P46028 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1615047 T3840 C200 P46028 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 1615048 T3882 C198 P46035 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1615048 T3882 C198 P46035 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1615048 T3882 C198 P46035 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1615051 T3840 C200 P46028 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1615052 T3882 C198 P46035 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1615053 T3882 C198 P46035 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/index.20130517171435683
[junit4:junit4] 2> 1615053 T3882 C198 P46035 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d57a77d lockFactory=org.apache.lucene.store.NativeFSLockFactory@1072c31f) fullCopy=false
[junit4:junit4] 2> 1615056 T3840 C200 P46028 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1615057 T3882 C198 P46035 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1615058 T3882 C198 P46035 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1615058 T3882 C198 P46035 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1615060 T3882 C198 P46035 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@63aadf6e lockFactory=org.apache.lucene.store.NativeFSLockFactory@ce678b3),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@63aadf6e lockFactory=org.apache.lucene.store.NativeFSLockFactory@ce678b3),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1615060 T3882 C198 P46035 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1615061 T3882 C198 P46035 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1615061 T3882 C198 P46035 oass.SolrIndexSearcher.<init> Opening Searcher@23be37eb main
[junit4:junit4] 2> 1615062 T3881 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@23be37eb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1615062 T3882 C198 P46035 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/index.20130517171435683 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/index.20130517171435683;done=true>>]
[junit4:junit4] 2> 1615063 T3882 C198 P46035 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/index.20130517171435683
[junit4:junit4] 2> 1615063 T3882 C198 P46035 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty3/index.20130517171435683
[junit4:junit4] 2> 1615063 T3882 C198 P46035 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1615063 T3882 C198 P46035 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1615063 T3882 C198 P46035 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1615064 T3882 C198 P46035 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1615065 T3882 C198 P46035 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1615248 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1615271 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1615271 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46039_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46039"}
[junit4:junit4] 2> 1615275 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46035_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46035"}
[junit4:junit4] 2> 1615288 T3896 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1615288 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1615288 T3879 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1615288 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1615288 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1615288 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1616248 T3853 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1616248 T3853 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:46039_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1616250 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1617252 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C199_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:46039_, base_url=http://127.0.0.1:46039}
[junit4:junit4] 2> 1618250 T3899 C199 P46039 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:46031/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1618250 T3899 C199 P46039 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46039 START replicas=[http://127.0.0.1:46031/collection1/] nUpdates=100
[junit4:junit4] 2> 1618251 T3899 C199 P46039 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1618251 T3899 C199 P46039 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1618251 T3899 C199 P46039 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1618251 T3899 C199 P46039 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1618251 T3899 C199 P46039 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1618269 T3899 C199 P46039 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:46031/collection1/. core=collection1
[junit4:junit4] 2> 1618270 T3899 C199 P46039 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1618270 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C201 name=collection1 org.apache.solr.core.SolrCore@88aa173 url=http://127.0.0.1:46031/collection1 node=127.0.0.1:46031_ C201_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46031_, base_url=http://127.0.0.1:46031, leader=true}
[junit4:junit4] 2> 1618284 T3854 C201 P46031 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1618298 T3855 C201 P46031 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1618301 T3855 C201 P46031 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@185ad842 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17e2bce8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1618301 T3855 C201 P46031 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1618302 T3855 C201 P46031 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@185ad842 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17e2bce8),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@185ad842 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17e2bce8),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1618303 T3855 C201 P46031 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1618303 T3855 C201 P46031 oass.SolrIndexSearcher.<init> Opening Searcher@4506755 realtime
[junit4:junit4] 2> 1618303 T3855 C201 P46031 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1618304 T3855 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1618305 T3899 C199 P46039 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1618305 T3899 C199 P46039 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1618306 T3856 C201 P46031 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1618307 T3856 C201 P46031 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1618307 T3899 C199 P46039 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1618307 T3899 C199 P46039 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1618308 T3899 C199 P46039 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1618310 T3856 C201 P46031 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1618311 T3899 C199 P46039 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1618312 T3899 C199 P46039 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index.20130517171438942
[junit4:junit4] 2> 1618312 T3899 C199 P46039 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@fbeee27 lockFactory=org.apache.lucene.store.NativeFSLockFactory@aa0dde8) fullCopy=false
[junit4:junit4] 2> 1618315 T3856 C201 P46031 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1618316 T3899 C199 P46039 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1618317 T3899 C199 P46039 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1618317 T3899 C199 P46039 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1618319 T3899 C199 P46039 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@32b779ea lockFactory=org.apache.lucene.store.NativeFSLockFactory@5007f196),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@32b779ea lockFactory=org.apache.lucene.store.NativeFSLockFactory@5007f196),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1618319 T3899 C199 P46039 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1618319 T3899 C199 P46039 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1618320 T3899 C199 P46039 oass.SolrIndexSearcher.<init> Opening Searcher@74a8bf7c main
[junit4:junit4] 2> 1618320 T3898 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@74a8bf7c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1618321 T3899 C199 P46039 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index.20130517171438942 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index.20130517171438942;done=true>>]
[junit4:junit4] 2> 1618321 T3899 C199 P46039 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index.20130517171438942
[junit4:junit4] 2> 1618321 T3899 C199 P46039 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index.20130517171438942
[junit4:junit4] 2> 1618321 T3899 C199 P46039 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1618322 T3899 C199 P46039 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1618322 T3899 C199 P46039 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1618322 T3899 C199 P46039 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1618324 T3899 C199 P46039 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1619272 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1619797 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1619798 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46039_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46039"}
[junit4:junit4] 2> 1619802 T3847 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1619803 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1619803 T3863 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1619803 T3879 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1619802 T3896 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1619803 T3834 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 1620274 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1620275 T3805 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C202 name=collection1 org.apache.solr.core.SolrCore@207bd1c7 url=http://127.0.0.1:46024/collection1 node=127.0.0.1:46024_ C202_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:46024_, base_url=http://127.0.0.1:46024, leader=true}
[junit4:junit4] 2> 1620284 T3817 C202 P46024 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1620287 T3817 C202 P46024 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7262caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@4be15815),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1620288 T3817 C202 P46024 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1620288 T3817 C202 P46024 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7262caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@4be15815),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7262caf lockFactory=org.apache.lucene.store.NativeFSLockFactory@4be15815),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1620289 T3817 C202 P46024 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1620289 T3817 C202 P46024 oass.SolrIndexSearcher.<init> Opening Searcher@72bc01e5 main
[junit4:junit4] 2> 1620290 T3817 C202 P46024 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1620290 T3831 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@72bc01e5 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1620291 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 1620301 T3857 C201 P46031 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1620302 T3857 C201 P46031 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@185ad842 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17e2bce8),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@185ad842 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17e2bce8),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1620303 T3857 C201 P46031 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1620303 T3857 C201 P46031 oass.SolrIndexSearcher.<init> Opening Searcher@13dcd67e main
[junit4:junit4] 2> 1620304 T3857 C201 P46031 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1620304 T3865 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13dcd67e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1620305 T3857 C201 P46031 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:46028/collection1/, StdNode: http://127.0.0.1:46035/collection1/, StdNode: http://127.0.0.1:46039/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1620308 T3841 C200 P46028 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1620309 T3841 C200 P46028 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20045b78 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c1f5ec9),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20045b78 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c1f5ec9),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1620310 T3841 C200 P46028 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1620310 T3841 C200 P46028 oass.SolrIndexSearcher.<init> Opening Searcher@4297bad0 main
[junit4:junit4] 2> 1620311 T3841 C200 P46028 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1620311 T3849 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4297bad0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1620312 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> C199_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46039_, base_url=http://127.0.0.1:46039}
[junit4:junit4] 2> 1620315 T3886 C199 P46039 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C198_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46035_, base_url=http://127.0.0.1:46035}
[junit4:junit4] 2> 1620315 T3869 C198 P46035 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1620317 T3886 C199 P46039 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@32b779ea lockFactory=org.apache.lucene.store.NativeFSLockFactory@5007f196),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@32b779ea lockFactory=org.apache.lucene.store.NativeFSLockFactory@5007f196),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1620318 T3869 C198 P46035 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@63aadf6e lockFactory=org.apache.lucene.store.NativeFSLockFactory@ce678b3),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@63aadf6e lockFactory=org.apache.lucene.store.NativeFSLockFactory@ce678b3),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1620318 T3886 C199 P46039 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1620318 T3869 C198 P46035 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1620319 T3886 C199 P46039 oass.SolrIndexSearcher.<init> Opening Searcher@6439dc54 main
[junit4:junit4] 2> 1620319 T3869 C198 P46035 oass.SolrIndexSearcher.<init> Opening Searcher@71ca6d81 main
[junit4:junit4] 2> 1620319 T3886 C199 P46039 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1620320 T3898 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6439dc54 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1620320 T3869 C198 P46035 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1620321 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1620320 T3881 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71ca6d81 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1620322 T3869 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 1620322 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 2> 1620323 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1620326 T3842 C200 P46028 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1620328 T3870 C198 P46035 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 1620329 T3858 C201 P46031 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1620331 T3887 C199 P46039 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1622336 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435264491680956416)} 0 1
[junit4:junit4] 2> 1622343 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435264491685150720&update.from=http://127.0.0.1:46031/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435264491685150720)} 0 1
[junit4:junit4] 2> 1622347 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435264491688296448&update.from=http://127.0.0.1:46028/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435264491688296448)} 0 1
[junit4:junit4] 2> 1622348 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435264491688296448)} 0 6
[junit4:junit4] 2> 1622348 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435264491685150720)} 0 9
[junit4:junit4] 2> 1622352 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1435264491697733632)]} 0 1
[junit4:junit4] 2> 1622357 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1435264491701927936)]} 0 0
[junit4:junit4] 2> 1622358 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1435264491701927936)]} 0 4
[junit4:junit4] 2> 1622358 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0]} 0 5
[junit4:junit4] 2> 1622362 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1435264491708219392)]} 0 1
[junit4:junit4] 2> 1622366 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1435264491711365120)]} 0 0
[junit4:junit4] 2> 1622367 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1435264491711365120)]} 0 3
[junit4:junit4] 2> 1622369 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1435264491716608000)]} 0 0
[junit4:junit4] 2> 1622374 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1435264491719753728)]} 0 0
[junit4:junit4] 2> 1622375 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1435264491719753728)]} 0 3
[junit4:junit4] 2> 1622378 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1435264491726045184)]} 0 0
[junit4:junit4] 2> 1622385 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1435264491731288064)]} 0 0
[junit4:junit4] 2> 1622386 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1435264491731288064)]} 0 3
[junit4:junit4] 2> 1622386 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3]} 0 5
[junit4:junit4] 2> 1622389 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1435264491737579520)]} 0 0
[junit4:junit4] 2> 1622394 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1435264491740725248)]} 0 0
[junit4:junit4] 2> 1622395 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1435264491740725248)]} 0 3
[junit4:junit4] 2> 1622397 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1435264491745968128)]} 0 0
[junit4:junit4] 2> 1622404 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1435264491751211008)]} 0 0
[junit4:junit4] 2> 1622405 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1435264491751211008)]} 0 3
[junit4:junit4] 2> 1622405 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5]} 0 5
[junit4:junit4] 2> 1622408 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1435264491757502464)]} 0 0
[junit4:junit4] 2> 1622415 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1435264491762745344)]} 0 0
[junit4:junit4] 2> 1622416 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1435264491762745344)]} 0 3
[junit4:junit4] 2> 1622417 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6]} 0 6
[junit4:junit4] 2> 1622419 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1435264491769036800)]} 0 0
[junit4:junit4] 2> 1622426 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1435264491774279680)]} 0 0
[junit4:junit4] 2> 1622427 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1435264491774279680)]} 0 3
[junit4:junit4] 2> 1622428 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7]} 0 5
[junit4:junit4] 2> 1622430 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1435264491780571136)]} 0 0
[junit4:junit4] 2> 1622436 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1435264491783716864)]} 0 0
[junit4:junit4] 2> 1622437 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1435264491783716864)]} 0 4
[junit4:junit4] 2> 1622440 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1435264491791056896)]} 0 0
[junit4:junit4] 2> 1622447 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1435264491796299776)]} 0 0
[junit4:junit4] 2> 1622448 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1435264491796299776)]} 0 3
[junit4:junit4] 2> 1622449 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9]} 0 6
[junit4:junit4] 2> 1622451 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1435264491802591232)]} 0 0
[junit4:junit4] 2> 1622458 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1435264491807834112)]} 0 0
[junit4:junit4] 2> 1622459 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!10 (1435264491807834112)]} 0 3
[junit4:junit4] 2> 1622460 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10]} 0 6
[junit4:junit4] 2> 1622462 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1435264491814125568)]} 0 0
[junit4:junit4] 2> 1622468 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1435264491817271296)]} 0 0
[junit4:junit4] 2> 1622469 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1435264491817271296)]} 0 4
[junit4:junit4] 2> 1622472 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1435264491824611328)]} 0 0
[junit4:junit4] 2> 1622479 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1435264491829854208)]} 0 0
[junit4:junit4] 2> 1622480 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1435264491829854208)]} 0 3
[junit4:junit4] 2> 1622481 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 6
[junit4:junit4] 2> 1622483 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1435264491836145664)]} 0 0
[junit4:junit4] 2> 1622492 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1435264491841388544)]} 0 1
[junit4:junit4] 2> 1622492 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1435264491841388544)]} 0 4
[junit4:junit4] 2> 1622493 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13]} 0 7
[junit4:junit4] 2> 1622496 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1435264491849777152)]} 0 0
[junit4:junit4] 2> 1622502 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1435264491852922880)]} 0 0
[junit4:junit4] 2> 1622503 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1435264491852922880)]} 0 4
[junit4:junit4] 2> 1622505 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1435264491859214336)]} 0 0
[junit4:junit4] 2> 1622510 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1435264491862360064)]} 0 0
[junit4:junit4] 2> 1622511 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1435264491862360064)]} 0 3
[junit4:junit4] 2> 1622514 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1435264491868651520)]} 0 0
[junit4:junit4] 2> 1622521 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1435264491873894400)]} 0 0
[junit4:junit4] 2> 1622522 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1435264491873894400)]} 0 3
[junit4:junit4] 2> 1622523 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16]} 0 6
[junit4:junit4] 2> 1622525 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1435264491880185856)]} 0 0
[junit4:junit4] 2> 1622532 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1435264491885428736)]} 0 0
[junit4:junit4] 2> 1622533 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1435264491885428736)]} 0 3
[junit4:junit4] 2> 1622533 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17]} 0 5
[junit4:junit4] 2> 1622536 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1435264491891720192)]} 0 0
[junit4:junit4] 2> 1622543 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1435264491896963072)]} 0 0
[junit4:junit4] 2> 1622544 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1435264491896963072)]} 0 3
[junit4:junit4] 2> 1622545 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18]} 0 6
[junit4:junit4] 2> 1622548 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1435264491903254528)]} 0 1
[junit4:junit4] 2> 1622554 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1435264491908497408)]} 0 0
[junit4:junit4] 2> 1622555 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1435264491908497408)]} 0 3
[junit4:junit4] 2> 1622556 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19]} 0 6
[junit4:junit4] 2> 1622558 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1435264491914788864)]} 0 0
[junit4:junit4] 2> 1622563 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1435264491917934592)]} 0 0
[junit4:junit4] 2> 1622564 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1435264491917934592)]} 0 3
[junit4:junit4] 2> 1622566 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1435264491923177472)]} 0 0
[junit4:junit4] 2> 1622571 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1435264491926323200)]} 0 0
[junit4:junit4] 2> 1622572 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1435264491926323200)]} 0 3
[junit4:junit4] 2> 1622574 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1435264491931566080)]} 0 0
[junit4:junit4] 2> 1622581 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1435264491936808960)]} 0 0
[junit4:junit4] 2> 1622582 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!22 (1435264491936808960)]} 0 3
[junit4:junit4] 2> 1622583 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22]} 0 6
[junit4:junit4] 2> 1622585 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1435264491943100416)]} 0 0
[junit4:junit4] 2> 1622592 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1435264491948343296)]} 0 0
[junit4:junit4] 2> 1622593 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1435264491948343296)]} 0 3
[junit4:junit4] 2> 1622593 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23]} 0 5
[junit4:junit4] 2> 1622595 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1435264491953586176)]} 0 0
[junit4:junit4] 2> 1622602 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1435264491958829056)]} 0 0
[junit4:junit4] 2> 1622602 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1435264491958829056)]} 0 2
[junit4:junit4] 2> 1622603 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24]} 0 5
[junit4:junit4] 2> 1622605 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1435264491964071936)]} 0 0
[junit4:junit4] 2> 1622610 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1435264491967217664)]} 0 0
[junit4:junit4] 2> 1622611 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1435264491967217664)]} 0 3
[junit4:junit4] 2> 1622613 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1435264491972460544)]} 0 0
[junit4:junit4] 2> 1622618 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1435264491975606272)]} 0 0
[junit4:junit4] 2> 1622619 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1435264491975606272)]} 0 3
[junit4:junit4] 2> 1622621 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1435264491980849152)]} 0 0
[junit4:junit4] 2> 1622628 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1435264491986092032)]} 0 0
[junit4:junit4] 2> 1622629 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1435264491986092032)]} 0 3
[junit4:junit4] 2> 1622629 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27]} 0 5
[junit4:junit4] 2> 1622632 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1435264491992383488)]} 0 0
[junit4:junit4] 2> 1622639 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1435264491997626368)]} 0 0
[junit4:junit4] 2> 1622640 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1435264491997626368)]} 0 3
[junit4:junit4] 2> 1622640 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28]} 0 5
[junit4:junit4] 2> 1622643 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1435264492003917824)]} 0 0
[junit4:junit4] 2> 1622648 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1435264492007063552)]} 0 0
[junit4:junit4] 2> 1622648 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1435264492007063552)]} 0 2
[junit4:junit4] 2> 1622651 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1435264492012306432)]} 0 0
[junit4:junit4] 2> 1622656 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1435264492015452160)]} 0 0
[junit4:junit4] 2> 1622657 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1435264492015452160)]} 0 3
[junit4:junit4] 2> 1622659 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1435264492020695040)]} 0 0
[junit4:junit4] 2> 1622666 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1435264492025937920)]} 0 0
[junit4:junit4] 2> 1622667 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1435264492025937920)]} 0 3
[junit4:junit4] 2> 1622667 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 5
[junit4:junit4] 2> 1622670 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1435264492032229376)]} 0 0
[junit4:junit4] 2> 1622675 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1435264492035375104)]} 0 0
[junit4:junit4] 2> 1622676 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1435264492035375104)]} 0 3
[junit4:junit4] 2> 1622678 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1435264492040617984)]} 0 0
[junit4:junit4] 2> 1622683 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1435264492043763712)]} 0 0
[junit4:junit4] 2> 1622684 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1435264492043763712)]} 0 3
[junit4:junit4] 2> 1622686 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1435264492049006592)]} 0 0
[junit4:junit4] 2> 1622693 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1435264492054249472)]} 0 0
[junit4:junit4] 2> 1622694 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1435264492054249472)]} 0 3
[junit4:junit4] 2> 1622694 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34]} 0 5
[junit4:junit4] 2> 1622697 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1435264492060540928)]} 0 0
[junit4:junit4] 2> 1622704 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1435264492065783808)]} 0 0
[junit4:junit4] 2> 1622705 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!35 (1435264492065783808)]} 0 3
[junit4:junit4] 2> 1622705 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35]} 0 5
[junit4:junit4] 2> 1622708 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1435264492072075264)]} 0 0
[junit4:junit4] 2> 1622713 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1435264492075220992)]} 0 0
[junit4:junit4] 2> 1622714 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1435264492075220992)]} 0 3
[junit4:junit4] 2> 1622716 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1435264492080463872)]} 0 0
[junit4:junit4] 2> 1622723 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1435264492085706752)]} 0 0
[junit4:junit4] 2> 1622724 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1435264492085706752)]} 0 3
[junit4:junit4] 2> 1622725 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37]} 0 6
[junit4:junit4] 2> 1622727 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1435264492091998208)]} 0 0
[junit4:junit4] 2> 1622735 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1435264492097241088)]} 0 1
[junit4:junit4] 2> 1622736 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1435264492097241088)]} 0 4
[junit4:junit4] 2> 1622736 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38]} 0 6
[junit4:junit4] 2> 1622739 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1435264492104581120)]} 0 0
[junit4:junit4] 2> 1622744 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1435264492107726848)]} 0 0
[junit4:junit4] 2> 1622745 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1435264492107726848)]} 0 3
[junit4:junit4] 2> 1622747 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1435264492112969728)]} 0 0
[junit4:junit4] 2> 1622752 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1435264492116115456)]} 0 0
[junit4:junit4] 2> 1622753 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1435264492116115456)]} 0 3
[junit4:junit4] 2> 1622755 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1435264492121358336)]} 0 0
[junit4:junit4] 2> 1622760 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1435264492124504064)]} 0 0
[junit4:junit4] 2> 1622761 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1435264492124504064)]} 0 3
[junit4:junit4] 2> 1622764 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1435264492130795520)]} 0 0
[junit4:junit4] 2> 1622771 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1435264492136038400)]} 0 0
[junit4:junit4] 2> 1622772 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1435264492136038400)]} 0 3
[junit4:junit4] 2> 1622773 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42]} 0 6
[junit4:junit4] 2> 1622775 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1435264492142329856)]} 0 0
[junit4:junit4] 2> 1622780 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1435264492145475584)]} 0 0
[junit4:junit4] 2> 1622781 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1435264492145475584)]} 0 3
[junit4:junit4] 2> 1622783 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1435264492150718464)]} 0 0
[junit4:junit4] 2> 1622790 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1435264492155961344)]} 0 0
[junit4:junit4] 2> 1622791 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1435264492155961344)]} 0 3
[junit4:junit4] 2> 1622792 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44]} 0 6
[junit4:junit4] 2> 1622794 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1435264492162252800)]} 0 0
[junit4:junit4] 2> 1622801 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1435264492167495680)]} 0 0
[junit4:junit4] 2> 1622802 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1435264492167495680)]} 0 3
[junit4:junit4] 2> 1622802 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45]} 0 5
[junit4:junit4] 2> 1622805 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1435264492173787136)]} 0 0
[junit4:junit4] 2> 1622810 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1435264492176932864)]} 0 0
[junit4:junit4] 2> 1622811 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1435264492176932864)]} 0 3
[junit4:junit4] 2> 1622813 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1435264492182175744)]} 0 0
[junit4:junit4] 2> 1622820 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1435264492187418624)]} 0 0
[junit4:junit4] 2> 1622821 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1435264492187418624)]} 0 3
[junit4:junit4] 2> 1622822 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47]} 0 5
[junit4:junit4] 2> 1622824 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1435264492193710080)]} 0 0
[junit4:junit4] 2> 1622831 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1435264492198952960)]} 0 0
[junit4:junit4] 2> 1622832 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1435264492198952960)]} 0 3
[junit4:junit4] 2> 1622833 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48]} 0 6
[junit4:junit4] 2> 1622835 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1435264492205244416)]} 0 0
[junit4:junit4] 2> 1622840 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1435264492208390144)]} 0 0
[junit4:junit4] 2> 1622841 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1435264492208390144)]} 0 3
[junit4:junit4] 2> 1622844 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1435264492214681600)]} 0 0
[junit4:junit4] 2> 1622850 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1435264492217827328)]} 0 0
[junit4:junit4] 2> 1622851 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1435264492217827328)]} 0 4
[junit4:junit4] 2> 1622853 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1435264492224118784)]} 0 0
[junit4:junit4] 2> 1622860 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1435264492229361664)]} 0 0
[junit4:junit4] 2> 1622861 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!51 (1435264492229361664)]} 0 3
[junit4:junit4] 2> 1622862 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51]} 0 6
[junit4:junit4] 2> 1622864 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1435264492235653120)]} 0 0
[junit4:junit4] 2> 1622871 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1435264492240896000)]} 0 0
[junit4:junit4] 2> 1622872 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1435264492240896000)]} 0 3
[junit4:junit4] 2> 1622873 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52]} 0 6
[junit4:junit4] 2> 1622875 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1435264492247187456)]} 0 0
[junit4:junit4] 2> 1622882 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1435264492252430336)]} 0 0
[junit4:junit4] 2> 1622883 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1435264492252430336)]} 0 3
[junit4:junit4] 2> 1622883 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53]} 0 5
[junit4:junit4] 2> 1622886 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1435264492258721792)]} 0 0
[junit4:junit4] 2> 1622893 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1435264492263964672)]} 0 0
[junit4:junit4] 2> 1622894 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1435264492263964672)]} 0 3
[junit4:junit4] 2> 1622894 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54]} 0 5
[junit4:junit4] 2> 1622897 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1435264492270256128)]} 0 0
[junit4:junit4] 2> 1622902 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1435264492273401856)]} 0 0
[junit4:junit4] 2> 1622903 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1435264492273401856)]} 0 3
[junit4:junit4] 2> 1622905 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1435264492278644736)]} 0 0
[junit4:junit4] 2> 1622912 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1435264492283887616)]} 0 0
[junit4:junit4] 2> 1622913 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1435264492283887616)]} 0 3
[junit4:junit4] 2> 1622913 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56]} 0 5
[junit4:junit4] 2> 1622916 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1435264492290179072)]} 0 0
[junit4:junit4] 2> 1622923 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1435264492295421952)]} 0 0
[junit4:junit4] 2> 1622924 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1435264492295421952)]} 0 3
[junit4:junit4] 2> 1622924 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57]} 0 5
[junit4:junit4] 2> 1622927 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1435264492301713408)]} 0 0
[junit4:junit4] 2> 1622934 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1435264492306956288)]} 0 0
[junit4:junit4] 2> 1622935 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1435264492306956288)]} 0 3
[junit4:junit4] 2> 1622935 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 5
[junit4:junit4] 2> 1622938 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1435264492313247744)]} 0 0
[junit4:junit4] 2> 1622943 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1435264492316393472)]} 0 0
[junit4:junit4] 2> 1622944 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1435264492316393472)]} 0 3
[junit4:junit4] 2> 1622946 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1435264492321636352)]} 0 0
[junit4:junit4] 2> 1622953 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1435264492326879232)]} 0 0
[junit4:junit4] 2> 1622954 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!60 (1435264492326879232)]} 0 3
[junit4:junit4] 2> 1622955 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60]} 0 6
[junit4:junit4] 2> 1622957 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1435264492333170688)]} 0 0
[junit4:junit4] 2> 1622964 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1435264492338413568)]} 0 0
[junit4:junit4] 2> 1622965 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!61 (1435264492338413568)]} 0 3
[junit4:junit4] 2> 1622965 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61]} 0 5
[junit4:junit4] 2> 1622968 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1435264492344705024)]} 0 0
[junit4:junit4] 2> 1622975 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1435264492349947904)]} 0 0
[junit4:junit4] 2> 1622976 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!62 (1435264492349947904)]} 0 3
[junit4:junit4] 2> 1622976 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62]} 0 5
[junit4:junit4] 2> 1622979 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1435264492356239360)]} 0 0
[junit4:junit4] 2> 1622984 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1435264492359385088)]} 0 0
[junit4:junit4] 2> 1622985 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1435264492359385088)]} 0 3
[junit4:junit4] 2> 1622987 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1435264492364627968)]} 0 0
[junit4:junit4] 2> 1622994 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1435264492369870848)]} 0 0
[junit4:junit4] 2> 1622995 T3859 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!64 (1435264492369870848)]} 0 3
[junit4:junit4] 2> 1622995 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64]} 0 5
[junit4:junit4] 2> 1622998 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1435264492376162304)]} 0 0
[junit4:junit4] 2> 1623003 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1435264492379308032)]} 0 0
[junit4:junit4] 2> 1623004 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1435264492379308032)]} 0 3
[junit4:junit4] 2> 1623007 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66 (1435264492385599488)]} 0 0
[junit4:junit4] 2> 1623012 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1435264492388745216)]} 0 0
[junit4:junit4] 2> 1623013 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66 (1435264492388745216)]} 0 3
[junit4:junit4] 2> 1623015 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67 (1435264492393988096)]} 0 0
[junit4:junit4] 2> 1623022 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!67 (1435264492399230976)]} 0 0
[junit4:junit4] 2> 1623023 T3841 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!67 (1435264492399230976)]} 0 3
[junit4:junit4] 2> 1623024 T3857 C201 P46031 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67]} 0 6
[junit4:junit4] 2> 1623026 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68 (1435264492405522432)]} 0 0
[junit4:junit4] 2> 1623031 T3871 C198 P46035 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46028/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!68 (1435264492408668160)]} 0 0
[junit4:junit4] 2> 1623032 T3843 C200 P46028 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68 (1435264492408668160)]} 0 3
[junit4:junit4] 2> 1623034 T3817 C202 P46024 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!69 (1435264492413911040)]} 0 0
[junit4:junit4] 2> 1623041 T3886 C199 P46039 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46031/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!69 (1435264492419153
[...truncated too long message...]
55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 1660794 T3896 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:46039 couldn't connect to http://127.0.0.1:46031/collection1/, counting as success
[junit4:junit4] 2> 1660794 T3896 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46039 DONE. sync succeeded
[junit4:junit4] 2> 1660795 T3896 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 1660795 T3896 oasc.ShardLeaderElectionContext.rejoinLeaderElection Not rejoining election because CoreContainer is shutdown
[junit4:junit4] 2> 1660795 T3896 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@31c7b093
[junit4:junit4] 2> 1660800 T3896 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=11,adds=11,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=53,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 1660801 T3896 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1660801 T3896 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1660801 T3896 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1660803 T3896 C199 P46039 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@32b779ea lockFactory=org.apache.lucene.store.NativeFSLockFactory@5007f196),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@32b779ea lockFactory=org.apache.lucene.store.NativeFSLockFactory@5007f196),segFN=segments_5,generation=5}
[junit4:junit4] 2> 1660803 T3896 C199 P46039 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 1660806 T3896 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1660806 T3896 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1660806 T3896 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4;done=false>>]
[junit4:junit4] 2> 1660806 T3896 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4
[junit4:junit4] 2> 1660807 T3896 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index;done=false>>]
[junit4:junit4] 2> 1660807 T3896 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368774855325/jetty4/index
[junit4:junit4] 2> 1660807 T3896 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1660807 T3896 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 1660808 T3896 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1660808 T3896 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=DefaultSimilarity, locale=et, timezone=Australia/ACT
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=3,free=271686464,total=462487552
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestFieldResource, TermVectorComponentTest, DistributedQueryElevationComponentTest, JsonLoaderTest, TestCoreContainer, TestStressVersions, MoreLikeThisHandlerTest, TestQueryUtils, ZkCLITest, QueryResultKeyTest, TestCloudManagedSchemaAddField, TestPhraseSuggestions, SOLR749Test, PreAnalyzedFieldTest, OverseerTest, TestDocSet, UnloadDistributedZkTest, TestFastLRUCache, TestRemoteStreaming, TestLMDirichletSimilarityFactory, TestTrie, DirectSolrConnectionTest, TestSerializedLuceneMatchVersion, TestReversedWildcardFilterFactory, ChaosMonkeyNothingIsSafeTest, BadCopyFieldTest, PolyFieldTest, CSVRequestHandlerTest, TestLRUCache, OverseerCollectionProcessorTest, TestCollationKeyRangeQueries, SimpleFacetsTest, TestRealTimeGet, TestStressRecovery, TestSolrCoreProperties, PrimUtilsTest, ResponseLogComponentTest, TestPerFieldSimilarity, WordBreakSolrSpellCheckerTest, SolrIndexSplitterTest, ClusterStateUpdateTest, QueryEqualityTest, DateFieldTest, TestManagedSchemaFieldResource, StatelessScriptUpdateProcessorFactoryTest, ReturnFieldsTest, UpdateRequestProcessorFactoryTest, TestPropInjectDefaults, TestFuzzyAnalyzedSuggestions, SliceStateUpdateTest, TestValueSourceCache, TestSearchPerf, SearchHandlerTest, TestPseudoReturnFields, TestPHPSerializedResponseWriter, TestSurroundQueryParser, TestFastWriter, TestSolrDeletionPolicy1, TestCharFilters, TestClassNameShortening, ExternalFileFieldSortTest, RegexBoostProcessorTest, BadComponentTest, TestJoin, SliceStateTest, TestWriterPerf, SpatialFilterTest, CoreAdminHandlerTest, TestRandomDVFaceting, AnalysisAfterCoreReloadTest, ShardRoutingTest, TestSolrDeletionPolicy2, BasicDistributedZkTest, SyncSliceTest, AutoCommitTest, TestFaceting, TestRecovery, ZkControllerTest, TestMultiCoreConfBootstrap, DistributedTermsComponentTest, StatsComponentTest, TestGroupingSearch, TestFunctionQuery, BasicFunctionalityTest, TestLazyCores, DirectUpdateHandlerTest, TestBadConfig, TestIndexSearcher, HighlighterTest, ShowFileRequestHandlerTest, CurrencyFieldXmlFileTest, TestCoreDiscovery, SignatureUpdateProcessorFactoryTest, SuggesterFSTTest, TestFoldingMultitermQuery, DocValuesTest, SuggesterTest, SchemaVersionSpecificBehaviorTest, TestUpdate, TestAtomicUpdateErrorCases, DirectUpdateHandlerOptimizeTest, SolrInfoMBeanTest, CacheHeaderTest, DisMaxRequestHandlerTest, TestQueryTypes, TestOmitPositions, TermsComponentTest, DocumentBuilderTest, TestSolrQueryParser, FastVectorHighlighterTest, LoggingHandlerTest, IndexSchemaTest, JSONWriterTest, MBeansHandlerTest, UniqFieldsUpdateProcessorFactoryTest, TestPartialUpdateDeduplication, CoreContainerCoreInitFailuresTest, TestLFUCache, TestPropInject, UpdateParamsTest, TestSolrIndexConfig, SolrIndexConfigTest, SampleTest, MinimalSchemaTest, TestConfig, EchoParamsTest, TestIBSimilarityFactory, TestPluginEnable, ScriptEngineTest, PluginInfoTest, TestSolrXMLSerializer, TestSuggestSpellingConverter, DOMUtilTest, ClusterStateTest, ZkNodePropsTest, SystemInfoHandlerTest, FileUtilsTest, TestRTGBase, AliasIntegrationTest, ShardSplitTest]
[junit4:junit4] Completed on J0 in 66.57s, 1 test, 1 error <<< FAILURES!
[...truncated 43 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:383: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:363: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 error, 28 ignored (9 assumptions)
Total time: 51 minutes 16 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure