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/16 17:16:05 UTC
[JENKINS] Lucene-Solr-Tests-trunk-java7 - Build # 3990 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-java7/3990/
1 tests failed.
FAILED: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:63091/abv 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:63091/abv returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([9CD91E937801BA2A:1D3F908B0F5EDA16]: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 10039 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 1541641 T3987 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /abv/
[junit4:junit4] 2> 1541649 T3987 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-1368717276675
[junit4:junit4] 2> 1541651 T3987 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1541653 T3988 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1541753 T3987 oasc.ZkTestServer.run start zk server on port:63084
[junit4:junit4] 2> 1541754 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1541788 T3994 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6c325e76 name:ZooKeeperConnection Watcher:127.0.0.1:63084 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1541789 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1541790 T3987 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1541796 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1541799 T3996 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3cf65708 name:ZooKeeperConnection Watcher:127.0.0.1:63084/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1541800 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1541800 T3987 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1541811 T3987 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1541815 T3987 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1541818 T3987 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1541824 T3987 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> 1541825 T3987 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1541839 T3987 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> 1541841 T3987 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1541946 T3987 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> 1541947 T3987 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1541951 T3987 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> 1541952 T3987 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1541957 T3987 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> 1541958 T3987 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1541963 T3987 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> 1541964 T3987 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1541968 T3987 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> 1541968 T3987 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1541972 T3987 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> 1541973 T3987 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1541976 T3987 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> 1541977 T3987 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1542200 T3987 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1542206 T3987 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63087
[junit4:junit4] 2> 1542207 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1542208 T3987 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1542208 T3987 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-1368717277005
[junit4:junit4] 2> 1542209 T3987 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-1368717277005/solr.xml
[junit4:junit4] 2> 1542209 T3987 oasc.CoreContainer.<init> New CoreContainer 1308049912
[junit4:junit4] 2> 1542210 T3987 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-1368717277005/'
[junit4:junit4] 2> 1542210 T3987 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-1368717277005/'
[junit4:junit4] 2> 1542361 T3987 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1542362 T3987 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1542363 T3987 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1542363 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1542364 T3987 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1542364 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1542365 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1542366 T3987 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1542366 T3987 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1542367 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1542389 T3987 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1542391 T3987 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63084/solr
[junit4:junit4] 2> 1542391 T3987 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1542392 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1542395 T4007 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@670c437 name:ZooKeeperConnection Watcher:127.0.0.1:63084 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1542397 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1542399 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1542413 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1542416 T4009 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2da776d4 name:ZooKeeperConnection Watcher:127.0.0.1:63084/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1542416 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1542419 T3987 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1542429 T3987 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1542434 T3987 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1542436 T3987 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63087_abv
[junit4:junit4] 2> 1542443 T3987 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63087_abv
[junit4:junit4] 2> 1542446 T3987 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1542460 T3987 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1542463 T3987 oasc.Overseer.start Overseer (id=89700255444697091-127.0.0.1:63087_abv-n_0000000000) starting
[junit4:junit4] 2> 1542476 T3987 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1542485 T4011 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1542486 T3987 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1542489 T3987 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1542496 T3987 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1542506 T4012 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-1368717277005/collection1
[junit4:junit4] 2> 1542506 T4012 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1542506 T4010 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1542507 T4012 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1542507 T4012 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1542509 T4012 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-1368717277005/collection1/'
[junit4:junit4] 2> 1542510 T4012 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-1368717277005/collection1/lib/README' to classloader
[junit4:junit4] 2> 1542511 T4012 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-1368717277005/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1542573 T4012 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1542671 T4012 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1542772 T4012 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1542787 T4012 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1543407 T4012 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1543410 T4012 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1543412 T4012 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1543416 T4012 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1543432 T4012 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1543433 T4012 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-1368717277005/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/control/data/
[junit4:junit4] 2> 1543433 T4012 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1aa37c24
[junit4:junit4] 2> 1543434 T4012 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1543434 T4012 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/control/data
[junit4:junit4] 2> 1543435 T4012 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368717276674/control/data/index/
[junit4:junit4] 2> 1543435 T4012 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368717276674/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1543435 T4012 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/control/data/index
[junit4:junit4] 2> 1543438 T4012 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c41056c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6c94588b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1543438 T4012 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1543440 T4012 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1543440 T4012 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1543441 T4012 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1543442 T4012 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1543442 T4012 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1543442 T4012 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1543442 T4012 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1543443 T4012 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1543443 T4012 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1543452 T4012 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1543456 T4012 oass.SolrIndexSearcher.<init> Opening Searcher@76e26797 main
[junit4:junit4] 2> 1543456 T4012 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/control/data/tlog
[junit4:junit4] 2> 1543457 T4012 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1543458 T4012 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1543460 T4013 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@76e26797 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1543462 T4012 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1543463 T4012 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1544016 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1544017 T4010 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:63087_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63087/abv"}
[junit4:junit4] 2> 1544018 T4010 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1544018 T4010 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1544032 T4009 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> 1544466 T4012 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1544466 T4012 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63087/abv collection:control_collection shard:shard1
[junit4:junit4] 2> 1544467 T4012 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1544486 T4012 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1544488 T4012 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1544489 T4012 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1544489 T4012 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:63087/abv/collection1/
[junit4:junit4] 2> 1544489 T4012 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1544490 T4012 oasc.SyncStrategy.syncToMe http://127.0.0.1:63087/abv/collection1/ has no replicas
[junit4:junit4] 2> 1544490 T4012 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:63087/abv/collection1/
[junit4:junit4] 2> 1544490 T4012 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1545537 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1545577 T4009 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> 1545620 T4012 oasc.ZkController.register We are http://127.0.0.1:63087/abv/collection1/ and leader is http://127.0.0.1:63087/abv/collection1/
[junit4:junit4] 2> 1545620 T4012 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63087/abv
[junit4:junit4] 2> 1545621 T4012 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1545621 T4012 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1545621 T4012 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1545627 T4012 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1545628 T3987 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> 1545629 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1545629 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1545648 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1545650 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1545653 T4016 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@364dcecb name:ZooKeeperConnection Watcher:127.0.0.1:63084/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1545654 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1545655 T3987 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1545657 T3987 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1545890 T3987 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1545894 T3987 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:63091
[junit4:junit4] 2> 1545895 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1545896 T3987 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1545897 T3987 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-1368717280682
[junit4:junit4] 2> 1545897 T3987 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-1368717280682/solr.xml
[junit4:junit4] 2> 1545898 T3987 oasc.CoreContainer.<init> New CoreContainer 2142960548
[junit4:junit4] 2> 1545899 T3987 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-1368717280682/'
[junit4:junit4] 2> 1545900 T3987 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-1368717280682/'
[junit4:junit4] 2> 1546051 T3987 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1546052 T3987 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1546053 T3987 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1546053 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1546054 T3987 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1546054 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1546055 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1546056 T3987 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1546056 T3987 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1546057 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1546077 T3987 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1546078 T3987 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63084/solr
[junit4:junit4] 2> 1546079 T3987 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1546080 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1546110 T4027 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4f8149f0 name:ZooKeeperConnection Watcher:127.0.0.1:63084 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1546111 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1546125 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1546137 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1546140 T4029 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@61c7edce name:ZooKeeperConnection Watcher:127.0.0.1:63084/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1546140 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1546152 T3987 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1547084 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1547085 T4010 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:63087_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63087/abv"}
[junit4:junit4] 2> 1547100 T4009 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> 1547100 T4029 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> 1547100 T4016 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> 1547156 T3987 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:63091_abv
[junit4:junit4] 2> 1547160 T3987 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:63091_abv
[junit4:junit4] 2> 1547163 T4016 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> 1547163 T4009 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> 1547163 T4029 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> 1547165 T4016 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1547165 T4009 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1547167 T4029 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1547174 T4030 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-1368717280682/collection1
[junit4:junit4] 2> 1547175 T4030 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1547176 T4030 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1547176 T4030 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1547178 T4030 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-1368717280682/collection1/'
[junit4:junit4] 2> 1547180 T4030 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-1368717280682/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1547180 T4030 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-1368717280682/collection1/lib/README' to classloader
[junit4:junit4] 2> 1547244 T4030 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1547332 T4030 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1547434 T4030 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1547449 T4030 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1548047 T4030 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1548051 T4030 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1548054 T4030 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1548059 T4030 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1548084 T4030 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1548084 T4030 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-1368717280682/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty1/
[junit4:junit4] 2> 1548085 T4030 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1aa37c24
[junit4:junit4] 2> 1548085 T4030 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1548086 T4030 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty1
[junit4:junit4] 2> 1548086 T4030 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty1/index/
[junit4:junit4] 2> 1548087 T4030 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1548089 T4030 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty1/index
[junit4:junit4] 2> 1548092 T4030 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1201a3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ab338ec),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1548092 T4030 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1548095 T4030 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1548096 T4030 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1548097 T4030 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1548097 T4030 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1548098 T4030 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1548098 T4030 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1548099 T4030 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1548100 T4030 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1548100 T4030 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1548114 T4030 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1548121 T4030 oass.SolrIndexSearcher.<init> Opening Searcher@470c2c06 main
[junit4:junit4] 2> 1548121 T4030 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty1/tlog
[junit4:junit4] 2> 1548122 T4030 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1548123 T4030 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1548128 T4031 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@470c2c06 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1548132 T4030 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1548133 T4030 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1548608 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1548609 T4010 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:63091_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63091/abv"}
[junit4:junit4] 2> 1548610 T4010 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1548610 T4010 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1548625 T4029 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> 1548625 T4009 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> 1548625 T4016 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> 1549136 T4030 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1549136 T4030 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:63091/abv collection:collection1 shard:shard1
[junit4:junit4] 2> 1549137 T4030 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1549157 T4030 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1549160 T4030 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1549160 T4030 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1549161 T4030 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:63091/abv/collection1/
[junit4:junit4] 2> 1549161 T4030 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1549161 T4030 oasc.SyncStrategy.syncToMe http://127.0.0.1:63091/abv/collection1/ has no replicas
[junit4:junit4] 2> 1549162 T4030 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:63091/abv/collection1/
[junit4:junit4] 2> 1549162 T4030 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1550130 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1550151 T4016 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> 1550151 T4009 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> 1550151 T4029 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> 1550189 T4030 oasc.ZkController.register We are http://127.0.0.1:63091/abv/collection1/ and leader is http://127.0.0.1:63091/abv/collection1/
[junit4:junit4] 2> 1550189 T4030 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:63091/abv
[junit4:junit4] 2> 1550190 T4030 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1550190 T4030 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1550191 T4030 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1550195 T4030 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1550196 T3987 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> 1550197 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1550198 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1550456 T3987 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1550461 T3987 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:60298
[junit4:junit4] 2> 1550461 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1550462 T3987 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1550463 T3987 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-1368717285241
[junit4:junit4] 2> 1550463 T3987 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-1368717285241/solr.xml
[junit4:junit4] 2> 1550464 T3987 oasc.CoreContainer.<init> New CoreContainer 2104236251
[junit4:junit4] 2> 1550464 T3987 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-1368717285241/'
[junit4:junit4] 2> 1550465 T3987 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-1368717285241/'
[junit4:junit4] 2> 1550587 T3987 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1550588 T3987 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1550589 T3987 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1550589 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1550590 T3987 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1550590 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1550591 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1550591 T3987 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1550592 T3987 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1550593 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1550609 T3987 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1550610 T3987 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63084/solr
[junit4:junit4] 2> 1550611 T3987 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1550612 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1550620 T4043 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3ad5f0e0 name:ZooKeeperConnection Watcher:127.0.0.1:63084 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1550621 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1550634 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1550651 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1550654 T4045 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fdc4e1f name:ZooKeeperConnection Watcher:127.0.0.1:63084/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1550654 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1550666 T3987 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1551663 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1551670 T3987 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60298_abv
[junit4:junit4] 2> 1551670 T4010 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:63091_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:63091/abv"}
[junit4:junit4] 2> 1551672 T3987 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60298_abv
[junit4:junit4] 2> 1551689 T4016 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> 1551690 T4029 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> 1551690 T4045 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1551689 T4009 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> 1551691 T4045 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> 1551693 T4016 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1551694 T4016 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> 1551703 T4029 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1551703 T4029 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> 1551709 T4046 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-1368717285241/collection1
[junit4:junit4] 2> 1551709 T4046 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1551710 T4009 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1551710 T4009 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> 1551711 T4046 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1551711 T4046 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1551712 T4046 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-1368717285241/collection1/'
[junit4:junit4] 2> 1551714 T4046 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-1368717285241/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1551715 T4046 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-1368717285241/collection1/lib/README' to classloader
[junit4:junit4] 2> 1551773 T4046 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1551870 T4046 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1551971 T4046 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1551990 T4046 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1552688 T4046 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1552693 T4046 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1552696 T4046 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1552702 T4046 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1552747 T4046 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1552747 T4046 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-1368717285241/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty2/
[junit4:junit4] 2> 1552748 T4046 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1aa37c24
[junit4:junit4] 2> 1552749 T4046 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1552749 T4046 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty2
[junit4:junit4] 2> 1552750 T4046 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty2/index/
[junit4:junit4] 2> 1552750 T4046 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1552752 T4046 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty2/index
[junit4:junit4] 2> 1552755 T4046 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8e9761b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d482346),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1552755 T4046 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1552759 T4046 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1552759 T4046 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1552760 T4046 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1552761 T4046 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1552762 T4046 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1552762 T4046 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1552763 T4046 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1552763 T4046 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1552764 T4046 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1552777 T4046 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1552785 T4046 oass.SolrIndexSearcher.<init> Opening Searcher@5adaf357 main
[junit4:junit4] 2> 1552785 T4046 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty2/tlog
[junit4:junit4] 2> 1552786 T4046 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1552787 T4046 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1552792 T4047 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5adaf357 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1552795 T4046 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1552795 T4046 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1553205 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1553207 T4010 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:60298_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60298/abv"}
[junit4:junit4] 2> 1553207 T4010 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1553207 T4010 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1553223 T4009 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> 1553223 T4016 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> 1553223 T4045 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> 1553223 T4029 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> 1553798 T4046 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1553798 T4046 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60298/abv collection:collection1 shard:shard2
[junit4:junit4] 2> 1553799 T4046 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1553817 T4046 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1553825 T4046 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1553826 T4046 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1553826 T4046 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60298/abv/collection1/
[junit4:junit4] 2> 1553826 T4046 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1553827 T4046 oasc.SyncStrategy.syncToMe http://127.0.0.1:60298/abv/collection1/ has no replicas
[junit4:junit4] 2> 1553827 T4046 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60298/abv/collection1/
[junit4:junit4] 2> 1553827 T4046 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1554727 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1554747 T4016 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> 1554747 T4045 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> 1554747 T4009 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> 1554747 T4029 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> 1554751 T4046 oasc.ZkController.register We are http://127.0.0.1:60298/abv/collection1/ and leader is http://127.0.0.1:60298/abv/collection1/
[junit4:junit4] 2> 1554751 T4046 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60298/abv
[junit4:junit4] 2> 1554751 T4046 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1554752 T4046 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1554752 T4046 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1554754 T4046 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1554755 T3987 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> 1554756 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1554757 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1555007 T3987 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1555011 T3987 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:57171
[junit4:junit4] 2> 1555012 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1555012 T3987 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1555013 T3987 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-1368717289799
[junit4:junit4] 2> 1555014 T3987 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-1368717289799/solr.xml
[junit4:junit4] 2> 1555014 T3987 oasc.CoreContainer.<init> New CoreContainer 394565656
[junit4:junit4] 2> 1555015 T3987 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-1368717289799/'
[junit4:junit4] 2> 1555015 T3987 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-1368717289799/'
[junit4:junit4] 2> 1555150 T3987 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1555151 T3987 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1555151 T3987 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1555152 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1555152 T3987 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1555153 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1555153 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1555154 T3987 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1555154 T3987 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1555155 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1555171 T3987 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1555172 T3987 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63084/solr
[junit4:junit4] 2> 1555172 T3987 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1555174 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1555177 T4059 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@744dc845 name:ZooKeeperConnection Watcher:127.0.0.1:63084 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1555179 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1555192 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1555205 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1555208 T4061 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@54a02fa7 name:ZooKeeperConnection Watcher:127.0.0.1:63084/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1555208 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1555220 T3987 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1556224 T3987 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57171_abv
[junit4:junit4] 2> 1556258 T3987 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57171_abv
[junit4:junit4] 2> 1556259 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1556260 T4010 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:60298_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60298/abv"}
[junit4:junit4] 2> 1556262 T4016 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> 1556262 T4009 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> 1556262 T4029 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> 1556279 T4045 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556279 T4061 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556280 T4045 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> 1556282 T4016 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556282 T4029 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556292 T4016 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> 1556292 T4061 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> 1556292 T4029 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> 1556292 T4045 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> 1556297 T4009 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1556298 T4009 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> 1556300 T4062 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-1368717289799/collection1
[junit4:junit4] 2> 1556300 T4062 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1556301 T4062 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1556301 T4062 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1556303 T4062 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-1368717289799/collection1/'
[junit4:junit4] 2> 1556305 T4062 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-1368717289799/collection1/lib/README' to classloader
[junit4:junit4] 2> 1556306 T4062 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-1368717289799/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1556370 T4062 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1556466 T4062 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1556567 T4062 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1556578 T4062 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1557192 T4062 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1557196 T4062 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1557199 T4062 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1557206 T4062 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1557231 T4062 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1557232 T4062 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-1368717289799/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/
[junit4:junit4] 2> 1557232 T4062 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1aa37c24
[junit4:junit4] 2> 1557233 T4062 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1557234 T4062 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3
[junit4:junit4] 2> 1557234 T4062 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/index/
[junit4:junit4] 2> 1557234 T4062 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1557236 T4062 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/index
[junit4:junit4] 2> 1557239 T4062 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@23cbc08c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c3474b8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1557239 T4062 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1557243 T4062 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1557243 T4062 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1557244 T4062 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1557245 T4062 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1557245 T4062 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1557246 T4062 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1557246 T4062 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1557247 T4062 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1557247 T4062 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1557270 T4062 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1557277 T4062 oass.SolrIndexSearcher.<init> Opening Searcher@8cfa084 main
[junit4:junit4] 2> 1557278 T4062 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/tlog
[junit4:junit4] 2> 1557279 T4062 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1557279 T4062 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1557285 T4063 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8cfa084 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1557288 T4062 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1557288 T4062 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1557798 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1557800 T4010 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:57171_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57171/abv"}
[junit4:junit4] 2> 1557800 T4010 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1557801 T4010 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1557816 T4016 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> 1557816 T4029 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> 1557816 T4061 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> 1557816 T4009 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> 1557816 T4045 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> 1558297 T4062 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1558297 T4062 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57171/abv collection:collection1 shard:shard1
[junit4:junit4] 2> 1558301 T4062 oasc.ZkController.register We are http://127.0.0.1:57171/abv/collection1/ and leader is http://127.0.0.1:63091/abv/collection1/
[junit4:junit4] 2> 1558301 T4062 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57171/abv
[junit4:junit4] 2> 1558301 T4062 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1558302 T4062 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C170 name=collection1 org.apache.solr.core.SolrCore@4bb0a5d7 url=http://127.0.0.1:57171/abv/collection1 node=127.0.0.1:57171_abv C170_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:57171_abv, base_url=http://127.0.0.1:57171/abv}
[junit4:junit4] 2> 1558302 T4064 C170 P57171 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1558305 T4064 C170 P57171 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1558305 T4062 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1558305 T4064 C170 P57171 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1558306 T4064 C170 P57171 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1558307 T3987 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> 1558308 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1558308 T4064 C170 P57171 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1558308 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1558331 T4019 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1558585 T3987 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1558588 T3987 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12593
[junit4:junit4] 2> 1558590 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1558590 T3987 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1558591 T3987 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-1368717293352
[junit4:junit4] 2> 1558592 T3987 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-1368717293352/solr.xml
[junit4:junit4] 2> 1558592 T3987 oasc.CoreContainer.<init> New CoreContainer 1969081914
[junit4:junit4] 2> 1558593 T3987 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-1368717293352/'
[junit4:junit4] 2> 1558594 T3987 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-1368717293352/'
[junit4:junit4] 2> 1558734 T3987 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1558735 T3987 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1558735 T3987 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1558736 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1558736 T3987 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1558737 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1558738 T3987 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1558738 T3987 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1558739 T3987 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1558740 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1558755 T3987 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1558757 T3987 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:63084/solr
[junit4:junit4] 2> 1558758 T3987 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1558759 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1558764 T4076 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@72723beb name:ZooKeeperConnection Watcher:127.0.0.1:63084 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1558765 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1558779 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1558791 T3987 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1558793 T4078 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@147d0a8a name:ZooKeeperConnection Watcher:127.0.0.1:63084/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1558794 T3987 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1558799 T3987 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1559322 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1559324 T4010 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:57171_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57171/abv"}
[junit4:junit4] 2> 1559329 T4016 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> 1559329 T4078 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> 1559329 T4061 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> 1559329 T4045 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> 1559329 T4029 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> 1559329 T4009 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> 1559803 T3987 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12593_abv
[junit4:junit4] 2> 1559806 T3987 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12593_abv
[junit4:junit4] 2> 1559809 T4016 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> 1559809 T4045 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1559809 T4009 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> 1559809 T4029 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> 1559810 T4045 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> 1559810 T4078 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1559809 T4061 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1559811 T4078 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> 1559811 T4061 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> 1559818 T4016 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1559819 T4009 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1559819 T4029 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1559826 T4079 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-1368717293352/collection1
[junit4:junit4] 2> 1559826 T4079 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1559827 T4079 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1559828 T4079 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1559830 T4079 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-1368717293352/collection1/'
[junit4:junit4] 2> 1559832 T4079 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-1368717293352/collection1/lib/README' to classloader
[junit4:junit4] 2> 1559832 T4079 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-1368717293352/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1559893 T4079 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1559990 T4079 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1560092 T4079 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1560103 T4079 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1560334 T4019 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1560335 T4019 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:57171_abv&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2004
[junit4:junit4] 2> 1560725 T4079 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1560729 T4079 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1560731 T4079 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1560738 T4079 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1560770 T4079 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1560771 T4079 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-1368717293352/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/
[junit4:junit4] 2> 1560772 T4079 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1aa37c24
[junit4:junit4] 2> 1560772 T4079 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1560773 T4079 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4
[junit4:junit4] 2> 1560774 T4079 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index/
[junit4:junit4] 2> 1560774 T4079 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1560776 T4079 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index
[junit4:junit4] 2> 1560779 T4079 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39baf2c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7edf2bbf),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1560780 T4079 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1560784 T4079 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1560784 T4079 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1560785 T4079 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1560786 T4079 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1560787 T4079 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1560787 T4079 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1560788 T4079 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1560788 T4079 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1560789 T4079 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1560806 T4079 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1560814 T4079 oass.SolrIndexSearcher.<init> Opening Searcher@7c08d54b main
[junit4:junit4] 2> 1560814 T4079 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/tlog
[junit4:junit4] 2> 1560815 T4079 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1560816 T4079 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1560821 T4080 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7c08d54b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1560824 T4079 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1560825 T4079 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1560840 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1560841 T4010 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:12593_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12593/abv"}
[junit4:junit4] 2> 1560841 T4010 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1560842 T4010 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1560857 T4016 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> 1560857 T4061 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> 1560857 T4029 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> 1560857 T4045 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> 1560858 T4078 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> 1560857 T4009 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> 1561828 T4079 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1561828 T4079 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12593/abv collection:collection1 shard:shard2
[junit4:junit4] 2> 1561860 T4079 oasc.ZkController.register We are http://127.0.0.1:12593/abv/collection1/ and leader is http://127.0.0.1:60298/abv/collection1/
[junit4:junit4] 2> 1561861 T4079 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12593/abv
[junit4:junit4] 2> 1561861 T4079 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1561861 T4079 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C171 name=collection1 org.apache.solr.core.SolrCore@3082ba5b url=http://127.0.0.1:12593/abv/collection1 node=127.0.0.1:12593_abv C171_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:12593_abv, base_url=http://127.0.0.1:12593/abv}
[junit4:junit4] 2> 1561862 T4081 C171 P12593 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1561863 T4079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1561864 T4081 C171 P12593 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1561865 T4081 C171 P12593 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1561865 T4081 C171 P12593 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1561866 T3987 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> 1561867 T3987 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1561868 T3987 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1561869 T4081 C171 P12593 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1561887 T3987 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1561888 T4035 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1561888 T3987 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1561889 T3987 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1561890 T3987 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C170_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57171_abv, base_url=http://127.0.0.1:57171/abv}
[junit4:junit4] 2> 1562337 T4064 C170 P57171 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:63091/abv/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1562337 T4064 C170 P57171 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57171/abv START replicas=[http://127.0.0.1:63091/abv/collection1/] nUpdates=100
[junit4:junit4] 2> 1562338 T4064 C170 P57171 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1562339 T4064 C170 P57171 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1562339 T4064 C170 P57171 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1562339 T4064 C170 P57171 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1562339 T4064 C170 P57171 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1562340 T4064 C170 P57171 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:63091/abv/collection1/. core=collection1
[junit4:junit4] 2> 1562340 T4064 C170 P57171 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C172 name=collection1 org.apache.solr.core.SolrCore@707caaf1 url=http://127.0.0.1:63091/abv/collection1 node=127.0.0.1:63091_abv C172_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:63091_abv, base_url=http://127.0.0.1:63091/abv, leader=true}
[junit4:junit4] 2> 1562351 T4020 C172 P63091 oasc.SolrCore.execute [collection1] webapp=/abv path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1562353 T4021 C172 P63091 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1562357 T4021 C172 P63091 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1201a3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ab338ec),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1562358 T4021 C172 P63091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1562359 T4021 C172 P63091 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1201a3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ab338ec),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1201a3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ab338ec),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1562360 T4021 C172 P63091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1562360 T4021 C172 P63091 oass.SolrIndexSearcher.<init> Opening Searcher@62ac9c1b realtime
[junit4:junit4] 2> 1562361 T4021 C172 P63091 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1562361 T4021 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 1562362 T4064 C170 P57171 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1562363 T4064 C170 P57171 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1562364 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1562366 T4022 C172 P63091 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1562366 T4010 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:12593_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12593/abv"}
[junit4:junit4] 2> 1562367 T4022 C172 P63091 oasc.SolrCore.execute [collection1] webapp=/abv path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=3
[junit4:junit4] 2> 1562368 T4064 C170 P57171 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1562368 T4064 C170 P57171 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1562369 T4064 C170 P57171 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1562372 T4022 C172 P63091 oasc.SolrCore.execute [collection1] webapp=/abv path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 1562373 T4064 C170 P57171 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1562375 T4064 C170 P57171 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/index.20130516101457397
[junit4:junit4] 2> 1562376 T4064 C170 P57171 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@67e4113 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e3aef2e) fullCopy=false
[junit4:junit4] 2> 1562379 T4022 C172 P63091 oasc.SolrCore.execute [collection1] webapp=/abv path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1562380 T4061 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> 1562380 T4029 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> 1562381 T4064 C170 P57171 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1562380 T4045 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> 1562380 T4016 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> 1562380 T4078 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> 1562380 T4009 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> 1562383 T4064 C170 P57171 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1562384 T4064 C170 P57171 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1562386 T4064 C170 P57171 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@23cbc08c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c3474b8),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@23cbc08c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c3474b8),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1562387 T4064 C170 P57171 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1562388 T4064 C170 P57171 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1562388 T4064 C170 P57171 oass.SolrIndexSearcher.<init> Opening Searcher@15fe1a83 main
[junit4:junit4] 2> 1562389 T4063 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15fe1a83 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1562390 T4064 C170 P57171 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/index.20130516101457397 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/index.20130516101457397;done=true>>]
[junit4:junit4] 2> 1562390 T4064 C170 P57171 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/index.20130516101457397
[junit4:junit4] 2> 1562391 T4064 C170 P57171 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty3/index.20130516101457397
[junit4:junit4] 2> 1562391 T4064 C170 P57171 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1562391 T4064 C170 P57171 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1562391 T4064 C170 P57171 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1562392 T4064 C170 P57171 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1562393 T4064 C170 P57171 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1562889 T4035 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1562889 T4035 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:12593_abv&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 1562892 T3987 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1563887 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1563888 T4010 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:57171_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57171/abv"}
[junit4:junit4] 2> 1563905 T4009 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> 1563905 T4045 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> 1563905 T3987 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1563905 T4016 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> 1563905 T4029 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> 1563905 T4061 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> 1563905 T4078 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> C171_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:12593_abv, base_url=http://127.0.0.1:12593/abv}
[junit4:junit4] 2> 1564891 T4081 C171 P12593 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:60298/abv/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1564891 T4081 C171 P12593 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:12593/abv START replicas=[http://127.0.0.1:60298/abv/collection1/] nUpdates=100
[junit4:junit4] 2> 1564892 T4081 C171 P12593 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1564892 T4081 C171 P12593 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1564892 T4081 C171 P12593 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1564893 T4081 C171 P12593 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1564893 T4081 C171 P12593 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1564893 T4081 C171 P12593 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:60298/abv/collection1/. core=collection1
[junit4:junit4] 2> 1564893 T4081 C171 P12593 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C173 name=collection1 org.apache.solr.core.SolrCore@3707a7c3 url=http://127.0.0.1:60298/abv/collection1 node=127.0.0.1:60298_abv C173_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:60298_abv, base_url=http://127.0.0.1:60298/abv, leader=true}
[junit4:junit4] 2> 1564905 T4036 C173 P60298 oasc.SolrCore.execute [collection1] webapp=/abv path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1564908 T3987 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1564910 T4037 C173 P60298 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1564914 T4037 C173 P60298 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8e9761b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d482346),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1564915 T4037 C173 P60298 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1564915 T4037 C173 P60298 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8e9761b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d482346),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8e9761b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d482346),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1564916 T4037 C173 P60298 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1564917 T4037 C173 P60298 oass.SolrIndexSearcher.<init> Opening Searcher@5c1a19bc realtime
[junit4:junit4] 2> 1564917 T4037 C173 P60298 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1564917 T4037 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 1564919 T4081 C171 P12593 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1564919 T4081 C171 P12593 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1564921 T4038 C173 P60298 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1564922 T4038 C173 P60298 oasc.SolrCore.execute [collection1] webapp=/abv path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1564922 T4081 C171 P12593 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1564923 T4081 C171 P12593 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1564923 T4081 C171 P12593 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1564925 T4038 C173 P60298 oasc.SolrCore.execute [collection1] webapp=/abv path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1564926 T4081 C171 P12593 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1564928 T4081 C171 P12593 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index.20130516101459951
[junit4:junit4] 2> 1564928 T4081 C171 P12593 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1d4d37a2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@52c6f602) fullCopy=false
[junit4:junit4] 2> 1564931 T4038 C173 P60298 oasc.SolrCore.execute [collection1] webapp=/abv path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1564934 T4081 C171 P12593 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1564935 T4081 C171 P12593 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1564935 T4081 C171 P12593 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1564938 T4081 C171 P12593 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39baf2c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7edf2bbf),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39baf2c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7edf2bbf),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1564939 T4081 C171 P12593 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1564939 T4081 C171 P12593 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1564940 T4081 C171 P12593 oass.SolrIndexSearcher.<init> Opening Searcher@50f292ac main
[junit4:junit4] 2> 1564942 T4080 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@50f292ac main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1564942 T4081 C171 P12593 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index.20130516101459951 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index.20130516101459951;done=true>>]
[junit4:junit4] 2> 1564943 T4081 C171 P12593 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index.20130516101459951
[junit4:junit4] 2> 1564943 T4081 C171 P12593 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index.20130516101459951
[junit4:junit4] 2> 1564943 T4081 C171 P12593 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1564943 T4081 C171 P12593 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1564944 T4081 C171 P12593 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1564944 T4081 C171 P12593 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1564946 T4081 C171 P12593 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1565411 T4010 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1565412 T4010 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:12593_abv",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12593/abv"}
[junit4:junit4] 2> 1565434 T4029 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> 1565434 T4078 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> 1565434 T4009 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> 1565434 T4016 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> 1565434 T4061 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> 1565434 T4045 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> 1565910 T3987 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1565912 T3987 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C174 name=collection1 org.apache.solr.core.SolrCore@7ab846d9 url=http://127.0.0.1:63087/abv/collection1 node=127.0.0.1:63087_abv C174_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:63087_abv, base_url=http://127.0.0.1:63087/abv, leader=true}
[junit4:junit4] 2> 1565921 T3999 C174 P63087 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1565925 T3999 C174 P63087 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c41056c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6c94588b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1565926 T3999 C174 P63087 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1565927 T3999 C174 P63087 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c41056c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6c94588b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4c41056c lockFactory=org.apache.lucene.store.NativeFSLockFactory@6c94588b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1565927 T3999 C174 P63087 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1565928 T3999 C174 P63087 oass.SolrIndexSearcher.<init> Opening Searcher@16b80b80 main
[junit4:junit4] 2> 1565929 T3999 C174 P63087 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1565930 T4013 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16b80b80 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1565931 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 1565944 T4039 C173 P60298 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1565946 T4039 C173 P60298 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8e9761b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d482346),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8e9761b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7d482346),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1565946 T4039 C173 P60298 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1565947 T4039 C173 P60298 oass.SolrIndexSearcher.<init> Opening Searcher@36365403 main
[junit4:junit4] 2> 1565948 T4039 C173 P60298 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1565949 T4047 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@36365403 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1565949 T4039 C173 P60298 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:63091/abv/collection1/, StdNode: http://127.0.0.1:57171/abv/collection1/, StdNode: http://127.0.0.1:12593/abv/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1565955 T4023 C172 P63091 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1565957 T4023 C172 P63091 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1201a3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ab338ec),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1201a3c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ab338ec),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1565957 T4023 C172 P63091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1565958 T4023 C172 P63091 oass.SolrIndexSearcher.<init> Opening Searcher@11738927 main
[junit4:junit4] 2> 1565959 T4023 C172 P63091 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1565960 T4031 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@11738927 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1565960 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> C170_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57171_abv, base_url=http://127.0.0.1:57171/abv}
[junit4:junit4] 2> 1565964 T4051 C170 P57171 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C171_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:12593_abv, base_url=http://127.0.0.1:12593/abv}
[junit4:junit4] 2> 1565964 T4068 C171 P12593 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1565966 T4051 C170 P57171 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@23cbc08c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c3474b8),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@23cbc08c lockFactory=org.apache.lucene.store.NativeFSLockFactory@7c3474b8),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1565966 T4068 C171 P12593 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39baf2c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7edf2bbf),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@39baf2c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7edf2bbf),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1565967 T4068 C171 P12593 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1565967 T4051 C170 P57171 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1565968 T4068 C171 P12593 oass.SolrIndexSearcher.<init> Opening Searcher@10566ec main
[junit4:junit4] 2> 1565969 T4051 C170 P57171 oass.SolrIndexSearcher.<init> Opening Searcher@45083c0d main
[junit4:junit4] 2> 1565969 T4068 C171 P12593 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1565970 T4051 C170 P57171 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1565970 T4080 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10566ec main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1565971 T4063 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@45083c0d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1565971 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv 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> 1565971 T4051 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 1565973 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 29
[junit4:junit4] 2> 1565974 T3987 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1565978 T4024 C172 P63091 oasc.SolrCore.execute [collection1] webapp=/abv path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 1565980 T4052 C170 P57171 oasc.SolrCore.execute [collection1] webapp=/abv path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1565982 T4040 C173 P60298 oasc.SolrCore.execute [collection1] webapp=/abv path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1565985 T4069 C171 P12593 oasc.SolrCore.execute [collection1] webapp=/abv path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 1567990 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435204114724159488)} 0 2
[junit4:junit4] 2> 1568010 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={update.distrib=FROMLEADER&_version_=-1435204114728353792&update.from=http://127.0.0.1:63091/abv/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435204114728353792)} 0 2
[junit4:junit4] 2> 1568010 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={update.distrib=FROMLEADER&_version_=-1435204114739888128&update.from=http://127.0.0.1:60298/abv/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435204114739888128)} 0 2
[junit4:junit4] 2> 1568011 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435204114739888128)} 0 7
[junit4:junit4] 2> 1568012 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435204114728353792)} 0 20
[junit4:junit4] 2> 1568016 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[a!0 (1435204114751422464)]} 0 1
[junit4:junit4] 2> 1568023 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1435204114755616768)]} 0 1
[junit4:junit4] 2> 1568024 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[a!0 (1435204114755616768)]} 0 5
[junit4:junit4] 2> 1568028 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[b!1 (1435204114764005376)]} 0 1
[junit4:junit4] 2> 1568035 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1435204114768199680)]} 0 1
[junit4:junit4] 2> 1568036 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[b!1 (1435204114768199680)]} 0 5
[junit4:junit4] 2> 1568040 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[c!2 (1435204114776588288)]} 0 1
[junit4:junit4] 2> 1568049 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1435204114782879744)]} 0 1
[junit4:junit4] 2> 1568050 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1435204114782879744)]} 0 5
[junit4:junit4] 2> 1568050 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[c!2]} 0 7
[junit4:junit4] 2> 1568054 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[d!3 (1435204114791268352)]} 0 1
[junit4:junit4] 2> 1568061 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1435204114795462656)]} 0 1
[junit4:junit4] 2> 1568061 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[d!3 (1435204114795462656)]} 0 4
[junit4:junit4] 2> 1568065 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[e!4 (1435204114802802688)]} 0 1
[junit4:junit4] 2> 1568072 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1435204114806996992)]} 0 1
[junit4:junit4] 2> 1568073 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[e!4 (1435204114806996992)]} 0 5
[junit4:junit4] 2> 1568077 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[f!5 (1435204114815385600)]} 0 1
[junit4:junit4] 2> 1568084 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1435204114819579904)]} 0 1
[junit4:junit4] 2> 1568085 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[f!5 (1435204114819579904)]} 0 5
[junit4:junit4] 2> 1568088 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[g!6 (1435204114826919936)]} 0 1
[junit4:junit4] 2> 1568097 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1435204114833211392)]} 0 1
[junit4:junit4] 2> 1568098 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1435204114833211392)]} 0 5
[junit4:junit4] 2> 1568098 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[g!6]} 0 7
[junit4:junit4] 2> 1568102 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[h!7 (1435204114841600000)]} 0 1
[junit4:junit4] 2> 1568109 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1435204114845794304)]} 0 1
[junit4:junit4] 2> 1568110 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[h!7 (1435204114845794304)]} 0 5
[junit4:junit4] 2> 1568114 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[i!8 (1435204114854182912)]} 0 1
[junit4:junit4] 2> 1568121 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1435204114858377216)]} 0 1
[junit4:junit4] 2> 1568122 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[i!8 (1435204114858377216)]} 0 5
[junit4:junit4] 2> 1568125 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[j!9 (1435204114865717248)]} 0 1
[junit4:junit4] 2> 1568135 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1435204114873057280)]} 0 1
[junit4:junit4] 2> 1568136 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1435204114873057280)]} 0 5
[junit4:junit4] 2> 1568136 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[j!9]} 0 8
[junit4:junit4] 2> 1568140 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[k!10 (1435204114881445888)]} 0 1
[junit4:junit4] 2> 1568147 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1435204114885640192)]} 0 1
[junit4:junit4] 2> 1568148 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[k!10 (1435204114885640192)]} 0 5
[junit4:junit4] 2> 1568151 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[l!11 (1435204114892980224)]} 0 1
[junit4:junit4] 2> 1568161 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1435204114900320256)]} 0 1
[junit4:junit4] 2> 1568161 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1435204114900320256)]} 0 4
[junit4:junit4] 2> 1568162 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[l!11]} 0 8
[junit4:junit4] 2> 1568166 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[m!12 (1435204114908708864)]} 0 1
[junit4:junit4] 2> 1568173 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1435204114913951744)]} 0 0
[junit4:junit4] 2> 1568174 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1435204114913951744)]} 0 4
[junit4:junit4] 2> 1568175 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[m!12]} 0 7
[junit4:junit4] 2> 1568178 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[n!13 (1435204114922340352)]} 0 0
[junit4:junit4] 2> 1568187 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1435204114928631808)]} 0 1
[junit4:junit4] 2> 1568188 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1435204114928631808)]} 0 5
[junit4:junit4] 2> 1568189 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[n!13]} 0 8
[junit4:junit4] 2> 1568193 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[o!14 (1435204114937020416)]} 0 1
[junit4:junit4] 2> 1568200 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1435204114941214720)]} 0 1
[junit4:junit4] 2> 1568201 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[o!14 (1435204114941214720)]} 0 5
[junit4:junit4] 2> 1568205 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[p!15 (1435204114949603328)]} 0 1
[junit4:junit4] 2> 1568212 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1435204114953797632)]} 0 1
[junit4:junit4] 2> 1568212 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[p!15 (1435204114953797632)]} 0 4
[junit4:junit4] 2> 1568217 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[q!16 (1435204114962186240)]} 0 1
[junit4:junit4] 2> 1568227 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1435204114969526272)]} 0 1
[junit4:junit4] 2> 1568227 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1435204114969526272)]} 0 4
[junit4:junit4] 2> 1568228 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[q!16]} 0 8
[junit4:junit4] 2> 1568232 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[r!17 (1435204114977914880)]} 0 1
[junit4:junit4] 2> 1568239 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1435204114982109184)]} 0 1
[junit4:junit4] 2> 1568239 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[r!17 (1435204114982109184)]} 0 4
[junit4:junit4] 2> 1568242 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[s!18 (1435204114989449216)]} 0 0
[junit4:junit4] 2> 1568251 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1435204114994692096)]} 0 1
[junit4:junit4] 2> 1568252 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1435204114994692096)]} 0 5
[junit4:junit4] 2> 1568253 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[s!18]} 0 8
[junit4:junit4] 2> 1568256 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[t!19 (1435204115003080704)]} 0 1
[junit4:junit4] 2> 1568262 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1435204115007275008)]} 0 0
[junit4:junit4] 2> 1568263 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[t!19 (1435204115007275008)]} 0 4
[junit4:junit4] 2> 1568267 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[u!20 (1435204115014615040)]} 0 1
[junit4:junit4] 2> 1568275 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1435204115019857920)]} 0 1
[junit4:junit4] 2> 1568275 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1435204115019857920)]} 0 4
[junit4:junit4] 2> 1568276 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[u!20]} 0 7
[junit4:junit4] 2> 1568280 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[v!21 (1435204115028246528)]} 0 1
[junit4:junit4] 2> 1568290 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1435204115035586560)]} 0 1
[junit4:junit4] 2> 1568291 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1435204115035586560)]} 0 5
[junit4:junit4] 2> 1568292 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[v!21]} 0 9
[junit4:junit4] 2> 1568296 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[w!22 (1435204115045023744)]} 0 1
[junit4:junit4] 2> 1568306 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1435204115052363776)]} 0 1
[junit4:junit4] 2> 1568307 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!22 (1435204115052363776)]} 0 5
[junit4:junit4] 2> 1568307 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[w!22]} 0 8
[junit4:junit4] 2> 1568311 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[x!23 (1435204115060752384)]} 0 1
[junit4:junit4] 2> 1568318 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1435204115064946688)]} 0 1
[junit4:junit4] 2> 1568319 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[x!23 (1435204115064946688)]} 0 5
[junit4:junit4] 2> 1568323 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[y!24 (1435204115073335296)]} 0 1
[junit4:junit4] 2> 1568330 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1435204115077529600)]} 0 1
[junit4:junit4] 2> 1568331 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[y!24 (1435204115077529600)]} 0 5
[junit4:junit4] 2> 1568335 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[z!25 (1435204115085918208)]} 0 1
[junit4:junit4] 2> 1568342 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1435204115090112512)]} 0 1
[junit4:junit4] 2> 1568342 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[z!25 (1435204115090112512)]} 0 4
[junit4:junit4] 2> 1568346 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[a!26 (1435204115097452544)]} 0 1
[junit4:junit4] 2> 1568355 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1435204115103744000)]} 0 1
[junit4:junit4] 2> 1568356 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1435204115103744000)]} 0 5
[junit4:junit4] 2> 1568356 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[a!26]} 0 8
[junit4:junit4] 2> 1568360 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[b!27 (1435204115112132608)]} 0 1
[junit4:junit4] 2> 1568366 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1435204115115278336)]} 0 1
[junit4:junit4] 2> 1568367 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[b!27 (1435204115115278336)]} 0 5
[junit4:junit4] 2> 1568371 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[c!28 (1435204115123666944)]} 0 1
[junit4:junit4] 2> 1568381 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1435204115131006976)]} 0 1
[junit4:junit4] 2> 1568382 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1435204115131006976)]} 0 5
[junit4:junit4] 2> 1568383 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[c!28]} 0 8
[junit4:junit4] 2> 1568387 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[d!29 (1435204115140444160)]} 0 1
[junit4:junit4] 2> 1568394 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1435204115144638464)]} 0 1
[junit4:junit4] 2> 1568394 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[d!29 (1435204115144638464)]} 0 4
[junit4:junit4] 2> 1568399 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[e!30 (1435204115153027072)]} 0 1
[junit4:junit4] 2> 1568405 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1435204115156172800)]} 0 1
[junit4:junit4] 2> 1568406 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[e!30 (1435204115156172800)]} 0 5
[junit4:junit4] 2> 1568409 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[f!31 (1435204115163512832)]} 0 1
[junit4:junit4] 2> 1568419 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1435204115170852864)]} 0 1
[junit4:junit4] 2> 1568420 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1435204115170852864)]} 0 5
[junit4:junit4] 2> 1568421 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[f!31]} 0 9
[junit4:junit4] 2> 1568424 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[g!32 (1435204115179241472)]} 0 1
[junit4:junit4] 2> 1568431 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1435204115183435776)]} 0 1
[junit4:junit4] 2> 1568431 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[g!32 (1435204115183435776)]} 0 4
[junit4:junit4] 2> 1568435 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[h!33 (1435204115190775808)]} 0 1
[junit4:junit4] 2> 1568444 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1435204115197067264)]} 0 1
[junit4:junit4] 2> 1568445 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!33 (1435204115197067264)]} 0 5
[junit4:junit4] 2> 1568446 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[h!33]} 0 9
[junit4:junit4] 2> 1568450 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[i!34 (1435204115206504448)]} 0 1
[junit4:junit4] 2> 1568457 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1435204115210698752)]} 0 1
[junit4:junit4] 2> 1568458 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[i!34 (1435204115210698752)]} 0 5
[junit4:junit4] 2> 1568461 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[j!35 (1435204115218038784)]} 0 1
[junit4:junit4] 2> 1568468 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1435204115222233088)]} 0 1
[junit4:junit4] 2> 1568468 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[j!35 (1435204115222233088)]} 0 4
[junit4:junit4] 2> 1568472 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[k!36 (1435204115229573120)]} 0 1
[junit4:junit4] 2> 1568481 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1435204115235864576)]} 0 1
[junit4:junit4] 2> 1568482 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1435204115235864576)]} 0 5
[junit4:junit4] 2> 1568483 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[k!36]} 0 8
[junit4:junit4] 2> 1568487 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[l!37 (1435204115246350336)]} 0 1
[junit4:junit4] 2> 1568494 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1435204115249496064)]} 0 1
[junit4:junit4] 2> 1568494 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[l!37 (1435204115249496064)]} 0 4
[junit4:junit4] 2> 1568497 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[m!38 (1435204115256836096)]} 0 0
[junit4:junit4] 2> 1568504 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1435204115259981824)]} 0 1
[junit4:junit4] 2> 1568505 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[m!38 (1435204115259981824)]} 0 5
[junit4:junit4] 2> 1568509 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[n!39 (1435204115268370432)]} 0 1
[junit4:junit4] 2> 1568519 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1435204115276759040)]} 0 1
[junit4:junit4] 2> 1568520 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1435204115276759040)]} 0 5
[junit4:junit4] 2> 1568521 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[n!39]} 0 9
[junit4:junit4] 2> 1568525 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[o!40 (1435204115285147648)]} 0 1
[junit4:junit4] 2> 1568531 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1435204115288293376)]} 0 1
[junit4:junit4] 2> 1568532 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[o!40 (1435204115288293376)]} 0 5
[junit4:junit4] 2> 1568536 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[p!41 (1435204115296681984)]} 0 1
[junit4:junit4] 2> 1568543 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1435204115300876288)]} 0 1
[junit4:junit4] 2> 1568544 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[p!41 (1435204115300876288)]} 0 5
[junit4:junit4] 2> 1568547 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[q!42 (1435204115308216320)]} 0 1
[junit4:junit4] 2> 1568557 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1435204115315556352)]} 0 1
[junit4:junit4] 2> 1568558 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1435204115315556352)]} 0 5
[junit4:junit4] 2> 1568559 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[q!42]} 0 9
[junit4:junit4] 2> 1568563 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[r!43 (1435204115324993536)]} 0 1
[junit4:junit4] 2> 1568570 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1435204115329187840)]} 0 1
[junit4:junit4] 2> 1568571 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[r!43 (1435204115329187840)]} 0 5
[junit4:junit4] 2> 1568575 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[s!44 (1435204115337576448)]} 0 1
[junit4:junit4] 2> 1568582 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1435204115341770752)]} 0 1
[junit4:junit4] 2> 1568583 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[s!44 (1435204115341770752)]} 0 5
[junit4:junit4] 2> 1568587 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[t!45 (1435204115350159360)]} 0 1
[junit4:junit4] 2> 1568597 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1435204115357499392)]} 0 1
[junit4:junit4] 2> 1568598 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1435204115357499392)]} 0 5
[junit4:junit4] 2> 1568598 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[t!45]} 0 8
[junit4:junit4] 2> 1568602 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[u!46 (1435204115365888000)]} 0 1
[junit4:junit4] 2> 1568612 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1435204115373228032)]} 0 1
[junit4:junit4] 2> 1568613 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!46 (1435204115373228032)]} 0 5
[junit4:junit4] 2> 1568614 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[u!46]} 0 8
[junit4:junit4] 2> 1568617 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[v!47 (1435204115381616640)]} 0 1
[junit4:junit4] 2> 1568626 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1435204115387908096)]} 0 1
[junit4:junit4] 2> 1568627 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[v!47 (1435204115387908096)]} 0 5
[junit4:junit4] 2> 1568631 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[w!48 (1435204115396296704)]} 0 1
[junit4:junit4] 2> 1568637 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1435204115399442432)]} 0 1
[junit4:junit4] 2> 1568637 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[w!48 (1435204115399442432)]} 0 4
[junit4:junit4] 2> 1568641 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[x!49 (1435204115406782464)]} 0 1
[junit4:junit4] 2> 1568650 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1435204115413073920)]} 0 1
[junit4:junit4] 2> 1568651 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1435204115413073920)]} 0 5
[junit4:junit4] 2> 1568651 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[x!49]} 0 7
[junit4:junit4] 2> 1568655 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[y!50 (1435204115421462528)]} 0 1
[junit4:junit4] 2> 1568662 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1435204115425656832)]} 0 1
[junit4:junit4] 2> 1568663 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[y!50 (1435204115425656832)]} 0 5
[junit4:junit4] 2> 1568667 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[z!51 (1435204115434045440)]} 0 1
[junit4:junit4] 2> 1568676 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1435204115440336896)]} 0 1
[junit4:junit4] 2> 1568677 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!51 (1435204115440336896)]} 0 5
[junit4:junit4] 2> 1568678 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[z!51]} 0 9
[junit4:junit4] 2> 1568682 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[a!52 (1435204115449774080)]} 0 1
[junit4:junit4] 2> 1568692 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1435204115457114112)]} 0 1
[junit4:junit4] 2> 1568694 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1435204115457114112)]} 0 6
[junit4:junit4] 2> 1568694 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[a!52]} 0 10
[junit4:junit4] 2> 1568698 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[b!53 (1435204115466551296)]} 0 1
[junit4:junit4] 2> 1568703 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1435204115469697024)]} 0 0
[junit4:junit4] 2> 1568704 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[b!53 (1435204115469697024)]} 0 4
[junit4:junit4] 2> 1568708 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[c!54 (1435204115477037056)]} 0 1
[junit4:junit4] 2> 1568714 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1435204115481231360)]} 0 0
[junit4:junit4] 2> 1568715 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[c!54 (1435204115481231360)]} 0 4
[junit4:junit4] 2> 1568719 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[d!55 (1435204115488571392)]} 0 1
[junit4:junit4] 2> 1568725 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1435204115491717120)]} 0 1
[junit4:junit4] 2> 1568726 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[d!55 (1435204115491717120)]} 0 5
[junit4:junit4] 2> 1568730 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[e!56 (1435204115500105728)]} 0 1
[junit4:junit4] 2> 1568740 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1435204115507445760)]} 0 1
[junit4:junit4] 2> 1568741 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1435204115507445760)]} 0 5
[junit4:junit4] 2> 1568742 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[e!56]} 0 9
[junit4:junit4] 2> 1568746 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[f!57 (1435204115516882944)]} 0 1
[junit4:junit4] 2> 1568756 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1435204115525271552)]} 0 1
[junit4:junit4] 2> 1568757 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1435204115525271552)]} 0 5
[junit4:junit4] 2> 1568757 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[f!57]} 0 8
[junit4:junit4] 2> 1568762 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[g!58 (1435204115533660160)]} 0 1
[junit4:junit4] 2> 1568769 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1435204115537854464)]} 0 1
[junit4:junit4] 2> 1568770 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[g!58 (1435204115537854464)]} 0 4
[junit4:junit4] 2> 1568773 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[h!59 (1435204115545194496)]} 0 1
[junit4:junit4] 2> 1568821 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1435204115592380416)]} 0 1
[junit4:junit4] 2> 1568822 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1435204115592380416)]} 0 6
[junit4:junit4] 2> 1568823 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[h!59]} 0 10
[junit4:junit4] 2> 1568827 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[i!60 (1435204115602866176)]} 0 1
[junit4:junit4] 2> 1568836 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1435204115608109056)]} 0 1
[junit4:junit4] 2> 1568837 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[i!60 (1435204115608109056)]} 0 6
[junit4:junit4] 2> 1568841 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[j!61 (1435204115616497664)]} 0 1
[junit4:junit4] 2> 1568848 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1435204115621740544)]} 0 1
[junit4:junit4] 2> 1568849 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[j!61 (1435204115621740544)]} 0 5
[junit4:junit4] 2> 1568853 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[k!62 (1435204115630129152)]} 0 1
[junit4:junit4] 2> 1568860 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1435204115634323456)]} 0 1
[junit4:junit4] 2> 1568861 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[k!62 (1435204115634323456)]} 0 5
[junit4:junit4] 2> 1568866 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[l!63 (1435204115643760640)]} 0 1
[junit4:junit4] 2> 1568873 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1435204115647954944)]} 0 1
[junit4:junit4] 2> 1568874 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[l!63 (1435204115647954944)]} 0 5
[junit4:junit4] 2> 1568878 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[m!64 (1435204115655294976)]} 0 1
[junit4:junit4] 2> 1568888 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1435204115662635008)]} 0 1
[junit4:junit4] 2> 1568889 T4041 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!64 (1435204115662635008)]} 0 5
[junit4:junit4] 2> 1568890 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[m!64]} 0 9
[junit4:junit4] 2> 1568894 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[n!65 (1435204115672072192)]} 0 1
[junit4:junit4] 2> 1568901 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1435204115676266496)]} 0 1
[junit4:junit4] 2> 1568902 T4025 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[n!65 (1435204115676266496)]} 0 5
[junit4:junit4] 2> 1568906 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[o!66 (1435204115684655104)]} 0 1
[junit4:junit4] 2> 1568913 T4068 C171 P12593 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1435204115689897984)]} 0 1
[junit4:junit4] 2> 1568914 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[o!66 (1435204115689897984)]} 0 5
[junit4:junit4] 2> 1568918 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[p!67 (1435204115697238016)]} 0 1
[junit4:junit4] 2> 1568929 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:63091/abv/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!67 (1435204115705626624)]} 0 1
[junit4:junit4] 2> 1568930 T4023 C172 P63091 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={distrib.from=http://127.0.0.1:60298/abv/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!67 (1435204115705626624)]} 0 6
[junit4:junit4] 2> 1568931 T4039 C173 P60298 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[p!67]} 0 10
[junit4:junit4] 2> 1568935 T3999 C174 P63087 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/update params={wt=javabin&version=2} {add=[q!68 (1435204115716112384)]} 0 1
[junit4:junit4] 2> 1568942 T4053 C170 P57171 oasup.LogUpdateProcessor.finish [collection1] webapp=/abv path=/updat
[...truncated too long message...]
est.
[junit4:junit4] 2> 1608896 T4078 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1608896 T4078 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index;done=false>>]
[junit4:junit4] 2> 1608896 T4078 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4/index
[junit4:junit4] 2> 1608897 T4078 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4;done=false>>]
[junit4:junit4] 2> 1608897 T4078 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1368717276674/jetty4
[junit4:junit4] 2> 1608897 T4078 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1608898 T4078 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89700255444697100-5-n_0000000001
[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.delete(ZooKeeper.java:873)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:152)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:246)
[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> 1608899 T4078 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1608899 T4078 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> 1608899 T4078 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1608899 T4078 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> 1608900 T4078 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1608900 T4078 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=Memory doPackFST= true), _version_=Pulsing41(freqCutoff=7 minBlockSize=35 maxBlockSize=151)}, docValues:{}, sim=DefaultSimilarity, locale=ar_QA, timezone=America/Cancun
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_17 (64-bit)/cpus=16,threads=2,free=219718296,total=351272960
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SuggesterFSTTest, PluginInfoTest, TestPerFieldSimilarity, TestFieldTypeCollectionResource, TestIBSimilarityFactory, ZkCLITest, TestFuzzyAnalyzedSuggestions, ClusterStateUpdateTest, DistributedSpellCheckComponentTest, SyncSliceTest, ResourceLoaderTest, TestLMDirichletSimilarityFactory, TestLRUCache, TermsComponentTest, DateFieldTest, PrimitiveFieldTypeTest, TestCoreContainer, TestLFUCache, BasicFunctionalityTest, TestPluginEnable, TestStressVersions, TestValueSourceCache, AlternateDirectoryTest, LukeRequestHandlerTest, TestRealTimeGet, TestSearchPerf, TestCloudManagedSchemaAddField, SynonymTokenizerTest, LeaderElectionTest, TestSolrIndexConfig, TestSolrDeletionPolicy2, TestDocSet, ExternalFileFieldSortTest, AnalysisAfterCoreReloadTest, DirectSolrConnectionTest, TestFunctionQuery, TestPHPSerializedResponseWriter, QueryResultKeyTest, RecoveryZkTest, TestQuerySenderListener, TestFieldResource, ReturnFieldsTest, AliasIntegrationTest, UnloadDistributedZkTest, ChaosMonkeyShardSplitTest, SpatialFilterTest, TestReversedWildcardFilterFactory, PeerSyncTest, SoftAutoCommitTest, SpellingQueryConverterTest, TestDocumentBuilder, WordBreakSolrSpellCheckerTest, ChaosMonkeyNothingIsSafeTest, ZkControllerTest, TestPseudoReturnFields, TestFastWriter, BinaryUpdateRequestHandlerTest, TestManagedSchemaFieldResource, UUIDFieldTest, TestSort, TestSolrCoreProperties, OverseerTest, TestCloudManagedSchema, TestSchemaResource, SOLR749Test, TestSolrQueryParser, DocValuesTest, SolrCoreTest, SliceStateUpdateTest, TestReplicationHandler, OverseerCollectionProcessorTest, TestTrie, BasicZkTest, TestZkChroot, TestRandomDVFaceting, TestJoin, TestGroupingSearch, CurrencyFieldXmlFileTest, SignatureUpdateProcessorFactoryTest, CoreAdminHandlerTest, SuggesterTest, TestStressLucene, PolyFieldTest, SolrCoreCheckLockOnStartupTest, FieldMutatingUpdateProcessorTest, DirectUpdateHandlerOptimizeTest, DocValuesMultiTest, TestSolrDeletionPolicy1, XsltUpdateRequestHandlerTest, CacheHeaderTest, DisMaxRequestHandlerTest, TestWriterPerf, DocumentAnalysisRequestHandlerTest, FileBasedSpellCheckerTest, RequestHandlersTest, TermVectorComponentTest, FieldAnalysisRequestHandlerTest, LoggingHandlerTest, RegexBoostProcessorTest, IndexSchemaTest, TestCollationField, MBeansHandlerTest, UniqFieldsUpdateProcessorFactoryTest, TestPartialUpdateDeduplication, CSVRequestHandlerTest, SearchHandlerTest, TestPropInject, SolrIndexConfigTest, TestMergePolicyConfig, SampleTest, TestBinaryField, MinimalSchemaTest, TestConfig, NotRequiredUniqueKeyTest, TestPhraseSuggestions, TestCharFilters, TestXIncludeConfig, EchoParamsTest, TestSweetSpotSimilarityFactory, TestDFRSimilarityFactory, TestNumberUtils, TestDefaultSimilarityFactory, LegacyHTMLStripCharFilterTest, TestJmxMonitoredMap, TestFastOutputStream, ScriptEngineTest, OpenExchangeRatesOrgProviderTest, URLClassifyProcessorTest, TestFastLRUCache, DateMathParserTest, PreAnalyzedFieldTest, PrimUtilsTest, TestSuggestSpellingConverter, DOMUtilTest, RAMDirectoryFactoryTest, ClusterStateTest, TestUtils, SliceStateTest, SystemInfoHandlerTest, CircularListTest, TestRTGBase, SolrTestCaseJ4Test, ShardSplitTest]
[junit4:junit4] Completed on J0 in 67.64s, 1 test, 1 error <<< FAILURES!
[...truncated 10 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: 47 minutes 30 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure