You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/05/17 06:35:12 UTC
[JENKINS] Lucene-Solr-Tests-trunk-java7 - Build # 3992 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-java7/3992/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:12233 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:12233 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([CCF8B25C48E70AA3:4D1E3C443FB86A9F]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java: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 9354 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 236909 T588 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 236916 T588 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1368763760203
[junit4:junit4] 2> 236934 T588 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 236935 T589 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 237035 T588 oasc.ZkTestServer.run start zk server on port:12226
[junit4:junit4] 2> 237036 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 237042 T595 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@331665d7 name:ZooKeeperConnection Watcher:127.0.0.1:12226 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 237043 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 237043 T588 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 237050 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 237162 T597 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@175cfaa5 name:ZooKeeperConnection Watcher:127.0.0.1:12226/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 237163 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 237164 T588 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 237169 T588 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 237173 T588 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 237183 T588 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 237188 T588 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 237375 T588 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 237406 T588 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 237407 T588 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 237515 T588 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 237516 T588 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 237524 T588 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 237526 T588 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 237532 T588 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 237534 T588 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 237538 T588 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 237539 T588 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 237543 T588 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 237544 T588 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 237552 T588 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 237553 T588 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 237558 T588 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 237559 T588 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 237945 T588 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 237951 T588 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12229
[junit4:junit4] 2> 237952 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 237953 T588 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 237953 T588 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368763760845
[junit4:junit4] 2> 237954 T588 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368763760845/solr.xml
[junit4:junit4] 2> 237954 T588 oasc.CoreContainer.<init> New CoreContainer 1012617594
[junit4:junit4] 2> 237955 T588 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368763760845/'
[junit4:junit4] 2> 237956 T588 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368763760845/'
[junit4:junit4] 2> 238264 T588 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 238265 T588 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 238266 T588 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 238273 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 238274 T588 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 238274 T588 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 238275 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 238276 T588 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 238276 T588 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 238277 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 238429 T588 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 238430 T588 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:12226/solr
[junit4:junit4] 2> 238447 T588 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 238449 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 238464 T608 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32f20d32 name:ZooKeeperConnection Watcher:127.0.0.1:12226 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 238465 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 238473 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 238496 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 238504 T610 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2a307bb2 name:ZooKeeperConnection Watcher:127.0.0.1:12226/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 238505 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 238533 T588 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 238575 T588 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 238580 T588 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 238583 T588 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12229_
[junit4:junit4] 2> 238610 T588 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12229_
[junit4:junit4] 2> 238614 T588 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 238683 T588 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 238687 T588 oasc.Overseer.start Overseer (id=89703301789188099-127.0.0.1:12229_-n_0000000000) starting
[junit4:junit4] 2> 238730 T588 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 238750 T612 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 238751 T588 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 238755 T588 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 238759 T588 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 238763 T611 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 238773 T613 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368763760845/collection1
[junit4:junit4] 2> 238773 T613 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 238774 T613 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 238775 T613 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 238806 T613 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368763760845/collection1/'
[junit4:junit4] 2> 238809 T613 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1368763760845/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 238810 T613 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1368763760845/collection1/lib/README' to classloader
[junit4:junit4] 2> 239055 T613 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 239154 T613 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 239257 T613 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 239280 T613 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 240273 T613 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 240278 T613 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 240281 T613 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 240287 T613 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 240338 T613 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 240339 T613 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1368763760845/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/control/data/
[junit4:junit4] 2> 240345 T613 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cda7939
[junit4:junit4] 2> 240346 T613 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 240347 T613 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/control/data
[junit4:junit4] 2> 240347 T613 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368763760187/control/data/index/
[junit4:junit4] 2> 240348 T613 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368763760187/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 240348 T613 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/control/data/index
[junit4:junit4] 2> 240353 T613 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@122e91e1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6910d843),segFN=segments_1,generation=1}
[junit4:junit4] 2> 240354 T613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 240366 T613 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 240367 T613 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 240368 T613 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 240369 T613 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 240369 T613 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 240370 T613 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 240370 T613 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 240371 T613 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 240372 T613 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 240386 T613 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 240395 T613 oass.SolrIndexSearcher.<init> Opening Searcher@1b7e58a2 main
[junit4:junit4] 2> 240403 T613 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/control/data/tlog
[junit4:junit4] 2> 240441 T613 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 240441 T613 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 240447 T614 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b7e58a2 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 240451 T613 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 240451 T613 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 241780 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 241782 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12229_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12229"}
[junit4:junit4] 2> 241782 T611 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 241783 T611 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 241839 T610 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> 242456 T613 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 242457 T613 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12229 collection:control_collection shard:shard1
[junit4:junit4] 2> 242498 T613 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 242530 T613 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 242567 T613 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 242573 T613 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 242573 T613 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 242573 T613 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:12229/collection1/
[junit4:junit4] 2> 242574 T613 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 242574 T613 oasc.SyncStrategy.syncToMe http://127.0.0.1:12229/collection1/ has no replicas
[junit4:junit4] 2> 242574 T613 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:12229/collection1/
[junit4:junit4] 2> 242575 T613 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 243388 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 243473 T610 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> 243567 T613 oasc.ZkController.register We are http://127.0.0.1:12229/collection1/ and leader is http://127.0.0.1:12229/collection1/
[junit4:junit4] 2> 243573 T613 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12229
[junit4:junit4] 2> 243574 T613 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 243574 T613 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 243574 T613 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 243577 T613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 243579 T588 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 243579 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 243832 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 243872 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 243883 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 243887 T617 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12ed826d name:ZooKeeperConnection Watcher:127.0.0.1:12226/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 243887 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 243889 T588 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 243900 T588 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 244233 T588 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 244236 T588 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12233
[junit4:junit4] 2> 244237 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 244238 T588 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 244238 T588 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368763767171
[junit4:junit4] 2> 244239 T588 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368763767171/solr.xml
[junit4:junit4] 2> 244239 T588 oasc.CoreContainer.<init> New CoreContainer 680687127
[junit4:junit4] 2> 244240 T588 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368763767171/'
[junit4:junit4] 2> 244241 T588 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368763767171/'
[junit4:junit4] 2> 244454 T588 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 244455 T588 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 244455 T588 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 244455 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 244456 T588 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 244456 T588 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 244457 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 244457 T588 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 244458 T588 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 244458 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 244478 T588 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 244479 T588 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:12226/solr
[junit4:junit4] 2> 244479 T588 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 244480 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 244484 T628 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@39e2bcc3 name:ZooKeeperConnection Watcher:127.0.0.1:12226 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 244485 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 244499 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 244515 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 244518 T630 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@20a8e005 name:ZooKeeperConnection Watcher:127.0.0.1:12226/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 244518 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 244527 T588 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 245085 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 245096 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12229_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12229"}
[junit4:junit4] 2> 245159 T630 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> 245159 T610 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> 245159 T617 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> 245536 T588 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12233_
[junit4:junit4] 2> 245544 T588 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12233_
[junit4:junit4] 2> 245548 T630 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> 245549 T610 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 245549 T617 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 245549 T610 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> 245550 T617 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> 245551 T630 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 245559 T631 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368763767171/collection1
[junit4:junit4] 2> 245559 T631 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 245561 T631 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 245562 T631 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 245563 T631 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368763767171/collection1/'
[junit4:junit4] 2> 245565 T631 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1368763767171/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 245566 T631 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1368763767171/collection1/lib/README' to classloader
[junit4:junit4] 2> 245811 T631 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 245911 T631 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 246013 T631 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 246027 T631 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 247240 T631 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 247244 T631 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 247247 T631 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 247254 T631 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 247292 T631 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 247293 T631 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1368763767171/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty1/
[junit4:junit4] 2> 247293 T631 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cda7939
[junit4:junit4] 2> 247294 T631 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 247295 T631 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty1
[junit4:junit4] 2> 247295 T631 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty1/index/
[junit4:junit4] 2> 247295 T631 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 247296 T631 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty1/index
[junit4:junit4] 2> 247305 T631 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6976f328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@727b89c0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 247305 T631 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 247316 T631 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 247317 T631 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 247318 T631 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 247319 T631 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 247321 T631 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 247321 T631 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 247322 T631 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 247323 T631 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 247324 T631 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 247374 T631 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 247387 T631 oass.SolrIndexSearcher.<init> Opening Searcher@386c0202 main
[junit4:junit4] 2> 247388 T631 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty1/tlog
[junit4:junit4] 2> 247390 T631 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 247390 T631 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 247398 T632 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@386c0202 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 247403 T631 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 247404 T631 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 248183 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 248188 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12233_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12233"}
[junit4:junit4] 2> 248188 T611 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 248189 T611 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 248204 T630 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> 248205 T617 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> 248204 T610 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> 248415 T631 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 248415 T631 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12233 collection:collection1 shard:shard1
[junit4:junit4] 2> 248422 T631 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 248514 T631 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 248557 T631 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 248558 T631 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 248558 T631 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:12233/collection1/
[junit4:junit4] 2> 248559 T631 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 248559 T631 oasc.SyncStrategy.syncToMe http://127.0.0.1:12233/collection1/ has no replicas
[junit4:junit4] 2> 248560 T631 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:12233/collection1/
[junit4:junit4] 2> 248560 T631 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 249714 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 249734 T610 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> 249734 T617 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> 249734 T630 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> 249739 T631 oasc.ZkController.register We are http://127.0.0.1:12233/collection1/ and leader is http://127.0.0.1:12233/collection1/
[junit4:junit4] 2> 249739 T631 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12233
[junit4:junit4] 2> 249739 T631 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 249739 T631 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 249740 T631 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 249741 T631 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 249742 T588 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 249743 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 249744 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 250035 T588 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 250038 T588 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12237
[junit4:junit4] 2> 250039 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 250039 T588 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 250040 T588 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368763773034
[junit4:junit4] 2> 250040 T588 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368763773034/solr.xml
[junit4:junit4] 2> 250041 T588 oasc.CoreContainer.<init> New CoreContainer 776384958
[junit4:junit4] 2> 250041 T588 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368763773034/'
[junit4:junit4] 2> 250042 T588 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368763773034/'
[junit4:junit4] 2> 250177 T588 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 250178 T588 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 250178 T588 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 250179 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 250179 T588 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 250180 T588 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 250180 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 250180 T588 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 250181 T588 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 250182 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 250204 T588 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 250205 T588 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:12226/solr
[junit4:junit4] 2> 250205 T588 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 250207 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 250212 T644 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@70c23b78 name:ZooKeeperConnection Watcher:127.0.0.1:12226 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 250213 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 250225 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 250245 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 250248 T646 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@630d1d3 name:ZooKeeperConnection Watcher:127.0.0.1:12226/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 250248 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 250257 T588 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 251242 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 251243 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12233_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12233"}
[junit4:junit4] 2> 251259 T646 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> 251260 T630 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> 251259 T617 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> 251259 T610 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> 251262 T588 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12237_
[junit4:junit4] 2> 251269 T588 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12237_
[junit4:junit4] 2> 251271 T630 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> 251271 T610 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 251271 T646 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 251271 T617 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 251272 T646 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> 251271 T610 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> 251272 T617 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> 251274 T630 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 251279 T647 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368763773034/collection1
[junit4:junit4] 2> 251280 T647 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 251280 T647 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 251280 T647 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 251282 T647 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368763773034/collection1/'
[junit4:junit4] 2> 251283 T647 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1368763773034/collection1/lib/README' to classloader
[junit4:junit4] 2> 251284 T647 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1368763773034/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 251322 T647 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 251363 T647 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 251464 T647 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 251478 T647 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 252144 T647 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 252149 T647 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 252151 T647 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 252157 T647 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 252189 T647 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 252190 T647 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1368763773034/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty2/
[junit4:junit4] 2> 252190 T647 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cda7939
[junit4:junit4] 2> 252191 T647 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 252192 T647 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty2
[junit4:junit4] 2> 252192 T647 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty2/index/
[junit4:junit4] 2> 252192 T647 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 252193 T647 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty2/index
[junit4:junit4] 2> 252203 T647 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45b11a5f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f69039e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 252204 T647 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 252211 T647 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 252212 T647 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 252212 T647 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 252213 T647 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 252214 T647 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 252214 T647 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 252215 T647 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 252216 T647 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 252216 T647 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 252232 T647 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 252239 T647 oass.SolrIndexSearcher.<init> Opening Searcher@3f257dae main
[junit4:junit4] 2> 252239 T647 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty2/tlog
[junit4:junit4] 2> 252240 T647 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 252241 T647 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 252247 T648 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f257dae main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 252250 T647 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 252251 T647 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 252766 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 252767 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12237_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12237"}
[junit4:junit4] 2> 252768 T611 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 252768 T611 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 252783 T630 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> 252783 T617 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> 252783 T646 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> 252783 T610 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> 253255 T647 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 253255 T647 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12237 collection:collection1 shard:shard2
[junit4:junit4] 2> 253257 T647 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 253273 T647 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 253285 T647 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 253285 T647 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 253286 T647 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:12237/collection1/
[junit4:junit4] 2> 253286 T647 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 253286 T647 oasc.SyncStrategy.syncToMe http://127.0.0.1:12237/collection1/ has no replicas
[junit4:junit4] 2> 253286 T647 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:12237/collection1/
[junit4:junit4] 2> 253287 T647 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 254290 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 254315 T610 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> 254315 T630 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> 254315 T646 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> 254315 T617 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> 254327 T647 oasc.ZkController.register We are http://127.0.0.1:12237/collection1/ and leader is http://127.0.0.1:12237/collection1/
[junit4:junit4] 2> 254327 T647 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12237
[junit4:junit4] 2> 254327 T647 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 254328 T647 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 254328 T647 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 254330 T647 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 254331 T588 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 254331 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 254332 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 254595 T588 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 254599 T588 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:38930
[junit4:junit4] 2> 254600 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 254600 T588 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 254601 T588 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368763777623
[junit4:junit4] 2> 254601 T588 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368763777623/solr.xml
[junit4:junit4] 2> 254602 T588 oasc.CoreContainer.<init> New CoreContainer 2142559762
[junit4:junit4] 2> 254602 T588 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368763777623/'
[junit4:junit4] 2> 254603 T588 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368763777623/'
[junit4:junit4] 2> 254728 T588 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 254729 T588 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 254729 T588 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 254730 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 254730 T588 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 254731 T588 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 254731 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 254732 T588 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 254732 T588 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 254733 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 254752 T588 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 254753 T588 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:12226/solr
[junit4:junit4] 2> 254753 T588 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 254754 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 254758 T660 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@599ebf6c name:ZooKeeperConnection Watcher:127.0.0.1:12226 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 254759 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 254761 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 254778 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 254780 T662 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@39905f87 name:ZooKeeperConnection Watcher:127.0.0.1:12226/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 254781 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 254793 T588 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 255797 T588 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38930_
[junit4:junit4] 2> 255799 T588 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38930_
[junit4:junit4] 2> 255801 T630 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> 255802 T662 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 255802 T610 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 255802 T617 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 255802 T646 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 255803 T617 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> 255802 T610 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> 255803 T646 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> 255803 T630 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 255817 T663 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368763777623/collection1
[junit4:junit4] 2> 255818 T663 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 255818 T663 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 255819 T663 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 255820 T663 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368763777623/collection1/'
[junit4:junit4] 2> 255822 T663 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1368763777623/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 255822 T663 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1368763777623/collection1/lib/README' to classloader
[junit4:junit4] 2> 255828 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 255829 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12237_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12237"}
[junit4:junit4] 2> 255839 T646 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> 255839 T630 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> 255839 T662 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> 255839 T617 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> 255839 T610 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> 255881 T663 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 255949 T663 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 256051 T663 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 256061 T663 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 256488 T663 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 256493 T663 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 256496 T663 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 256502 T663 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 256528 T663 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 256528 T663 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1368763777623/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/
[junit4:junit4] 2> 256528 T663 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cda7939
[junit4:junit4] 2> 256529 T663 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 256530 T663 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3
[junit4:junit4] 2> 256530 T663 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/index/
[junit4:junit4] 2> 256530 T663 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 256531 T663 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/index
[junit4:junit4] 2> 256537 T663 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@472b3178 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b6813ad),segFN=segments_1,generation=1}
[junit4:junit4] 2> 256538 T663 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 256541 T663 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 256541 T663 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 256541 T663 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 256543 T663 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 256543 T663 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 256543 T663 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 256544 T663 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 256545 T663 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 256545 T663 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 256554 T663 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 256558 T663 oass.SolrIndexSearcher.<init> Opening Searcher@52becbb main
[junit4:junit4] 2> 256559 T663 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/tlog
[junit4:junit4] 2> 256560 T663 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 256560 T663 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 256565 T664 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@52becbb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 256567 T663 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 256568 T663 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 257344 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 257345 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38930_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38930"}
[junit4:junit4] 2> 257346 T611 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 257346 T611 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 257364 T646 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> 257364 T610 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> 257364 T662 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> 257364 T630 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> 257364 T617 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> 257573 T663 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 257573 T663 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38930 collection:collection1 shard:shard1
[junit4:junit4] 2> 257583 T663 oasc.ZkController.register We are http://127.0.0.1:38930/collection1/ and leader is http://127.0.0.1:12233/collection1/
[junit4:junit4] 2> 257584 T663 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38930
[junit4:junit4] 2> 257584 T663 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 257584 T663 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C12 name=collection1 org.apache.solr.core.SolrCore@14b153a3 url=http://127.0.0.1:38930/collection1 node=127.0.0.1:38930_ C12_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:38930_, base_url=http://127.0.0.1:38930}
[junit4:junit4] 2> 257592 T665 C12 P38930 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 257592 T663 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 257593 T665 C12 P38930 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 257594 T665 C12 P38930 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 257594 T665 C12 P38930 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 257594 T588 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 257595 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 257596 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 257617 T665 C12 P38930 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 257952 T588 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 257955 T588 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:59526
[junit4:junit4] 2> 257956 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 257957 T588 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 257957 T588 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368763780884
[junit4:junit4] 2> 257958 T588 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368763780884/solr.xml
[junit4:junit4] 2> 257958 T588 oasc.CoreContainer.<init> New CoreContainer 1119429088
[junit4:junit4] 2> 257959 T588 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368763780884/'
[junit4:junit4] 2> 257959 T588 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368763780884/'
[junit4:junit4] 2> 258108 T588 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 258110 T588 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 258111 T588 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 258111 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 258112 T588 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 258112 T588 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 258113 T588 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 258114 T588 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 258114 T588 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 258115 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 258139 T588 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 258140 T588 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:12226/solr
[junit4:junit4] 2> 258140 T588 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 258142 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 258186 T677 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@397c1057 name:ZooKeeperConnection Watcher:127.0.0.1:12226 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 258187 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 258206 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 258220 T588 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 258227 T679 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5bf0e6d5 name:ZooKeeperConnection Watcher:127.0.0.1:12226/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 258228 T588 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 258251 T588 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 258801 T620 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 258876 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 258878 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38930_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38930"}
[junit4:junit4] 2> 258902 T610 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> 258903 T662 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> 258903 T617 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> 258903 T679 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> 258902 T646 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> 258902 T630 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> 259255 T588 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59526_
[junit4:junit4] 2> 259262 T588 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59526_
[junit4:junit4] 2> 259274 T630 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> 259274 T610 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 259274 T617 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 259274 T646 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 259274 T662 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 259274 T679 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 259279 T662 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> 259278 T646 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> 259278 T630 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 259277 T617 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> 259276 T610 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> 259280 T679 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> 259288 T680 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368763780884/collection1
[junit4:junit4] 2> 259289 T680 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 259290 T680 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 259291 T680 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 259305 T680 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368763780884/collection1/'
[junit4:junit4] 2> 259308 T680 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1368763780884/collection1/lib/README' to classloader
[junit4:junit4] 2> 259309 T680 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1368763780884/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 259428 T680 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 259507 T680 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 259610 T680 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 259622 T680 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 259803 T620 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 259804 T620 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:38930_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1010
[junit4:junit4] 2> 260320 T680 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 260325 T680 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 260328 T680 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 260335 T680 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 260367 T680 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 260368 T680 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1368763780884/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/
[junit4:junit4] 2> 260369 T680 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1cda7939
[junit4:junit4] 2> 260370 T680 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 260371 T680 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4
[junit4:junit4] 2> 260372 T680 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index/
[junit4:junit4] 2> 260373 T680 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 260374 T680 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index
[junit4:junit4] 2> 260378 T680 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2dacdb61 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fc55091),segFN=segments_1,generation=1}
[junit4:junit4] 2> 260379 T680 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 260384 T680 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 260384 T680 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 260386 T680 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 260387 T680 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 260388 T680 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 260389 T680 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 260390 T680 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 260391 T680 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 260392 T680 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 260407 T680 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 260415 T680 oass.SolrIndexSearcher.<init> Opening Searcher@2223878 main
[junit4:junit4] 2> 260415 T680 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/tlog
[junit4:junit4] 2> 260416 T680 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 260417 T680 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 260424 T681 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2223878 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 260427 T680 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 260428 T680 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 261923 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 261923 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59526_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59526"}
[junit4:junit4] 2> 261924 T611 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 261924 T611 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> C12_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:38930_, base_url=http://127.0.0.1:38930}
[junit4:junit4] 2> 261942 T665 C12 P38930 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:12233/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 261953 T665 C12 P38930 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 261975 T630 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> 261975 T617 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> 261975 T610 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> 261975 T679 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> 261975 T646 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> 261975 T662 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> 261979 T665 C12 P38930 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38930 START replicas=[http://127.0.0.1:12233/collection1/] nUpdates=100
[junit4:junit4] 2> 261989 T665 C12 P38930 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 261990 T665 C12 P38930 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 261990 T665 C12 P38930 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 261990 T665 C12 P38930 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 261991 T665 C12 P38930 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 261991 T665 C12 P38930 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:12233/collection1/. core=collection1
[junit4:junit4] 2> 261991 T665 C12 P38930 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C13 name=collection1 org.apache.solr.core.SolrCore@25d8c06a url=http://127.0.0.1:12233/collection1 node=127.0.0.1:12233_ C13_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:12233_, base_url=http://127.0.0.1:12233, leader=true}
[junit4:junit4] 2> 262046 T622 C13 P12233 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=7
[junit4:junit4] 2> 262065 T621 C13 P12233 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 262086 T621 C13 P12233 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6976f328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@727b89c0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 262087 T621 C13 P12233 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 262088 T621 C13 P12233 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6976f328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@727b89c0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6976f328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@727b89c0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 262089 T621 C13 P12233 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 262089 T621 C13 P12233 oass.SolrIndexSearcher.<init> Opening Searcher@fe0272f realtime
[junit4:junit4] 2> 262090 T621 C13 P12233 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 262091 T621 C13 P12233 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 52
[junit4:junit4] 2> 262165 T665 C12 P38930 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 262166 T665 C12 P38930 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 262200 T665 C12 P38930 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 262266 T623 C13 P12233 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 262267 T623 C13 P12233 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=63
[junit4:junit4] 2> 262269 T665 C12 P38930 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 262270 T665 C12 P38930 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 262270 T665 C12 P38930 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 262274 T623 C13 P12233 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> 262276 T665 C12 P38930 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 262277 T665 C12 P38930 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/index.20130516220945546
[junit4:junit4] 2> 262278 T665 C12 P38930 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@651ff2d2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4fc0fe5b) fullCopy=false
[junit4:junit4] 2> 262294 T623 C13 P12233 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=7
[junit4:junit4] 2> 262310 T665 C12 P38930 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 262312 T665 C12 P38930 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 262313 T665 C12 P38930 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 262336 T665 C12 P38930 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@472b3178 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b6813ad),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@472b3178 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b6813ad),segFN=segments_2,generation=2}
[junit4:junit4] 2> 262337 T665 C12 P38930 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 262338 T665 C12 P38930 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 262338 T665 C12 P38930 oass.SolrIndexSearcher.<init> Opening Searcher@71ada121 main
[junit4:junit4] 2> 262340 T664 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71ada121 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 262341 T665 C12 P38930 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/index.20130516220945546 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/index.20130516220945546;done=true>>]
[junit4:junit4] 2> 262342 T665 C12 P38930 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/index.20130516220945546
[junit4:junit4] 2> 262342 T665 C12 P38930 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty3/index.20130516220945546
[junit4:junit4] 2> 262343 T665 C12 P38930 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 262343 T665 C12 P38930 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 262343 T665 C12 P38930 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 262344 T665 C12 P38930 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 262346 T665 C12 P38930 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 262433 T680 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 262433 T680 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59526 collection:collection1 shard:shard2
[junit4:junit4] 2> 262437 T680 oasc.ZkController.register We are http://127.0.0.1:59526/collection1/ and leader is http://127.0.0.1:12237/collection1/
[junit4:junit4] 2> 262438 T680 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59526
[junit4:junit4] 2> 262438 T680 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 262438 T680 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C14 name=collection1 org.apache.solr.core.SolrCore@42858d1e url=http://127.0.0.1:59526/collection1 node=127.0.0.1:59526_ C14_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:59526_, base_url=http://127.0.0.1:59526}
[junit4:junit4] 2> 262439 T684 C14 P59526 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 262440 T680 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 262440 T684 C14 P59526 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 262441 T684 C14 P59526 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 262441 T684 C14 P59526 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 262442 T588 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 262443 T588 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 262444 T588 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 262449 T684 C14 P59526 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 262460 T588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 262462 T588 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 262463 T588 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 262464 T588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 262468 T636 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 263466 T588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 263493 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 263494 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38930_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38930"}
[junit4:junit4] 2> 263557 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59526_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59526"}
[junit4:junit4] 2> 263597 T662 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> 263598 T630 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> 263598 T646 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> 263597 T617 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> 263597 T610 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> 263597 T679 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> 264469 T588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 264471 T636 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 264471 T636 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:59526_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 265472 T588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C14_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59526_, base_url=http://127.0.0.1:59526}
[junit4:junit4] 2> 266473 T684 C14 P59526 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:12237/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 266473 T684 C14 P59526 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59526 START replicas=[http://127.0.0.1:12237/collection1/] nUpdates=100
[junit4:junit4] 2> 266474 T684 C14 P59526 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 266474 T684 C14 P59526 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 266474 T684 C14 P59526 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 266474 T684 C14 P59526 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 266475 T684 C14 P59526 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 266475 T684 C14 P59526 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:12237/collection1/. core=collection1
[junit4:junit4] 2> 266476 T684 C14 P59526 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 266476 T588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C15 name=collection1 org.apache.solr.core.SolrCore@353f42fc url=http://127.0.0.1:12237/collection1 node=127.0.0.1:12237_ C15_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:12237_, base_url=http://127.0.0.1:12237, leader=true}
[junit4:junit4] 2> 266489 T637 C15 P12237 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> 266494 T638 C15 P12237 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 266508 T638 C15 P12237 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45b11a5f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f69039e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 266513 T638 C15 P12237 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 266514 T638 C15 P12237 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45b11a5f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f69039e),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45b11a5f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f69039e),segFN=segments_2,generation=2}
[junit4:junit4] 2> 266514 T638 C15 P12237 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 266514 T638 C15 P12237 oass.SolrIndexSearcher.<init> Opening Searcher@621c1360 realtime
[junit4:junit4] 2> 266515 T638 C15 P12237 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 266515 T638 C15 P12237 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 22
[junit4:junit4] 2> 266516 T684 C14 P59526 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 266516 T684 C14 P59526 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 266519 T639 C15 P12237 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 266520 T639 C15 P12237 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 266520 T684 C14 P59526 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 266520 T684 C14 P59526 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 266521 T684 C14 P59526 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 266523 T639 C15 P12237 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> 266524 T684 C14 P59526 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 266525 T684 C14 P59526 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index.20130516220949794
[junit4:junit4] 2> 266525 T684 C14 P59526 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@15cafd1a lockFactory=org.apache.lucene.store.NativeFSLockFactory@192b8681) fullCopy=false
[junit4:junit4] 2> 266529 T639 C15 P12237 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> 266530 T684 C14 P59526 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 266531 T684 C14 P59526 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 266531 T684 C14 P59526 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 266546 T684 C14 P59526 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2dacdb61 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fc55091),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2dacdb61 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fc55091),segFN=segments_2,generation=2}
[junit4:junit4] 2> 266547 T684 C14 P59526 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 266547 T684 C14 P59526 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 266547 T684 C14 P59526 oass.SolrIndexSearcher.<init> Opening Searcher@22815b70 main
[junit4:junit4] 2> 266548 T681 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@22815b70 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 266549 T684 C14 P59526 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index.20130516220949794 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index.20130516220949794;done=true>>]
[junit4:junit4] 2> 266549 T684 C14 P59526 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index.20130516220949794
[junit4:junit4] 2> 266549 T684 C14 P59526 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index.20130516220949794
[junit4:junit4] 2> 266549 T684 C14 P59526 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 266550 T684 C14 P59526 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 266550 T684 C14 P59526 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 266550 T684 C14 P59526 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 266552 T684 C14 P59526 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 266606 T611 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 266607 T611 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59526_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59526"}
[junit4:junit4] 2> 266612 T679 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> 266612 T610 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> 266612 T617 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> 266612 T630 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> 266612 T646 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> 266612 T662 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> 267478 T588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 267480 T588 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C16 name=collection1 org.apache.solr.core.SolrCore@37d917b2 url=http://127.0.0.1:12229/collection1 node=127.0.0.1:12229_ C16_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:12229_, base_url=http://127.0.0.1:12229, leader=true}
[junit4:junit4] 2> 267500 T600 C16 P12229 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 267538 T600 C16 P12229 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@122e91e1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6910d843),segFN=segments_1,generation=1}
[junit4:junit4] 2> 267539 T600 C16 P12229 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 267541 T600 C16 P12229 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@122e91e1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6910d843),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@122e91e1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6910d843),segFN=segments_2,generation=2}
[junit4:junit4] 2> 267542 T600 C16 P12229 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 267543 T600 C16 P12229 oass.SolrIndexSearcher.<init> Opening Searcher@777c73ff main
[junit4:junit4] 2> 267543 T600 C16 P12229 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267545 T614 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@777c73ff main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267546 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 47
[junit4:junit4] 2> 267578 T640 C15 P12237 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 267579 T640 C15 P12237 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45b11a5f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f69039e),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@45b11a5f lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f69039e),segFN=segments_3,generation=3}
[junit4:junit4] 2> 267580 T640 C15 P12237 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 267580 T640 C15 P12237 oass.SolrIndexSearcher.<init> Opening Searcher@62cf0e01 main
[junit4:junit4] 2> 267581 T640 C15 P12237 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267582 T648 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@62cf0e01 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267603 T640 C15 P12237 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:12233/collection1/, StdNode: http://127.0.0.1:38930/collection1/, StdNode: http://127.0.0.1:59526/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 267613 T624 C13 P12233 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 267615 T624 C13 P12233 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6976f328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@727b89c0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6976f328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@727b89c0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 267616 T624 C13 P12233 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 267616 T624 C13 P12233 oass.SolrIndexSearcher.<init> Opening Searcher@2d955f79 main
[junit4:junit4] 2> 267617 T624 C13 P12233 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267618 T632 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d955f79 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267619 T624 C13 P12233 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> C12_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:38930_, base_url=http://127.0.0.1:38930}
[junit4:junit4] 2> 267621 T652 C12 P38930 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 267623 T652 C12 P38930 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@472b3178 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b6813ad),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@472b3178 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6b6813ad),segFN=segments_3,generation=3}
[junit4:junit4] 2> C14_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:59526_, base_url=http://127.0.0.1:59526}
[junit4:junit4] 2> 267623 T669 C14 P59526 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 267623 T652 C12 P38930 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 267625 T669 C14 P59526 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2dacdb61 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fc55091),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2dacdb61 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fc55091),segFN=segments_3,generation=3}
[junit4:junit4] 2> 267625 T652 C12 P38930 oass.SolrIndexSearcher.<init> Opening Searcher@72fabe72 main
[junit4:junit4] 2> 267625 T669 C14 P59526 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 267626 T652 C12 P38930 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267627 T669 C14 P59526 oass.SolrIndexSearcher.<init> Opening Searcher@2d6ab39 main
[junit4:junit4] 2> 267627 T664 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@72fabe72 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267627 T669 C14 P59526 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 267628 T652 C12 P38930 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> 267628 T681 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d6ab39 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 267629 T669 C14 P59526 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> 267630 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 53
[junit4:junit4] 2> 267631 T588 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 267659 T625 C13 P12233 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> 267663 T653 C12 P38930 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 267667 T641 C15 P12237 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> 267670 T670 C14 P59526 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 269834 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435252863073779712)} 0 83
[junit4:junit4] 2> 269866 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435252863123062784&update.from=http://127.0.0.1:12237/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435252863123062784)} 0 4
[junit4:junit4] 2> 269880 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435252863147180032&update.from=http://127.0.0.1:12233/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435252863147180032)} 0 5
[junit4:junit4] 2> 269881 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435252863147180032)} 0 19
[junit4:junit4] 2> 269882 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435252863123062784)} 0 43
[junit4:junit4] 2> 269894 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1435252863178637312)]} 0 7
[junit4:junit4] 2> 269921 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1435252863202754560)]} 0 1
[junit4:junit4] 2> 269922 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1435252863202754560)]} 0 7
[junit4:junit4] 2> 269923 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0]} 0 24
[junit4:junit4] 2> 269927 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1435252863215337472)]} 0 0
[junit4:junit4] 2> 269937 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1435252863219531776)]} 0 1
[junit4:junit4] 2> 269938 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1435252863219531776)]} 0 8
[junit4:junit4] 2> 269942 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1435252863231066112)]} 0 0
[junit4:junit4] 2> 269951 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1435252863236308992)]} 0 1
[junit4:junit4] 2> 269952 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1435252863236308992)]} 0 6
[junit4:junit4] 2> 269958 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1435252863246794752)]} 0 1
[junit4:junit4] 2> 269970 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1435252863255183360)]} 0 1
[junit4:junit4] 2> 269971 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1435252863255183360)]} 0 6
[junit4:junit4] 2> 269972 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3]} 0 10
[junit4:junit4] 2> 269977 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1435252863266717696)]} 0 1
[junit4:junit4] 2> 269992 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1435252863278252032)]} 0 1
[junit4:junit4] 2> 269993 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1435252863278252032)]} 0 6
[junit4:junit4] 2> 269997 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1435252863288737792)]} 0 1
[junit4:junit4] 2> 270010 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1435252863297126400)]} 0 1
[junit4:junit4] 2> 270011 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1435252863297126400)]} 0 6
[junit4:junit4] 2> 270012 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5]} 0 11
[junit4:junit4] 2> 270016 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1435252863308660736)]} 0 0
[junit4:junit4] 2> 270025 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1435252863312855040)]} 0 1
[junit4:junit4] 2> 270026 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1435252863312855040)]} 0 6
[junit4:junit4] 2> 270030 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1435252863323340800)]} 0 0
[junit4:junit4] 2> 270041 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1435252863330680832)]} 0 0
[junit4:junit4] 2> 270042 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1435252863330680832)]} 0 5
[junit4:junit4] 2> 270043 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7]} 0 9
[junit4:junit4] 2> 270047 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1435252863341166592)]} 0 0
[junit4:junit4] 2> 270057 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1435252863346409472)]} 0 1
[junit4:junit4] 2> 270057 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1435252863346409472)]} 0 5
[junit4:junit4] 2> 270062 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1435252863356895232)]} 0 0
[junit4:junit4] 2> 270072 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1435252863363186688)]} 0 0
[junit4:junit4] 2> 270073 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1435252863363186688)]} 0 5
[junit4:junit4] 2> 270074 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9]} 0 8
[junit4:junit4] 2> 270078 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1435252863373672448)]} 0 1
[junit4:junit4] 2> 270090 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1435252863382061056)]} 0 1
[junit4:junit4] 2> 270091 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!10 (1435252863382061056)]} 0 5
[junit4:junit4] 2> 270092 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10]} 0 10
[junit4:junit4] 2> 270096 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1435252863392546816)]} 0 1
[junit4:junit4] 2> 270108 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1435252863400935424)]} 0 1
[junit4:junit4] 2> 270109 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1435252863400935424)]} 0 5
[junit4:junit4] 2> 270109 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11]} 0 9
[junit4:junit4] 2> 270114 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1435252863411421184)]} 0 1
[junit4:junit4] 2> 270125 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1435252863419809792)]} 0 0
[junit4:junit4] 2> 270126 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1435252863419809792)]} 0 4
[junit4:junit4] 2> 270127 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 9
[junit4:junit4] 2> 270132 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1435252863430295552)]} 0 1
[junit4:junit4] 2> 270146 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1435252863439732736)]} 0 1
[junit4:junit4] 2> 270148 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1435252863439732736)]} 0 8
[junit4:junit4] 2> 270149 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13]} 0 13
[junit4:junit4] 2> 270153 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1435252863452315648)]} 0 0
[junit4:junit4] 2> 270166 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1435252863460704256)]} 0 1
[junit4:junit4] 2> 270167 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1435252863460704256)]} 0 6
[junit4:junit4] 2> 270167 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14]} 0 10
[junit4:junit4] 2> 270172 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1435252863472238592)]} 0 1
[junit4:junit4] 2> 270184 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1435252863479578624)]} 0 1
[junit4:junit4] 2> 270185 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1435252863479578624)]} 0 5
[junit4:junit4] 2> 270186 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15]} 0 10
[junit4:junit4] 2> 270190 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1435252863491112960)]} 0 1
[junit4:junit4] 2> 270202 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1435252863498452992)]} 0 1
[junit4:junit4] 2> 270203 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1435252863498452992)]} 0 6
[junit4:junit4] 2> 270203 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16]} 0 9
[junit4:junit4] 2> 270208 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1435252863509987328)]} 0 1
[junit4:junit4] 2> 270216 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1435252863514181632)]} 0 0
[junit4:junit4] 2> 270217 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1435252863514181632)]} 0 5
[junit4:junit4] 2> 270222 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1435252863524667392)]} 0 1
[junit4:junit4] 2> 270230 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1435252863528861696)]} 0 0
[junit4:junit4] 2> 270231 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1435252863528861696)]} 0 5
[junit4:junit4] 2> 270235 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1435252863538298880)]} 0 1
[junit4:junit4] 2> 270243 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1435252863542493184)]} 0 0
[junit4:junit4] 2> 270244 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1435252863542493184)]} 0 5
[junit4:junit4] 2> 270249 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1435252863552978944)]} 0 1
[junit4:junit4] 2> 270256 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1435252863557173248)]} 0 0
[junit4:junit4] 2> 270257 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1435252863557173248)]} 0 5
[junit4:junit4] 2> 270261 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1435252863565561856)]} 0 0
[junit4:junit4] 2> 270269 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1435252863569756160)]} 0 0
[junit4:junit4] 2> 270270 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1435252863569756160)]} 0 5
[junit4:junit4] 2> 270275 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1435252863579193344)]} 0 1
[junit4:junit4] 2> 270285 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1435252863587581952)]} 0 1
[junit4:junit4] 2> 270286 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!22 (1435252863587581952)]} 0 4
[junit4:junit4] 2> 270287 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22]} 0 8
[junit4:junit4] 2> 270291 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1435252863597019136)]} 0 0
[junit4:junit4] 2> 270299 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1435252863601213440)]} 0 0
[junit4:junit4] 2> 270300 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1435252863601213440)]} 0 5
[junit4:junit4] 2> 270304 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1435252863610650624)]} 0 1
[junit4:junit4] 2> 270312 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1435252863614844928)]} 0 0
[junit4:junit4] 2> 270313 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1435252863614844928)]} 0 6
[junit4:junit4] 2> 270318 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1435252863625330688)]} 0 1
[junit4:junit4] 2> 270326 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1435252863629524992)]} 0 0
[junit4:junit4] 2> 270327 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1435252863629524992)]} 0 5
[junit4:junit4] 2> 270332 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1435252863640010752)]} 0 0
[junit4:junit4] 2> 270339 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1435252863644205056)]} 0 1
[junit4:junit4] 2> 270340 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1435252863644205056)]} 0 5
[junit4:junit4] 2> 270344 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1435252863652593664)]} 0 1
[junit4:junit4] 2> 270353 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1435252863657836544)]} 0 1
[junit4:junit4] 2> 270354 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1435252863657836544)]} 0 6
[junit4:junit4] 2> 270359 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1435252863667273728)]} 0 1
[junit4:junit4] 2> 270367 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1435252863672516608)]} 0 1
[junit4:junit4] 2> 270368 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1435252863672516608)]} 0 5
[junit4:junit4] 2> 270372 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1435252863681953792)]} 0 1
[junit4:junit4] 2> 270380 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1435252863686148096)]} 0 1
[junit4:junit4] 2> 270381 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1435252863686148096)]} 0 5
[junit4:junit4] 2> 270385 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1435252863695585280)]} 0 1
[junit4:junit4] 2> 270396 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1435252863703973888)]} 0 1
[junit4:junit4] 2> 270397 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1435252863703973888)]} 0 5
[junit4:junit4] 2> 270398 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30]} 0 9
[junit4:junit4] 2> 270402 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1435252863713411072)]} 0 0
[junit4:junit4] 2> 270413 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1435252863721799680)]} 0 1
[junit4:junit4] 2> 270414 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1435252863721799680)]} 0 5
[junit4:junit4] 2> 270415 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 9
[junit4:junit4] 2> 270420 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1435252863732285440)]} 0 0
[junit4:junit4] 2> 270431 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1435252863740674048)]} 0 0
[junit4:junit4] 2> 270432 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!32 (1435252863740674048)]} 0 4
[junit4:junit4] 2> 270433 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32]} 0 8
[junit4:junit4] 2> 270437 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1435252863750111232)]} 0 1
[junit4:junit4] 2> 270446 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1435252863754305536)]} 0 1
[junit4:junit4] 2> 270447 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1435252863754305536)]} 0 6
[junit4:junit4] 2> 270452 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1435252863765839872)]} 0 1
[junit4:junit4] 2> 270462 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1435252863773179904)]} 0 1
[junit4:junit4] 2> 270463 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1435252863773179904)]} 0 5
[junit4:junit4] 2> 270463 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34]} 0 8
[junit4:junit4] 2> 270467 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1435252863781568512)]} 0 0
[junit4:junit4] 2> 270475 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1435252863785762816)]} 0 1
[junit4:junit4] 2> 270476 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1435252863785762816)]} 0 5
[junit4:junit4] 2> 270480 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1435252863795200000)]} 0 1
[junit4:junit4] 2> 270490 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1435252863802540032)]} 0 0
[junit4:junit4] 2> 270491 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1435252863802540032)]} 0 5
[junit4:junit4] 2> 270492 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36]} 0 9
[junit4:junit4] 2> 270496 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1435252863811977216)]} 0 0
[junit4:junit4] 2> 270504 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1435252863816171520)]} 0 0
[junit4:junit4] 2> 270505 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1435252863816171520)]} 0 5
[junit4:junit4] 2> 270509 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1435252863825608704)]} 0 1
[junit4:junit4] 2> 270516 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1435252863829803008)]} 0 1
[junit4:junit4] 2> 270517 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1435252863829803008)]} 0 5
[junit4:junit4] 2> 270521 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1435252863838191616)]} 0 1
[junit4:junit4] 2> 270531 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1435252863845531648)]} 0 0
[junit4:junit4] 2> 270532 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1435252863845531648)]} 0 5
[junit4:junit4] 2> 270533 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39]} 0 9
[junit4:junit4] 2> 270537 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1435252863854968832)]} 0 1
[junit4:junit4] 2> 270545 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1435252863859163136)]} 0 1
[junit4:junit4] 2> 270546 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1435252863859163136)]} 0 5
[junit4:junit4] 2> 270550 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1435252863867551744)]} 0 1
[junit4:junit4] 2> 270560 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1435252863875940352)]} 0 0
[junit4:junit4] 2> 270561 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1435252863875940352)]} 0 5
[junit4:junit4] 2> 270562 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41]} 0 8
[junit4:junit4] 2> 270567 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1435252863886426112)]} 0 1
[junit4:junit4] 2> 270576 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1435252863890620416)]} 0 1
[junit4:junit4] 2> 270577 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1435252863890620416)]} 0 6
[junit4:junit4] 2> 270582 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1435252863902154752)]} 0 1
[junit4:junit4] 2> 270594 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1435252863910543360)]} 0 0
[junit4:junit4] 2> 270595 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!43 (1435252863910543360)]} 0 5
[junit4:junit4] 2> 270597 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43]} 0 11
[junit4:junit4] 2> 270601 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1435252863922077696)]} 0 0
[junit4:junit4] 2> 270615 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1435252863931514880)]} 0 1
[junit4:junit4] 2> 270616 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1435252863931514880)]} 0 6
[junit4:junit4] 2> 270617 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44]} 0 11
[junit4:junit4] 2> 270623 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1435252863944097792)]} 0 1
[junit4:junit4] 2> 270632 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1435252863949340672)]} 0 1
[junit4:junit4] 2> 270633 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1435252863949340672)]} 0 6
[junit4:junit4] 2> 270637 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1435252863959826432)]} 0 1
[junit4:junit4] 2> 270645 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1435252863964020736)]} 0 0
[junit4:junit4] 2> 270646 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1435252863964020736)]} 0 5
[junit4:junit4] 2> 270650 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1435252863973457920)]} 0 0
[junit4:junit4] 2> 270659 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1435252863977652224)]} 0 1
[junit4:junit4] 2> 270660 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1435252863977652224)]} 0 7
[junit4:junit4] 2> 270664 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1435252863988137984)]} 0 0
[junit4:junit4] 2> 270674 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1435252863993380864)]} 0 1
[junit4:junit4] 2> 270675 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1435252863993380864)]} 0 6
[junit4:junit4] 2> 270681 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1435252864004915200)]} 0 1
[junit4:junit4] 2> 270694 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1435252864014352384)]} 0 1
[junit4:junit4] 2> 270695 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1435252864014352384)]} 0 6
[junit4:junit4] 2> 270696 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49]} 0 11
[junit4:junit4] 2> 270700 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1435252864025886720)]} 0 1
[junit4:junit4] 2> 270711 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1435252864033226752)]} 0 1
[junit4:junit4] 2> 270712 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!50 (1435252864033226752)]} 0 6
[junit4:junit4] 2> 270713 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50]} 0 10
[junit4:junit4] 2> 270717 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1435252864043712512)]} 0 1
[junit4:junit4] 2> 270727 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1435252864051052544)]} 0 0
[junit4:junit4] 2> 270728 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!51 (1435252864051052544)]} 0 5
[junit4:junit4] 2> 270729 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51]} 0 9
[junit4:junit4] 2> 270733 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1435252864060489728)]} 0 1
[junit4:junit4] 2> 270742 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1435252864064684032)]} 0 1
[junit4:junit4] 2> 270743 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1435252864064684032)]} 0 7
[junit4:junit4] 2> 270747 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1435252864075169792)]} 0 0
[junit4:junit4] 2> 270756 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1435252864080412672)]} 0 0
[junit4:junit4] 2> 270757 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1435252864080412672)]} 0 5
[junit4:junit4] 2> 270761 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1435252864089849856)]} 0 1
[junit4:junit4] 2> 270770 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1435252864094044160)]} 0 1
[junit4:junit4] 2> 270771 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1435252864094044160)]} 0 7
[junit4:junit4] 2> 270775 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1435252864104529920)]} 0 0
[junit4:junit4] 2> 270788 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1435252864112918528)]} 0 1
[junit4:junit4] 2> 270789 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1435252864112918528)]} 0 6
[junit4:junit4] 2> 270790 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 11
[junit4:junit4] 2> 270794 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1435252864124452864)]} 0 0
[junit4:junit4] 2> 270804 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1435252864129695744)]} 0 1
[junit4:junit4] 2> 270805 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1435252864129695744)]} 0 6
[junit4:junit4] 2> 270810 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1435252864140181504)]} 0 1
[junit4:junit4] 2> 270822 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1435252864148570112)]} 0 1
[junit4:junit4] 2> 270823 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1435252864148570112)]} 0 6
[junit4:junit4] 2> 270824 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57]} 0 11
[junit4:junit4] 2> 270828 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1435252864160104448)]} 0 0
[junit4:junit4] 2> 270840 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1435252864168493056)]} 0 1
[junit4:junit4] 2> 270841 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1435252864168493056)]} 0 5
[junit4:junit4] 2> 270842 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 9
[junit4:junit4] 2> 270846 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1435252864178978816)]} 0 0
[junit4:junit4] 2> 270856 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1435252864184221696)]} 0 1
[junit4:junit4] 2> 270857 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1435252864184221696)]} 0 6
[junit4:junit4] 2> 270862 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1435252864194707456)]} 0 1
[junit4:junit4] 2> 270870 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1435252864199950336)]} 0 1
[junit4:junit4] 2> 270871 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1435252864199950336)]} 0 6
[junit4:junit4] 2> 270875 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1435252864209387520)]} 0 1
[junit4:junit4] 2> 270886 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1435252864216727552)]} 0 0
[junit4:junit4] 2> 270887 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!61 (1435252864216727552)]} 0 5
[junit4:junit4] 2> 270888 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61]} 0 10
[junit4:junit4] 2> 270893 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1435252864228261888)]} 0 1
[junit4:junit4] 2> 270901 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1435252864232456192)]} 0 1
[junit4:junit4] 2> 270902 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1435252864232456192)]} 0 5
[junit4:junit4] 2> 270906 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1435252864241893376)]} 0 1
[junit4:junit4] 2> 270914 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1435252864246087680)]} 0 1
[junit4:junit4] 2> 270915 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1435252864246087680)]} 0 6
[junit4:junit4] 2> 270919 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1435252864255524864)]} 0 0
[junit4:junit4] 2> 270931 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1435252864262864896)]} 0 2
[junit4:junit4] 2> 270932 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!64 (1435252864262864896)]} 0 6
[junit4:junit4] 2> 270933 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64]} 0 11
[junit4:junit4] 2> 270936 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1435252864273350656)]} 0 1
[junit4:junit4] 2> 270943 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1435252864277544960)]} 0 1
[junit4:junit4] 2> 270944 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1435252864277544960)]} 0 5
[junit4:junit4] 2> 270948 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66 (1435252864285933568)]} 0 1
[junit4:junit4] 2> 270960 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1435252864293273600)]} 0 1
[junit4:junit4] 2> 270961 T642 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!66 (1435252864293273600)]} 0 6
[junit4:junit4] 2> 270962 T626 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66]} 0 11
[junit4:junit4] 2> 270966 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67 (1435252864304807936)]} 0 1
[junit4:junit4] 2> 270977 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!67 (1435252864312147968)]} 0 1
[junit4:junit4] 2> 270978 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!67 (1435252864312147968)]} 0 5
[junit4:junit4] 2> 270979 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67]} 0 10
[junit4:junit4] 2> 270984 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68 (1435252864323682304)]} 0 1
[junit4:junit4] 2> 270995 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!68 (1435252864331022336)]} 0 1
[junit4:junit4] 2> 270996 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!68 (1435252864331022336)]} 0 5
[junit4:junit4] 2> 270997 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68]} 0 9
[junit4:junit4] 2> 271002 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!69 (1435252864341508096)]} 0 1
[junit4:junit4] 2> 271011 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!69 (1435252864346750976)]} 0 1
[junit4:junit4] 2> 271012 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!69 (1435252864346750976)]} 0 7
[junit4:junit4] 2> 271016 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!70 (1435252864357236736)]} 0 1
[junit4:junit4] 2> 271027 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!70 (1435252864364576768)]} 0 1
[junit4:junit4] 2> 271028 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!70 (1435252864364576768)]} 0 6
[junit4:junit4] 2> 271029 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!70]} 0 10
[junit4:junit4] 2> 271033 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!71 (1435252864375062528)]} 0 1
[junit4:junit4] 2> 271043 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12233/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!71 (1435252864382402560)]} 0 1
[junit4:junit4] 2> 271044 T624 C13 P12233 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!71 (1435252864382402560)]} 0 5
[junit4:junit4] 2> 271045 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!71]} 0 9
[junit4:junit4] 2> 271049 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!72 (1435252864391839744)]} 0 1
[junit4:junit4] 2> 271057 T669 C14 P59526 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:12237/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!72 (1435252864396034048)]} 0 1
[junit4:junit4] 2> 271059 T640 C15 P12237 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!72 (1435252864396034048)]} 0 7
[junit4:junit4] 2> 271063 T600 C16 P12229 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!73 (1435252864406519808)]} 0 1
[junit4:junit4] 2> 271070 T654 C12 P38930 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update para
[...truncated too long message...]
.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:260)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 309108 T662 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 309108 T662 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> 309108 T662 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 309108 T662 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> 309109 T662 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 309109 T662 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 310153 T679 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:59526 couldn't connect to http://127.0.0.1:12237/collection1/, counting as success
[junit4:junit4] 2> 310160 T679 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59526 DONE. sync succeeded
[junit4:junit4] 2> 310160 T679 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 310161 T679 oasc.ShardLeaderElectionContext.rejoinLeaderElection Not rejoining election because CoreContainer is shutdown
[junit4:junit4] 2> 310161 T679 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@42858d1e
[junit4:junit4] 2> 310175 T679 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=10,adds=10,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=52,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 310176 T679 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 310176 T679 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 310176 T679 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 310180 T679 C14 P59526 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2dacdb61 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fc55091),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2dacdb61 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2fc55091),segFN=segments_5,generation=5}
[junit4:junit4] 2> 310180 T679 C14 P59526 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 310202 T679 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 310203 T679 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 310203 T679 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4;done=false>>]
[junit4:junit4] 2> 310203 T679 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4
[junit4:junit4] 2> 310204 T679 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index;done=false>>]
[junit4:junit4] 2> 310204 T679 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368763760187/jetty4/index
[junit4:junit4] 2> 310204 T679 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 310205 T679 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> 310205 T679 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 310205 T679 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=MockRandom), _version_=PostingsFormat(name=Direct)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=ar_IQ, timezone=America/Ojinaga
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_17 (64-bit)/cpus=16,threads=3,free=147982952,total=393216000
[junit4:junit4] 2> NOTE: All tests run in this JVM: [PrimUtilsTest, DocumentBuilderTest, QueryEqualityTest, TestPluginEnable, UpdateRequestProcessorFactoryTest, TestQuerySenderListener, QueryElevationComponentTest, OverseerTest, FastVectorHighlighterTest, DateFieldTest, TestSchemaResource, TestRandomDVFaceting, ShardSplitTest]
[junit4:junit4] Completed on J0 in 74.12s, 1 test, 1 error <<< FAILURES!
[...truncated 749 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:377: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:357: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:1240: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:884: There were test failures: 295 suites, 1231 tests, 1 error, 27 ignored (8 assumptions)
Total time: 52 minutes 55 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure