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/06/18 07:39:33 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 1340 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/1340/
2 tests failed.
REGRESSION: org.apache.solr.cloud.RecoveryZkTest.testDistribSearch
Error Message:
expected:<182> but was:<74>
Stack Trace:
java.lang.AssertionError: expected:<182> but was:<74>
at __randomizedtesting.SeedInfo.seed([7E1360AB42849902:FFF5EEB335DBF93E]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.junit.Assert.assertEquals(Assert.java:456)
at org.apache.solr.cloud.RecoveryZkTest.doTest(RecoveryZkTest.java:108)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
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:601)
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:722)
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:19626 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:19626 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([7E1360AB42849902:FFF5EEB335DBF93E]: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:228)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
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:601)
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:722)
Build Log:
[...truncated 9686 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 650684 T1461 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 650691 T1461 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./solrtest-ShardSplitTest-1371532603673
[junit4:junit4] 2> 650693 T1461 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 650693 T1462 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 650794 T1461 oasc.ZkTestServer.run start zk server on port:19619
[junit4:junit4] 2> 650795 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 650800 T1468 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@27e1bf0e name:ZooKeeperConnection Watcher:127.0.0.1:19619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 650800 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 650801 T1461 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 650820 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 650822 T1470 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4cfe19a8 name:ZooKeeperConnection Watcher:127.0.0.1:19619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 650823 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 650823 T1461 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 650828 T1461 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 650838 T1461 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 650840 T1461 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 650848 T1461 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 650849 T1461 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 650860 T1461 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 650861 T1461 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 650965 T1461 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 650966 T1461 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 650977 T1461 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 650978 T1461 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 650981 T1461 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 650982 T1461 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 650985 T1461 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 650986 T1461 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 650989 T1461 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 650989 T1461 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 650993 T1461 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 650993 T1461 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 650997 T1461 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 650997 T1461 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 651271 T1461 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 651274 T1461 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19622
[junit4:junit4] 2> 651274 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 651275 T1461 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 651275 T1461 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371532603983
[junit4:junit4] 2> 651276 T1461 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371532603983/solr.xml
[junit4:junit4] 2> 651276 T1461 oasc.CoreContainer.<init> New CoreContainer 1286292745
[junit4:junit4] 2> 651277 T1461 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371532603983/'
[junit4:junit4] 2> 651278 T1461 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371532603983/'
[junit4:junit4] 2> 651407 T1461 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 651408 T1461 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 651408 T1461 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 651409 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 651409 T1461 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 651410 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 651410 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 651411 T1461 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 651411 T1461 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 651412 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 651430 T1461 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 651431 T1461 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19619/solr
[junit4:junit4] 2> 651432 T1461 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 651433 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 651435 T1481 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6d0229bd name:ZooKeeperConnection Watcher:127.0.0.1:19619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 651436 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 651439 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 651453 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 651455 T1483 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@291e4e3d name:ZooKeeperConnection Watcher:127.0.0.1:19619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 651455 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 651458 T1461 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 651468 T1461 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 651472 T1461 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 651479 T1461 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19622_
[junit4:junit4] 2> 651480 T1461 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19622_
[junit4:junit4] 2> 651484 T1461 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 651500 T1461 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 651504 T1461 oasc.Overseer.start Overseer (id=89884760714772483-127.0.0.1:19622_-n_0000000000) starting
[junit4:junit4] 2> 651514 T1461 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 651525 T1485 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 651525 T1461 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 651528 T1461 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 651535 T1461 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 651538 T1484 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 651542 T1486 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 651543 T1486 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 653042 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 653042 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:19622_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19622"}
[junit4:junit4] 2> 653043 T1484 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 653043 T1484 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 653063 T1483 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> 653546 T1486 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371532603983/collection1
[junit4:junit4] 2> 653546 T1486 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 653547 T1486 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 653547 T1486 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 653549 T1486 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371532603983/collection1/'
[junit4:junit4] 2> 653550 T1486 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1371532603983/collection1/lib/README' to classloader
[junit4:junit4] 2> 653551 T1486 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-controljetty-1371532603983/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 653604 T1486 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 653664 T1486 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 653765 T1486 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 653771 T1486 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 654368 T1486 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 654372 T1486 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 654374 T1486 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 654380 T1486 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 654405 T1486 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 654406 T1486 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-controljetty-1371532603983/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/control/data/
[junit4:junit4] 2> 654406 T1486 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@361e5287
[junit4:junit4] 2> 654407 T1486 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 654407 T1486 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/control/data
[junit4:junit4] 2> 654408 T1486 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371532603672/control/data/index/
[junit4:junit4] 2> 654408 T1486 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371532603672/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 654409 T1486 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/control/data/index
[junit4:junit4] 2> 654413 T1486 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d66a164 lockFactory=org.apache.lucene.store.NativeFSLockFactory@390a31a2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 654414 T1486 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 654417 T1486 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 654417 T1486 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 654418 T1486 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 654418 T1486 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 654419 T1486 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 654419 T1486 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 654420 T1486 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 654420 T1486 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 654421 T1486 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 654436 T1486 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 654443 T1486 oass.SolrIndexSearcher.<init> Opening Searcher@500fc86e main
[junit4:junit4] 2> 654444 T1486 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/control/data/tlog
[junit4:junit4] 2> 654445 T1486 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 654445 T1486 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 654448 T1487 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@500fc86e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 654449 T1486 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 654450 T1486 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19622 collection:control_collection shard:shard1
[junit4:junit4] 2> 654451 T1486 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 654477 T1486 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 654480 T1486 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 654480 T1486 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 654480 T1486 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:19622/collection1/
[junit4:junit4] 2> 654481 T1486 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 654481 T1486 oasc.SyncStrategy.syncToMe http://127.0.0.1:19622/collection1/ has no replicas
[junit4:junit4] 2> 654481 T1486 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:19622/collection1/
[junit4:junit4] 2> 654482 T1486 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 654567 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 654585 T1483 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> 654590 T1486 oasc.ZkController.register We are http://127.0.0.1:19622/collection1/ and leader is http://127.0.0.1:19622/collection1/
[junit4:junit4] 2> 654590 T1486 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19622
[junit4:junit4] 2> 654590 T1486 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 654590 T1486 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 654591 T1486 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 654592 T1486 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 654593 T1461 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 654594 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 654595 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 654614 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 654615 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 654617 T1490 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@336a135 name:ZooKeeperConnection Watcher:127.0.0.1:19619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 654618 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 654619 T1461 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 654622 T1461 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 654900 T1461 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 654903 T1461 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19626
[junit4:junit4] 2> 654904 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 654905 T1461 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 654905 T1461 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371532607603
[junit4:junit4] 2> 654906 T1461 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371532607603/solr.xml
[junit4:junit4] 2> 654906 T1461 oasc.CoreContainer.<init> New CoreContainer 1851571052
[junit4:junit4] 2> 654907 T1461 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371532607603/'
[junit4:junit4] 2> 654908 T1461 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371532607603/'
[junit4:junit4] 2> 655039 T1461 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 655040 T1461 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 655040 T1461 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 655041 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 655041 T1461 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 655042 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 655042 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 655043 T1461 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 655043 T1461 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 655044 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 655062 T1461 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 655063 T1461 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19619/solr
[junit4:junit4] 2> 655063 T1461 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 655064 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 655068 T1501 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e62ac9b name:ZooKeeperConnection Watcher:127.0.0.1:19619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 655069 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 655085 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 655096 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 655098 T1503 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bc3822b name:ZooKeeperConnection Watcher:127.0.0.1:19619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 655099 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 655111 T1461 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 656090 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 656091 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:19622__collection1",
[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:19622_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19622"}
[junit4:junit4] 2> 656109 T1503 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> 656109 T1483 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> 656109 T1490 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> 656115 T1461 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19626_
[junit4:junit4] 2> 656118 T1461 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19626_
[junit4:junit4] 2> 656120 T1490 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> 656120 T1503 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> 656120 T1483 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 656121 T1483 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> 656121 T1490 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 656127 T1503 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 656133 T1504 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 656133 T1504 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 657615 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 657616 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:19626_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19626"}
[junit4:junit4] 2> 657617 T1484 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 657617 T1484 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 657633 T1490 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> 657633 T1503 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> 657633 T1483 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> 658137 T1504 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371532607603/collection1
[junit4:junit4] 2> 658137 T1504 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 658138 T1504 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 658138 T1504 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 658140 T1504 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371532607603/collection1/'
[junit4:junit4] 2> 658141 T1504 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1371532607603/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 658142 T1504 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty1-1371532607603/collection1/lib/README' to classloader
[junit4:junit4] 2> 658195 T1504 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 658255 T1504 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 658357 T1504 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 658363 T1504 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 658941 T1504 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 658945 T1504 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 658947 T1504 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 658953 T1504 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 658979 T1504 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 658980 T1504 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty1-1371532607603/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty1/
[junit4:junit4] 2> 658980 T1504 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@361e5287
[junit4:junit4] 2> 658981 T1504 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 658981 T1504 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty1
[junit4:junit4] 2> 658982 T1504 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty1/index/
[junit4:junit4] 2> 658982 T1504 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 658983 T1504 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty1/index
[junit4:junit4] 2> 658987 T1504 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58bed46 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18420fd5),segFN=segments_1,generation=1}
[junit4:junit4] 2> 658987 T1504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 658991 T1504 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 658991 T1504 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 658992 T1504 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 658992 T1504 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 658993 T1504 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 658993 T1504 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 658994 T1504 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 658995 T1504 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 658995 T1504 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 659011 T1504 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 659019 T1504 oass.SolrIndexSearcher.<init> Opening Searcher@5c5ba35 main
[junit4:junit4] 2> 659019 T1504 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty1/tlog
[junit4:junit4] 2> 659020 T1504 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 659021 T1504 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 659026 T1505 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c5ba35 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 659028 T1504 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 659028 T1504 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19626 collection:collection1 shard:shard1
[junit4:junit4] 2> 659029 T1504 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 659112 T1504 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 659114 T1504 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 659115 T1504 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 659115 T1504 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:19626/collection1/
[junit4:junit4] 2> 659115 T1504 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 659116 T1504 oasc.SyncStrategy.syncToMe http://127.0.0.1:19626/collection1/ has no replicas
[junit4:junit4] 2> 659116 T1504 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:19626/collection1/
[junit4:junit4] 2> 659116 T1504 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 659137 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 659205 T1490 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> 659205 T1483 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> 659205 T1503 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> 659224 T1504 oasc.ZkController.register We are http://127.0.0.1:19626/collection1/ and leader is http://127.0.0.1:19626/collection1/
[junit4:junit4] 2> 659224 T1504 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19626
[junit4:junit4] 2> 659224 T1504 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 659225 T1504 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 659225 T1504 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 659227 T1504 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 659228 T1461 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 659229 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 659229 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 659507 T1461 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 659511 T1461 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19630
[junit4:junit4] 2> 659512 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 659512 T1461 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 659513 T1461 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371532612228
[junit4:junit4] 2> 659513 T1461 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371532612228/solr.xml
[junit4:junit4] 2> 659514 T1461 oasc.CoreContainer.<init> New CoreContainer 470874863
[junit4:junit4] 2> 659515 T1461 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371532612228/'
[junit4:junit4] 2> 659515 T1461 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371532612228/'
[junit4:junit4] 2> 659644 T1461 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 659645 T1461 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 659646 T1461 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 659646 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 659647 T1461 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 659647 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 659648 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 659648 T1461 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 659649 T1461 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 659649 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 659667 T1461 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 659667 T1461 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19619/solr
[junit4:junit4] 2> 659668 T1461 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 659669 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 659705 T1517 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7e19d69f name:ZooKeeperConnection Watcher:127.0.0.1:19619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 659705 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 659719 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 659731 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 659733 T1519 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@78d98a7e name:ZooKeeperConnection Watcher:127.0.0.1:19619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 659734 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 659746 T1461 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 660718 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 660719 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:19626__collection1",
[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:19626_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19626"}
[junit4:junit4] 2> 660736 T1503 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> 660736 T1519 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> 660736 T1483 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> 660736 T1490 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> 660749 T1461 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19630_
[junit4:junit4] 2> 660751 T1461 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19630_
[junit4:junit4] 2> 660753 T1503 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> 660753 T1519 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> 660753 T1490 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> 660754 T1483 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 660754 T1483 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> 660755 T1503 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 660761 T1519 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 660761 T1490 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 660766 T1520 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 660767 T1520 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 662241 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 662243 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:19630_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19630"}
[junit4:junit4] 2> 662243 T1484 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 662243 T1484 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 662249 T1490 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> 662249 T1483 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> 662249 T1503 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> 662249 T1519 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> 662770 T1520 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371532612228/collection1
[junit4:junit4] 2> 662770 T1520 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 662771 T1520 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 662771 T1520 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 662773 T1520 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371532612228/collection1/'
[junit4:junit4] 2> 662774 T1520 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1371532612228/collection1/lib/README' to classloader
[junit4:junit4] 2> 662775 T1520 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty2-1371532612228/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 662828 T1520 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 662888 T1520 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 662990 T1520 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 662996 T1520 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 663571 T1520 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 663576 T1520 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 663578 T1520 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 663583 T1520 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 663609 T1520 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 663609 T1520 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty2-1371532612228/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty2/
[junit4:junit4] 2> 663609 T1520 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@361e5287
[junit4:junit4] 2> 663610 T1520 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 663611 T1520 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty2
[junit4:junit4] 2> 663611 T1520 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty2/index/
[junit4:junit4] 2> 663611 T1520 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 663613 T1520 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty2/index
[junit4:junit4] 2> 663617 T1520 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45d336db lockFactory=org.apache.lucene.store.NativeFSLockFactory@24343f0a),segFN=segments_1,generation=1}
[junit4:junit4] 2> 663617 T1520 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 663620 T1520 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 663621 T1520 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 663621 T1520 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 663622 T1520 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 663623 T1520 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 663623 T1520 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 663624 T1520 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 663624 T1520 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 663625 T1520 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 663641 T1520 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 663648 T1520 oass.SolrIndexSearcher.<init> Opening Searcher@6e17449a main
[junit4:junit4] 2> 663649 T1520 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty2/tlog
[junit4:junit4] 2> 663650 T1520 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 663650 T1520 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 663655 T1521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6e17449a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 663657 T1520 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 663658 T1520 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19630 collection:collection1 shard:shard2
[junit4:junit4] 2> 663659 T1520 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 663679 T1520 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 663683 T1520 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 663683 T1520 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 663683 T1520 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:19630/collection1/
[junit4:junit4] 2> 663683 T1520 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 663684 T1520 oasc.SyncStrategy.syncToMe http://127.0.0.1:19630/collection1/ has no replicas
[junit4:junit4] 2> 663684 T1520 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:19630/collection1/
[junit4:junit4] 2> 663684 T1520 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 663753 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 663768 T1490 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> 663768 T1483 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> 663768 T1503 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> 663768 T1519 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> 663792 T1520 oasc.ZkController.register We are http://127.0.0.1:19630/collection1/ and leader is http://127.0.0.1:19630/collection1/
[junit4:junit4] 2> 663792 T1520 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19630
[junit4:junit4] 2> 663792 T1520 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 663792 T1520 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 663793 T1520 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 663794 T1520 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 663796 T1461 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 663796 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 663797 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 664081 T1461 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 664084 T1461 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19635
[junit4:junit4] 2> 664085 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 664085 T1461 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 664086 T1461 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371532616795
[junit4:junit4] 2> 664086 T1461 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371532616795/solr.xml
[junit4:junit4] 2> 664087 T1461 oasc.CoreContainer.<init> New CoreContainer 1678993531
[junit4:junit4] 2> 664088 T1461 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371532616795/'
[junit4:junit4] 2> 664088 T1461 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371532616795/'
[junit4:junit4] 2> 664220 T1461 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 664221 T1461 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 664221 T1461 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 664222 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 664222 T1461 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 664223 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 664223 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 664224 T1461 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 664224 T1461 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 664225 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 664242 T1461 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 664243 T1461 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19619/solr
[junit4:junit4] 2> 664244 T1461 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 664245 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 664248 T1533 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@53c10ede name:ZooKeeperConnection Watcher:127.0.0.1:19619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 664249 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 664252 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 664265 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 664272 T1535 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@58b44d37 name:ZooKeeperConnection Watcher:127.0.0.1:19619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 664273 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 664303 T1461 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 665283 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 665284 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:19630__collection1",
[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:19630_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19630"}
[junit4:junit4] 2> 665289 T1483 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> 665289 T1519 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> 665289 T1490 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> 665289 T1535 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> 665289 T1503 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> 665310 T1461 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19635_
[junit4:junit4] 2> 665314 T1461 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19635_
[junit4:junit4] 2> 665317 T1535 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> 665317 T1519 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> 665317 T1490 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> 665317 T1503 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> 665317 T1483 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 665318 T1483 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> 665319 T1535 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 665319 T1519 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 665327 T1490 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 665327 T1503 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 665332 T1536 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 665332 T1536 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 666812 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 666813 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:19635_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19635"}
[junit4:junit4] 2> 666814 T1484 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 666814 T1484 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 666819 T1535 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> 666819 T1519 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> 666819 T1490 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> 666819 T1483 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> 666819 T1503 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> 667337 T1536 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371532616795/collection1
[junit4:junit4] 2> 667337 T1536 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 667338 T1536 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 667338 T1536 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 667340 T1536 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371532616795/collection1/'
[junit4:junit4] 2> 667341 T1536 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1371532616795/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 667342 T1536 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty3-1371532616795/collection1/lib/README' to classloader
[junit4:junit4] 2> 667395 T1536 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 667456 T1536 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 667558 T1536 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 667564 T1536 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 668143 T1536 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 668148 T1536 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 668150 T1536 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 668155 T1536 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 668181 T1536 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 668182 T1536 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty3-1371532616795/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/
[junit4:junit4] 2> 668182 T1536 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@361e5287
[junit4:junit4] 2> 668183 T1536 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 668184 T1536 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3
[junit4:junit4] 2> 668184 T1536 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/index/
[junit4:junit4] 2> 668184 T1536 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 668185 T1536 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/index
[junit4:junit4] 2> 668207 T1536 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@337af227 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb08bf7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 668207 T1536 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 668211 T1536 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 668211 T1536 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 668212 T1536 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 668213 T1536 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 668213 T1536 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 668214 T1536 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 668214 T1536 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 668215 T1536 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 668215 T1536 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 668232 T1536 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 668239 T1536 oass.SolrIndexSearcher.<init> Opening Searcher@777cd1 main
[junit4:junit4] 2> 668240 T1536 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/tlog
[junit4:junit4] 2> 668241 T1536 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 668242 T1536 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 668246 T1537 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@777cd1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 668249 T1536 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 668249 T1536 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19635 collection:collection1 shard:shard1
[junit4:junit4] 2> 668252 T1536 oasc.ZkController.register We are http://127.0.0.1:19635/collection1/ and leader is http://127.0.0.1:19626/collection1/
[junit4:junit4] 2> 668253 T1536 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19635
[junit4:junit4] 2> 668253 T1536 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 668253 T1536 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C620 name=collection1 org.apache.solr.core.SolrCore@10e4fb96 url=http://127.0.0.1:19635/collection1 node=127.0.0.1:19635_ C620_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:19635_, base_url=http://127.0.0.1:19635}
[junit4:junit4] 2> 668254 T1538 C620 P19635 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 668254 T1536 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 668254 T1538 C620 P19635 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 668255 T1538 C620 P19635 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 668255 T1538 C620 P19635 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 668255 T1461 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 668256 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 668257 T1538 C620 P19635 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 668257 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 668281 T1493 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:19635__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 668331 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 668332 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:19635__collection1",
[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:19635_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19635"}
[junit4:junit4] 2> 668346 T1535 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> 668346 T1490 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> 668346 T1483 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> 668346 T1503 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> 668346 T1519 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> 668545 T1461 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 668548 T1461 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19639
[junit4:junit4] 2> 668549 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 668549 T1461 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 668550 T1461 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371532621261
[junit4:junit4] 2> 668550 T1461 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371532621261/solr.xml
[junit4:junit4] 2> 668551 T1461 oasc.CoreContainer.<init> New CoreContainer 265595525
[junit4:junit4] 2> 668552 T1461 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371532621261/'
[junit4:junit4] 2> 668552 T1461 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371532621261/'
[junit4:junit4] 2> 668681 T1461 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 668682 T1461 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 668683 T1461 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 668683 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 668684 T1461 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 668684 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 668685 T1461 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 668685 T1461 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 668686 T1461 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 668687 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 668702 T1461 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 668703 T1461 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19619/solr
[junit4:junit4] 2> 668703 T1461 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 668705 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 668708 T1550 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@25f04b32 name:ZooKeeperConnection Watcher:127.0.0.1:19619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 668708 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 668719 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 668730 T1461 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 668732 T1552 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10ddee69 name:ZooKeeperConnection Watcher:127.0.0.1:19619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 668732 T1461 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 668742 T1461 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 669283 T1493 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:19635__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 669283 T1493 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:19635__collection1&state=recovering&nodeName=127.0.0.1:19635_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 669746 T1461 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19639_
[junit4:junit4] 2> 669775 T1461 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19639_
[junit4:junit4] 2> 669779 T1535 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> 669779 T1519 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> 669780 T1552 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 669779 T1490 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> 669779 T1503 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> 669780 T1483 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 669781 T1483 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> 669781 T1535 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 669781 T1519 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 669793 T1490 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 669794 T1503 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 669799 T1553 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 669799 T1553 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 669858 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 669859 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:19639_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19639"}
[junit4:junit4] 2> 669859 T1484 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 669859 T1484 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 669866 T1552 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> 669867 T1519 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> 669867 T1490 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> 669866 T1483 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> 669866 T1535 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> 669866 T1503 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> 670802 T1553 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371532621261/collection1
[junit4:junit4] 2> 670802 T1553 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 670803 T1553 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 670803 T1553 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 670805 T1553 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371532621261/collection1/'
[junit4:junit4] 2> 670806 T1553 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1371532621261/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 670807 T1553 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/org.apache.solr.cloud.ShardSplitTest-jetty4-1371532621261/collection1/lib/README' to classloader
[junit4:junit4] 2> 670860 T1553 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 670921 T1553 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 671022 T1553 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 671028 T1553 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> C620_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:19635_, base_url=http://127.0.0.1:19635}
[junit4:junit4] 2> 671285 T1538 C620 P19635 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:19626/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 671285 T1538 C620 P19635 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:19635 START replicas=[http://127.0.0.1:19626/collection1/] nUpdates=100
[junit4:junit4] 2> 671286 T1538 C620 P19635 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 671286 T1538 C620 P19635 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 671287 T1538 C620 P19635 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 671287 T1538 C620 P19635 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 671287 T1538 C620 P19635 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 671288 T1538 C620 P19635 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:19626/collection1/. core=collection1
[junit4:junit4] 2> 671288 T1538 C620 P19635 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C621 name=collection1 org.apache.solr.core.SolrCore@13887716 url=http://127.0.0.1:19626/collection1 node=127.0.0.1:19626_ C621_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19626_, base_url=http://127.0.0.1:19626, leader=true}
[junit4:junit4] 2> 671295 T1494 C621 P19626 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> 671299 T1495 C621 P19626 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 671303 T1495 C621 P19626 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58bed46 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18420fd5),segFN=segments_1,generation=1}
[junit4:junit4] 2> 671303 T1495 C621 P19626 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 671304 T1495 C621 P19626 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58bed46 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18420fd5),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58bed46 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18420fd5),segFN=segments_2,generation=2}
[junit4:junit4] 2> 671304 T1495 C621 P19626 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 671305 T1495 C621 P19626 oass.SolrIndexSearcher.<init> Opening Searcher@2213f290 realtime
[junit4:junit4] 2> 671306 T1495 C621 P19626 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 671306 T1495 C621 P19626 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> ASYNC NEW_CORE C622 name=collection1 org.apache.solr.core.SolrCore@10e4fb96 url=http://127.0.0.1:19635/collection1 node=127.0.0.1:19635_ C622_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:19635_, base_url=http://127.0.0.1:19635}
[junit4:junit4] 2> 671323 T1538 C622 P19635 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 671323 T1538 C622 P19635 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> ASYNC NEW_CORE C623 name=collection1 org.apache.solr.core.SolrCore@13887716 url=http://127.0.0.1:19626/collection1 node=127.0.0.1:19626_ C623_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19626_, base_url=http://127.0.0.1:19626, leader=true}
[junit4:junit4] 2> 671326 T1496 C623 P19626 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 671327 T1496 C623 P19626 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 671328 T1538 C622 P19635 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 671328 T1538 C622 P19635 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 671328 T1538 C622 P19635 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 671330 T1496 C623 P19626 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> 671331 T1538 C622 P19635 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 671332 T1538 C622 P19635 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/index.20130617221704312
[junit4:junit4] 2> 671332 T1538 C622 P19635 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@7a20a3f7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@25adaaee) fullCopy=false
[junit4:junit4] 2> 671335 T1496 C623 P19626 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> 671336 T1538 C622 P19635 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 671338 T1538 C622 P19635 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 671338 T1538 C622 P19635 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 671390 T1538 C622 P19635 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@337af227 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb08bf7),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@337af227 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb08bf7),segFN=segments_2,generation=2}
[junit4:junit4] 2> 671391 T1538 C622 P19635 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 671391 T1538 C622 P19635 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 671392 T1538 C622 P19635 oass.SolrIndexSearcher.<init> Opening Searcher@4de148be main
[junit4:junit4] 2> 671393 T1537 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4de148be main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 671394 T1538 C622 P19635 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/index.20130617221704312 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/index.20130617221704312;done=true>>]
[junit4:junit4] 2> 671394 T1538 C622 P19635 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/index.20130617221704312
[junit4:junit4] 2> 671394 T1538 C622 P19635 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty3/index.20130617221704312
[junit4:junit4] 2> 671394 T1538 C622 P19635 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 671395 T1538 C622 P19635 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 671395 T1538 C622 P19635 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 671395 T1538 C622 P19635 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 671397 T1538 C622 P19635 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 671607 T1553 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 671611 T1553 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 671614 T1553 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 671619 T1553 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 671645 T1553 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 671645 T1553 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ShardSplitTest-jetty4-1371532621261/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/
[junit4:junit4] 2> 671645 T1553 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@361e5287
[junit4:junit4] 2> 671646 T1553 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 671647 T1553 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4
[junit4:junit4] 2> 671647 T1553 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/index/
[junit4:junit4] 2> 671647 T1553 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 671648 T1553 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/index
[junit4:junit4] 2> 671652 T1553 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@53923f0b lockFactory=org.apache.lucene.store.NativeFSLockFactory@9556f8c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 671652 T1553 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 671656 T1553 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 671656 T1553 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 671657 T1553 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 671657 T1553 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 671658 T1553 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 671658 T1553 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 671660 T1553 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 671660 T1553 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 671661 T1553 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 671677 T1553 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 671685 T1553 oass.SolrIndexSearcher.<init> Opening Searcher@35aa04c5 main
[junit4:junit4] 2> 671685 T1553 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/tlog
[junit4:junit4] 2> 671686 T1553 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 671687 T1553 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 671691 T1556 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@35aa04c5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 671693 T1553 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 671694 T1553 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19639 collection:collection1 shard:shard2
[junit4:junit4] 2> 671697 T1553 oasc.ZkController.register We are http://127.0.0.1:19639/collection1/ and leader is http://127.0.0.1:19630/collection1/
[junit4:junit4] 2> 671697 T1553 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19639
[junit4:junit4] 2> 671698 T1553 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 671698 T1553 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C624 name=collection1 org.apache.solr.core.SolrCore@14a30878 url=http://127.0.0.1:19639/collection1 node=127.0.0.1:19639_ C624_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:19639_, base_url=http://127.0.0.1:19639}
[junit4:junit4] 2> 671698 T1557 C624 P19639 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 671699 T1553 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 671699 T1557 C624 P19639 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 671699 T1557 C624 P19639 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 671700 T1557 C624 P19639 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 671700 T1461 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J1
[junit4:junit4] 2> 671701 T1461 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 671701 T1557 C624 P19639 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 671701 T1461 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 671725 T1461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 671726 T1509 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:19639__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 671726 T1461 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 671727 T1461 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 671728 T1461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 672730 T1461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 672873 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 672874 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:19635__collection1",
[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:19635_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19635"}
[junit4:junit4] 2> 672878 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:19639__collection1",
[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:19639_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19639"}
[junit4:junit4] 2> 672892 T1552 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> 672892 T1483 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> 672892 T1490 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> 672892 T1519 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> 672892 T1503 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> 672892 T1535 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> 673729 T1509 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:19639__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 673729 T1509 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:19639__collection1&state=recovering&nodeName=127.0.0.1:19639_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 673732 T1461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 674734 T1461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C624_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:19639_, base_url=http://127.0.0.1:19639}
[junit4:junit4] 2> 675731 T1557 C624 P19639 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:19630/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 675731 T1557 C624 P19639 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:19639 START replicas=[http://127.0.0.1:19630/collection1/] nUpdates=100
[junit4:junit4] 2> 675732 T1557 C624 P19639 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 675732 T1557 C624 P19639 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 675732 T1557 C624 P19639 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 675732 T1557 C624 P19639 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 675733 T1557 C624 P19639 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 675734 T1557 C624 P19639 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:19630/collection1/. core=collection1
[junit4:junit4] 2> 675734 T1557 C624 P19639 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 675736 T1461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C625 name=collection1 org.apache.solr.core.SolrCore@1084f38e url=http://127.0.0.1:19630/collection1 node=127.0.0.1:19630_ C625_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19630_, base_url=http://127.0.0.1:19630, leader=true}
[junit4:junit4] 2> 675741 T1510 C625 P19630 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> 675745 T1511 C625 P19630 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 675748 T1511 C625 P19630 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45d336db lockFactory=org.apache.lucene.store.NativeFSLockFactory@24343f0a),segFN=segments_1,generation=1}
[junit4:junit4] 2> 675749 T1511 C625 P19630 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 675750 T1511 C625 P19630 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45d336db lockFactory=org.apache.lucene.store.NativeFSLockFactory@24343f0a),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45d336db lockFactory=org.apache.lucene.store.NativeFSLockFactory@24343f0a),segFN=segments_2,generation=2}
[junit4:junit4] 2> 675750 T1511 C625 P19630 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 675751 T1511 C625 P19630 oass.SolrIndexSearcher.<init> Opening Searcher@5db7a5ba realtime
[junit4:junit4] 2> 675751 T1511 C625 P19630 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 675752 T1511 C625 P19630 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> 675753 T1557 C624 P19639 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 675753 T1557 C624 P19639 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 675755 T1512 C625 P19630 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 675756 T1512 C625 P19630 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 675757 T1557 C624 P19639 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 675757 T1557 C624 P19639 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 675757 T1557 C624 P19639 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 675759 T1512 C625 P19630 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> 675760 T1557 C624 P19639 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 675761 T1557 C624 P19639 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/index.20130617221708741
[junit4:junit4] 2> 675761 T1557 C624 P19639 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@debae77 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7949378) fullCopy=false
[junit4:junit4] 2> 675764 T1512 C625 P19630 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> 675765 T1557 C624 P19639 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 675766 T1557 C624 P19639 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 675766 T1557 C624 P19639 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 675819 T1557 C624 P19639 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@53923f0b lockFactory=org.apache.lucene.store.NativeFSLockFactory@9556f8c),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@53923f0b lockFactory=org.apache.lucene.store.NativeFSLockFactory@9556f8c),segFN=segments_2,generation=2}
[junit4:junit4] 2> 675820 T1557 C624 P19639 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 675820 T1557 C624 P19639 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 675820 T1557 C624 P19639 oass.SolrIndexSearcher.<init> Opening Searcher@1323bfa main
[junit4:junit4] 2> 675822 T1556 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1323bfa main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 675822 T1557 C624 P19639 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/index.20130617221708741 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/index.20130617221708741;done=true>>]
[junit4:junit4] 2> 675823 T1557 C624 P19639 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/index.20130617221708741
[junit4:junit4] 2> 675823 T1557 C624 P19639 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1371532603672/jetty4/index.20130617221708741
[junit4:junit4] 2> 675823 T1557 C624 P19639 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 675823 T1557 C624 P19639 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 675824 T1557 C624 P19639 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 675824 T1557 C624 P19639 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 675826 T1557 C624 P19639 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 675906 T1484 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 675907 T1484 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:19639__collection1",
[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:19639_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19639"}
[junit4:junit4] 2> 675920 T1552 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> 675920 T1519 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> 675920 T1503 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> 675920 T1490 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> 675920 T1483 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> 675920 T1535 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> 676738 T1461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 676739 T1461 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C626 name=collection1 org.apache.solr.core.SolrCore@79406006 url=http://127.0.0.1:19622/collection1 node=127.0.0.1:19622_ C626_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:19622_, base_url=http://127.0.0.1:19622, leader=true}
[junit4:junit4] 2> 676748 T1473 C626 P19622 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 676752 T1473 C626 P19622 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d66a164 lockFactory=org.apache.lucene.store.NativeFSLockFactory@390a31a2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 676753 T1473 C626 P19622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 676753 T1473 C626 P19622 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d66a164 lockFactory=org.apache.lucene.store.NativeFSLockFactory@390a31a2),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d66a164 lockFactory=org.apache.lucene.store.NativeFSLockFactory@390a31a2),segFN=segments_2,generation=2}
[junit4:junit4] 2> 676754 T1473 C626 P19622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 676755 T1473 C626 P19622 oass.SolrIndexSearcher.<init> Opening Searcher@3d2a6704 main
[junit4:junit4] 2> 676755 T1473 C626 P19622 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 676756 T1487 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d2a6704 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 676757 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 676769 T1497 C623 P19626 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:19626/collection1/, StdNode: http://127.0.0.1:19635/collection1/, StdNode: http://127.0.0.1:19630/collection1/, StdNode: http://127.0.0.1:19639/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 676773 T1498 C623 P19626 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 676773 T1513 C625 P19630 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 676774 T1498 C623 P19626 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58bed46 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18420fd5),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@58bed46 lockFactory=org.apache.lucene.store.NativeFSLockFactory@18420fd5),segFN=segments_3,generation=3}
[junit4:junit4] 2> 676775 T1513 C625 P19630 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45d336db lockFactory=org.apache.lucene.store.NativeFSLockFactory@24343f0a),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45d336db lockFactory=org.apache.lucene.store.NativeFSLockFactory@24343f0a),segFN=segments_3,generation=3}
[junit4:junit4] 2> 676775 T1498 C623 P19626 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 676775 T1513 C625 P19630 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 676776 T1498 C623 P19626 oass.SolrIndexSearcher.<init> Opening Searcher@647277f9 main
[junit4:junit4] 2> 676777 T1513 C625 P19630 oass.SolrIndexSearcher.<init> Opening Searcher@1992dc2d main
[junit4:junit4] 2> 676777 T1498 C623 P19626 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 676778 T1513 C625 P19630 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 676778 T1505 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@647277f9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 676778 T1521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1992dc2d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 676779 T1498 C623 P19626 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> 676779 T1513 C625 P19630 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> C624_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19639_, base_url=http://127.0.0.1:19639}
[junit4:junit4] 2> 676781 T1542 C624 P19639 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C622_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19635_, base_url=http://127.0.0.1:19635}
[junit4:junit4] 2> 676781 T1525 C622 P19635 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 676782 T1542 C624 P19639 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@53923f0b lockFactory=org.apache.lucene.store.NativeFSLockFactory@9556f8c),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@53923f0b lockFactory=org.apache.lucene.store.NativeFSLockFactory@9556f8c),segFN=segments_3,generation=3}
[junit4:junit4] 2> 676783 T1525 C622 P19635 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@337af227 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb08bf7),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@337af227 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1eb08bf7),segFN=segments_3,generation=3}
[junit4:junit4] 2> 676783 T1542 C624 P19639 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 676784 T1525 C622 P19635 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 676784 T1542 C624 P19639 oass.SolrIndexSearcher.<init> Opening Searcher@792e38f5 main
[junit4:junit4] 2> 676785 T1525 C622 P19635 oass.SolrIndexSearcher.<init> Opening Searcher@a29b8d8 main
[junit4:junit4] 2> 676785 T1542 C624 P19639 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 676786 T1556 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@792e38f5 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 676786 T1525 C622 P19635 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 676787 T1542 C624 P19639 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> 676787 T1537 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a29b8d8 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 676788 T1525 C622 P19635 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> 676789 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4] 2> 676790 T1461 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 676793 T1499 C623 P19626 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> 676795 T1526 C622 P19635 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> 676797 T1514 C625 P19630 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> 676799 T1543 C624 P19639 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> 678805 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438156200905539584)} 0 2
[junit4:junit4] 2> 678816 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438156200912879616&update.from=http://127.0.0.1:19626/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438156200912879616)} 0 2
[junit4:junit4] 2> 678821 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438156200917073920&update.from=http://127.0.0.1:19630/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438156200917073920)} 0 2
[junit4:junit4] 2> 678822 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438156200917073920)} 0 8
[junit4:junit4] 2> 678823 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438156200912879616)} 0 14
[junit4:junit4] 2> 678827 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1438156200929656832)]} 0 1
[junit4:junit4] 2> 678836 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1438156200935948288)]} 0 1
[junit4:junit4] 2> 678837 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1438156200935948288)]} 0 5
[junit4:junit4] 2> 678837 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0]} 0 7
[junit4:junit4] 2> 678840 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1438156200944336896)]} 0 0
[junit4:junit4] 2> 678847 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1438156200947482624)]} 0 1
[junit4:junit4] 2> 678847 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1438156200947482624)]} 0 4
[junit4:junit4] 2> 678850 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1438156200954822656)]} 0 0
[junit4:junit4] 2> 678857 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1438156200959016960)]} 0 1
[junit4:junit4] 2> 678857 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1438156200959016960)]} 0 3
[junit4:junit4] 2> 678858 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2]} 0 6
[junit4:junit4] 2> 678861 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1438156200966356992)]} 0 0
[junit4:junit4] 2> 678868 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1438156200969502720)]} 0 1
[junit4:junit4] 2> 678868 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1438156200969502720)]} 0 4
[junit4:junit4] 2> 678871 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1438156200976842752)]} 0 0
[junit4:junit4] 2> 678877 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1438156200979988480)]} 0 0
[junit4:junit4] 2> 678878 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1438156200979988480)]} 0 4
[junit4:junit4] 2> 678881 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1438156200987328512)]} 0 0
[junit4:junit4] 2> 678890 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1438156200992571392)]} 0 1
[junit4:junit4] 2> 678890 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1438156200992571392)]} 0 4
[junit4:junit4] 2> 678891 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5]} 0 7
[junit4:junit4] 2> 678894 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1438156201000960000)]} 0 0
[junit4:junit4] 2> 678901 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1438156201004105728)]} 0 1
[junit4:junit4] 2> 678901 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1438156201004105728)]} 0 4
[junit4:junit4] 2> 678904 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1438156201011445760)]} 0 0
[junit4:junit4] 2> 678912 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1438156201016688640)]} 0 0
[junit4:junit4] 2> 678913 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1438156201016688640)]} 0 4
[junit4:junit4] 2> 678914 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7]} 0 7
[junit4:junit4] 2> 678916 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1438156201024028672)]} 0 0
[junit4:junit4] 2> 678924 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1438156201029271552)]} 0 0
[junit4:junit4] 2> 678925 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!8 (1438156201029271552)]} 0 4
[junit4:junit4] 2> 678926 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8]} 0 7
[junit4:junit4] 2> 678929 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1438156201037660160)]} 0 0
[junit4:junit4] 2> 678936 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1438156201040805888)]} 0 0
[junit4:junit4] 2> 678936 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1438156201040805888)]} 0 4
[junit4:junit4] 2> 678940 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1438156201048145920)]} 0 1
[junit4:junit4] 2> 678947 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1438156201053388800)]} 0 0
[junit4:junit4] 2> 678948 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!10 (1438156201053388800)]} 0 4
[junit4:junit4] 2> 678949 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10]} 0 7
[junit4:junit4] 2> 678953 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1438156201061777408)]} 0 1
[junit4:junit4] 2> 678960 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1438156201067020288)]} 0 0
[junit4:junit4] 2> 678961 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1438156201067020288)]} 0 4
[junit4:junit4] 2> 678962 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11]} 0 7
[junit4:junit4] 2> 678965 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1438156201075408896)]} 0 0
[junit4:junit4] 2> 678971 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1438156201078554624)]} 0 0
[junit4:junit4] 2> 678972 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1438156201078554624)]} 0 4
[junit4:junit4] 2> 678975 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1438156201085894656)]} 0 0
[junit4:junit4] 2> 678983 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1438156201091137536)]} 0 0
[junit4:junit4] 2> 678984 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1438156201091137536)]} 0 4
[junit4:junit4] 2> 678985 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13]} 0 7
[junit4:junit4] 2> 678988 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1438156201099526144)]} 0 0
[junit4:junit4] 2> 678996 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1438156201104769024)]} 0 0
[junit4:junit4] 2> 678997 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1438156201104769024)]} 0 4
[junit4:junit4] 2> 678998 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14]} 0 7
[junit4:junit4] 2> 679001 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1438156201113157632)]} 0 0
[junit4:junit4] 2> 679009 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1438156201118400512)]} 0 0
[junit4:junit4] 2> 679010 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1438156201118400512)]} 0 4
[junit4:junit4] 2> 679011 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15]} 0 7
[junit4:junit4] 2> 679014 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1438156201126789120)]} 0 0
[junit4:junit4] 2> 679022 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1438156201132032000)]} 0 0
[junit4:junit4] 2> 679023 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1438156201132032000)]} 0 4
[junit4:junit4] 2> 679024 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16]} 0 7
[junit4:junit4] 2> 679027 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1438156201140420608)]} 0 0
[junit4:junit4] 2> 679033 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1438156201143566336)]} 0 0
[junit4:junit4] 2> 679034 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1438156201143566336)]} 0 4
[junit4:junit4] 2> 679037 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1438156201150906368)]} 0 0
[junit4:junit4] 2> 679046 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1438156201156149248)]} 0 1
[junit4:junit4] 2> 679046 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1438156201156149248)]} 0 4
[junit4:junit4] 2> 679047 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18]} 0 7
[junit4:junit4] 2> 679051 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1438156201164537856)]} 0 1
[junit4:junit4] 2> 679057 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1438156201167683584)]} 0 0
[junit4:junit4] 2> 679058 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1438156201167683584)]} 0 5
[junit4:junit4] 2> 679061 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1438156201176072192)]} 0 0
[junit4:junit4] 2> 679069 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1438156201181315072)]} 0 0
[junit4:junit4] 2> 679070 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1438156201181315072)]} 0 4
[junit4:junit4] 2> 679071 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20]} 0 7
[junit4:junit4] 2> 679074 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1438156201189703680)]} 0 0
[junit4:junit4] 2> 679080 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1438156201192849408)]} 0 0
[junit4:junit4] 2> 679081 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1438156201192849408)]} 0 4
[junit4:junit4] 2> 679084 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1438156201200189440)]} 0 0
[junit4:junit4] 2> 679090 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1438156201203335168)]} 0 0
[junit4:junit4] 2> 679091 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1438156201203335168)]} 0 4
[junit4:junit4] 2> 679094 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1438156201210675200)]} 0 0
[junit4:junit4] 2> 679102 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1438156201215918080)]} 0 0
[junit4:junit4] 2> 679103 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1438156201215918080)]} 0 4
[junit4:junit4] 2> 679104 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23]} 0 7
[junit4:junit4] 2> 679107 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1438156201224306688)]} 0 0
[junit4:junit4] 2> 679115 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1438156201229549568)]} 0 0
[junit4:junit4] 2> 679116 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1438156201229549568)]} 0 4
[junit4:junit4] 2> 679117 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24]} 0 7
[junit4:junit4] 2> 679120 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1438156201237938176)]} 0 0
[junit4:junit4] 2> 679126 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1438156201241083904)]} 0 0
[junit4:junit4] 2> 679127 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1438156201241083904)]} 0 4
[junit4:junit4] 2> 679130 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1438156201248423936)]} 0 0
[junit4:junit4] 2> 679136 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1438156201251569664)]} 0 0
[junit4:junit4] 2> 679137 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1438156201251569664)]} 0 4
[junit4:junit4] 2> 679140 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1438156201258909696)]} 0 0
[junit4:junit4] 2> 679148 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1438156201264152576)]} 0 0
[junit4:junit4] 2> 679149 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1438156201264152576)]} 0 4
[junit4:junit4] 2> 679150 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27]} 0 7
[junit4:junit4] 2> 679152 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1438156201271492608)]} 0 0
[junit4:junit4] 2> 679161 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1438156201276735488)]} 0 1
[junit4:junit4] 2> 679161 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1438156201276735488)]} 0 4
[junit4:junit4] 2> 679162 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28]} 0 7
[junit4:junit4] 2> 679165 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1438156201285124096)]} 0 0
[junit4:junit4] 2> 679173 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1438156201290366976)]} 0 0
[junit4:junit4] 2> 679174 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1438156201290366976)]} 0 4
[junit4:junit4] 2> 679175 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29]} 0 7
[junit4:junit4] 2> 679179 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1438156201298755584)]} 0 1
[junit4:junit4] 2> 679186 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1438156201302949888)]} 0 1
[junit4:junit4] 2> 679187 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1438156201302949888)]} 0 5
[junit4:junit4] 2> 679191 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1438156201311338496)]} 0 1
[junit4:junit4] 2> 679199 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1438156201316581376)]} 0 1
[junit4:junit4] 2> 679200 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1438156201316581376)]} 0 5
[junit4:junit4] 2> 679200 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 7
[junit4:junit4] 2> 679204 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1438156201324969984)]} 0 1
[junit4:junit4] 2> 679210 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1438156201328115712)]} 0 1
[junit4:junit4] 2> 679211 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1438156201328115712)]} 0 5
[junit4:junit4] 2> 679214 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1438156201335455744)]} 0 1
[junit4:junit4] 2> 679219 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1438156201338601472)]} 0 0
[junit4:junit4] 2> 679220 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1438156201338601472)]} 0 4
[junit4:junit4] 2> 679223 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1438156201345941504)]} 0 0
[junit4:junit4] 2> 679231 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1438156201351184384)]} 0 0
[junit4:junit4] 2> 679232 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1438156201351184384)]} 0 4
[junit4:junit4] 2> 679233 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34]} 0 7
[junit4:junit4] 2> 679236 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1438156201359572992)]} 0 0
[junit4:junit4] 2> 679242 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1438156201362718720)]} 0 0
[junit4:junit4] 2> 679243 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1438156201362718720)]} 0 4
[junit4:junit4] 2> 679246 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1438156201370058752)]} 0 0
[junit4:junit4] 2> 679254 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1438156201375301632)]} 0 0
[junit4:junit4] 2> 679255 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1438156201375301632)]} 0 4
[junit4:junit4] 2> 679256 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36]} 0 7
[junit4:junit4] 2> 679259 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1438156201383690240)]} 0 0
[junit4:junit4] 2> 679267 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1438156201388933120)]} 0 0
[junit4:junit4] 2> 679268 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1438156201388933120)]} 0 4
[junit4:junit4] 2> 679269 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37]} 0 7
[junit4:junit4] 2> 679272 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1438156201397321728)]} 0 0
[junit4:junit4] 2> 679278 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1438156201400467456)]} 0 0
[junit4:junit4] 2> 679279 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1438156201400467456)]} 0 4
[junit4:junit4] 2> 679282 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1438156201407807488)]} 0 0
[junit4:junit4] 2> 679288 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1438156201410953216)]} 0 0
[junit4:junit4] 2> 679289 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1438156201410953216)]} 0 4
[junit4:junit4] 2> 679293 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1438156201419341824)]} 0 0
[junit4:junit4] 2> 679301 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1438156201424584704)]} 0 0
[junit4:junit4] 2> 679302 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!40 (1438156201424584704)]} 0 4
[junit4:junit4] 2> 679303 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40]} 0 7
[junit4:junit4] 2> 679306 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1438156201432973312)]} 0 0
[junit4:junit4] 2> 679313 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1438156201436119040)]} 0 0
[junit4:junit4] 2> 679313 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1438156201436119040)]} 0 4
[junit4:junit4] 2> 679316 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1438156201443459072)]} 0 0
[junit4:junit4] 2> 679324 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1438156201448701952)]} 0 0
[junit4:junit4] 2> 679325 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1438156201448701952)]} 0 4
[junit4:junit4] 2> 679326 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42]} 0 7
[junit4:junit4] 2> 679328 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1438156201456041984)]} 0 0
[junit4:junit4] 2> 679335 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1438156201459187712)]} 0 0
[junit4:junit4] 2> 679335 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1438156201459187712)]} 0 4
[junit4:junit4] 2> 679338 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1438156201466527744)]} 0 0
[junit4:junit4] 2> 679344 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1438156201469673472)]} 0 0
[junit4:junit4] 2> 679345 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1438156201469673472)]} 0 4
[junit4:junit4] 2> 679348 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1438156201477013504)]} 0 0
[junit4:junit4] 2> 679356 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1438156201482256384)]} 0 0
[junit4:junit4] 2> 679357 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1438156201482256384)]} 0 4
[junit4:junit4] 2> 679358 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45]} 0 7
[junit4:junit4] 2> 679361 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1438156201490644992)]} 0 0
[junit4:junit4] 2> 679369 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1438156201495887872)]} 0 0
[junit4:junit4] 2> 679370 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!46 (1438156201495887872)]} 0 4
[junit4:junit4] 2> 679371 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46]} 0 7
[junit4:junit4] 2> 679374 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1438156201504276480)]} 0 0
[junit4:junit4] 2> 679382 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1438156201509519360)]} 0 0
[junit4:junit4] 2> 679383 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1438156201509519360)]} 0 4
[junit4:junit4] 2> 679384 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47]} 0 7
[junit4:junit4] 2> 679387 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1438156201517907968)]} 0 0
[junit4:junit4] 2> 679397 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1438156201523150848)]} 0 1
[junit4:junit4] 2> 679397 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1438156201523150848)]} 0 5
[junit4:junit4] 2> 679398 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48]} 0 8
[junit4:junit4] 2> 679401 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1438156201532588032)]} 0 0
[junit4:junit4] 2> 679409 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1438156201537830912)]} 0 0
[junit4:junit4] 2> 679410 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1438156201537830912)]} 0 4
[junit4:junit4] 2> 679411 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49]} 0 7
[junit4:junit4] 2> 679414 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1438156201546219520)]} 0 0
[junit4:junit4] 2> 679422 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1438156201551462400)]} 0 0
[junit4:junit4] 2> 679423 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1438156201551462400)]} 0 4
[junit4:junit4] 2> 679424 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50]} 0 7
[junit4:junit4] 2> 679427 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1438156201559851008)]} 0 0
[junit4:junit4] 2> 679433 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1438156201562996736)]} 0 0
[junit4:junit4] 2> 679434 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1438156201562996736)]} 0 4
[junit4:junit4] 2> 679437 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1438156201570336768)]} 0 0
[junit4:junit4] 2> 679443 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1438156201573482496)]} 0 0
[junit4:junit4] 2> 679444 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1438156201573482496)]} 0 4
[junit4:junit4] 2> 679447 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1438156201580822528)]} 0 0
[junit4:junit4] 2> 679456 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1438156201586065408)]} 0 1
[junit4:junit4] 2> 679456 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1438156201586065408)]} 0 4
[junit4:junit4] 2> 679457 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53]} 0 7
[junit4:junit4] 2> 679460 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1438156201594454016)]} 0 0
[junit4:junit4] 2> 679468 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1438156201599696896)]} 0 0
[junit4:junit4] 2> 679469 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1438156201599696896)]} 0 4
[junit4:junit4] 2> 679470 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54]} 0 7
[junit4:junit4] 2> 679473 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1438156201608085504)]} 0 0
[junit4:junit4] 2> 679481 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1438156201613328384)]} 0 0
[junit4:junit4] 2> 679482 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1438156201613328384)]} 0 4
[junit4:junit4] 2> 679483 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 7
[junit4:junit4] 2> 679485 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1438156201620668416)]} 0 0
[junit4:junit4] 2> 679493 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1438156201625911296)]} 0 0
[junit4:junit4] 2> 679494 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1438156201625911296)]} 0 4
[junit4:junit4] 2> 679495 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56]} 0 7
[junit4:junit4] 2> 679499 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1438156201634299904)]} 0 1
[junit4:junit4] 2> 679506 T1544 C624 P19639 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1438156201639542784)]} 0 0
[junit4:junit4] 2> 679507 T1513 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1438156201639542784)]} 0 4
[junit4:junit4] 2> 679508 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57]} 0 7
[junit4:junit4] 2> 679511 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1438156201647931392)]} 0 0
[junit4:junit4] 2> 679519 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1438156201653174272)]} 0 0
[junit4:junit4] 2> 679520 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1438156201653174272)]} 0 4
[junit4:junit4] 2> 679521 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 7
[junit4:junit4] 2> 679523 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1438156201660514304)]} 0 0
[junit4:junit4] 2> 679531 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1438156201665757184)]} 0 0
[junit4:junit4] 2> 679532 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1438156201665757184)]} 0 4
[junit4:junit4] 2> 679533 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59]} 0 7
[junit4:junit4] 2> 679536 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1438156201674145792)]} 0 0
[junit4:junit4] 2> 679542 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1438156201677291520)]} 0 0
[junit4:junit4] 2> 679543 T1497 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1438156201677291520)]} 0 4
[junit4:junit4] 2> 679546 T1473 C626 P19622 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1438156201684631552)]} 0 0
[junit4:junit4] 2> 679554 T1525 C622 P19635 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19626/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1438156201689874432)]} 0 0
[junit4:junit4] 2> 679555 T1493 C623 P19626 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:19630/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!61 (1438156201689874432)]} 0 4
[junit4:junit4] 2> 679556 T1515 C625 P19630 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61]} 0 7
[junit4:junit4] 2> 679
[...truncated too long message...]
2> 1721817 T3250 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:63819_ik_x%2Fxx_collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:63819_ik_x%2Fxx",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63819/ik_x/xx"}
[junit4:junit4] 2> 1721820 T3250 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:63819_ik_x%2Fxx_collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[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:63819_ik_x%2Fxx",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63819/ik_x/xx"}
[junit4:junit4] 2> 1721829 T3240 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> 1721832 T3158 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 63822
[junit4:junit4] 2> 1721832 T3158 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1120341647
[junit4:junit4] 2> 1721989 T3180 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1721989 T3180 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> 1721989 T3180 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1722835 T3158 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1722835 T3158 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1722837 T3158 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@2d0b5de3
[junit4:junit4] 2> 1722846 T3158 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=43,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=74,cumulative_deletesById=34,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 1722847 T3158 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1722848 T3158 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1722848 T3158 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1722851 T3158 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1722851 T3158 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1722852 T3158 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371533562554/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371533562554/jetty2/index;done=false>>]
[junit4:junit4] 2> 1722852 T3158 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371533562554/jetty2/index
[junit4:junit4] 2> 1722853 T3158 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1371533562554/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1371533562554/jetty2;done=false>>]
[junit4:junit4] 2> 1722853 T3158 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1371533562554/jetty2
[junit4:junit4] 2> 1722854 T3250 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89884823556063242-127.0.0.1:63822_ik_x%2Fxx-n_0000000003) am no longer a leader.
[junit4:junit4] 2> 1722856 T3240 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> 1722856 T3240 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1722856 T3158 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/ik_x/xx,null}
[junit4:junit4] 2> 1722856 T3240 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1722922 T3158 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1722924 T3158 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:63812 63812
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.method=testDistribSearch -Dtests.seed=7E1360AB42849902 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=de_CH -Dtests.timezone=Europe/Warsaw -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 114s J1 | RecoveryZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: expected:<182> but was:<74>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([7E1360AB42849902:FFF5EEB335DBF93E]:0)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryZkTest.doTest(RecoveryZkTest.java:108)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 1723078 T3158 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=FastDecompressionCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST_DECOMPRESSION, chunkSize=310), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST_DECOMPRESSION, chunkSize=310)), sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=de_CH, timezone=Europe/Warsaw
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=1,free=125389904,total=533725184
[junit4:junit4] 2> NOTE: All tests run in this JVM: [LukeRequestHandlerTest, CircularListTest, TestDFRSimilarityFactory, TestJoin, SolrTestCaseJ4Test, NotRequiredUniqueKeyTest, TestArbitraryIndexDir, OutputWriterTest, QueryParsingTest, SliceStateUpdateTest, QueryResultKeyTest, TestPropInject, TestDynamicFieldResource, SuggesterWFSTTest, CopyFieldTest, CurrencyFieldXmlFileTest, WordBreakSolrSpellCheckerTest, ResourceLoaderTest, QueryEqualityTest, DOMUtilTest, TestCharFilters, TestDocSet, DistributedQueryElevationComponentTest, ClusterStateTest, RAMDirectoryFactoryTest, FastVectorHighlighterTest, TestUpdate, TestQueryTypes, TestQuerySenderListener, HighlighterConfigTest, TestIndexingPerformance, SpellCheckComponentTest, AutoCommitTest, TestFunctionQuery, CachingDirectoryFactoryTest, TestBinaryResponseWriter, DirectSolrConnectionTest, TestReloadAndDeleteDocs, ChaosMonkeySafeLeaderTest, XmlUpdateRequestHandlerTest, TestDynamicFieldCollectionResource, SearchHandlerTest, XsltUpdateRequestHandlerTest, DirectSolrSpellCheckerTest, TestRealTimeGet, ScriptEngineTest, TestPartialUpdateDeduplication, SolrIndexConfigTest, ShardRoutingCustomTest, DistributedTermsComponentTest, PluginInfoTest, FieldAnalysisRequestHandlerTest, TestSolrCoreProperties, RequestHandlersTest, TestSweetSpotSimilarityFactory, ClusterStateUpdateTest, DisMaxRequestHandlerTest, StatsComponentTest, TestDistributedSearch, ShardSplitTest, TestNumberUtils, TestCollationField, ChaosMonkeyShardSplitTest, TestFastWriter, SolrCmdDistributorTest, TestTrie, AnalysisAfterCoreReloadTest, SystemInfoHandlerTest, DocumentAnalysisRequestHandlerTest, BadIndexSchemaTest, TestRandomDVFaceting, TestReplicationHandler, UnloadDistributedZkTest, LeaderElectionIntegrationTest, RecoveryZkTest]
[junit4:junit4] Completed on J1 in 113.54s, 1 test, 1 failure <<< FAILURES!
[...truncated 421 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:392: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:372: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1246: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:890: There were test failures: 298 suites, 1253 tests, 1 error, 1 failure, 13 ignored (7 assumptions)
Total time: 54 minutes 34 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure