You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/05 02:40:10 UTC
[JENKINS] Lucene-Solr-4.x-Windows (64bit/jdk1.7.0_21) - Build #
2856 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Windows/2856/
Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:56024/jt/l 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:56024/jt/l returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([145A3F58FB755781:95BCB1408C2A37BD]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
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 9348 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 476751 T893 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /jt/l
[junit4:junit4] 2> 476762 T893 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\solrtest-ChaosMonkeyShardSplitTest-1370390631669
[junit4:junit4] 2> 476765 T893 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 476767 T894 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 476867 T893 oasc.ZkTestServer.run start zk server on port:56005
[junit4:junit4] 2> 476870 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 476891 T900 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@27025142 name:ZooKeeperConnection Watcher:127.0.0.1:56005 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 476892 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 476893 T893 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 476907 T895 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f11a595040000, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 476910 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 476914 T902 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3cc071c5 name:ZooKeeperConnection Watcher:127.0.0.1:56005/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 476914 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 476914 T893 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 476927 T893 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 476936 T893 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 476943 T893 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 476949 T893 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 476951 T893 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 476964 T893 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 476964 T893 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 476972 T893 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 476973 T893 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 476978 T893 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 476979 T893 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 476985 T893 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 476985 T893 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 476990 T893 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 476991 T893 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 476996 T893 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 476997 T893 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 477002 T893 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 477003 T893 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 477010 T893 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 477010 T893 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 477509 T893 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 477516 T893 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56012
[junit4:junit4] 2> 477516 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 477516 T893 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 477517 T893 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370390631926
[junit4:junit4] 2> 477517 T893 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370390631926\solr.xml
[junit4:junit4] 2> 477517 T893 oasc.CoreContainer.<init> New CoreContainer 1882091878
[junit4:junit4] 2> 477518 T893 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370390631926\'
[junit4:junit4] 2> 477518 T893 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370390631926\'
[junit4:junit4] 2> 477647 T893 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 477647 T893 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 477647 T893 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 477648 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 477648 T893 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 477648 T893 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 477648 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 477649 T893 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 477649 T893 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 477649 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 477658 T893 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 477659 T893 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:56005/solr
[junit4:junit4] 2> 477659 T893 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 477661 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 477679 T913 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@680be213 name:ZooKeeperConnection Watcher:127.0.0.1:56005 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 477680 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 477685 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 477696 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 477701 T915 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3480b199 name:ZooKeeperConnection Watcher:127.0.0.1:56005/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 477702 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 477707 T893 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 477717 T893 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 477725 T893 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 477730 T893 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56012_jt%2Fl
[junit4:junit4] 2> 477735 T893 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56012_jt%2Fl
[junit4:junit4] 2> 477743 T893 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 477763 T893 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 477771 T893 oasc.Overseer.start Overseer (id=89809920438042627-127.0.0.1:56012_jt%2Fl-n_0000000000) starting
[junit4:junit4] 2> 477783 T893 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 477798 T917 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 477801 T893 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 477813 T893 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 477819 T893 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 477832 T916 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 477836 T918 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370390631926\collection1
[junit4:junit4] 2> 477836 T918 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 477837 T918 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 477838 T918 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 477841 T918 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370390631926\collection1\'
[junit4:junit4] 2> 477842 T918 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370390631926/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 477843 T918 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370390631926/collection1/lib/README' to classloader
[junit4:junit4] 2> 477897 T918 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 477965 T918 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 477967 T918 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 477974 T918 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 478688 T918 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 478692 T918 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 478694 T918 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 478707 T918 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 478774 T918 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 478774 T918 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370390631926\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/control/data\
[junit4:junit4] 2> 478775 T918 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f5dbf82
[junit4:junit4] 2> 478775 T918 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 478776 T918 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/control/data\
[junit4:junit4] 2> 478776 T918 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/control/data\index/
[junit4:junit4] 2> 478776 T918 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 478776 T918 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/control/data\index
[junit4:junit4] 2> 478780 T918 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@11d6f520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d037a56; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 478780 T918 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 478783 T918 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 478784 T918 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 478784 T918 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 478785 T918 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 478785 T918 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 478786 T918 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 478786 T918 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 478786 T918 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 478787 T918 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 478797 T918 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 478803 T918 oass.SolrIndexSearcher.<init> Opening Searcher@5bb31d58 main
[junit4:junit4] 2> 478804 T918 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\control\data\tlog
[junit4:junit4] 2> 478806 T918 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 478806 T918 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 478809 T919 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5bb31d58 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 478810 T918 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 478810 T918 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 479340 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 479341 T916 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:56012_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56012/jt/l"}
[junit4:junit4] 2> 479341 T916 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 479341 T916 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 479351 T915 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> 479815 T918 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 479815 T918 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56012/jt/l collection:control_collection shard:shard1
[junit4:junit4] 2> 479816 T918 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 479834 T918 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 479840 T918 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 479840 T918 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 479840 T918 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:56012/jt/l/collection1/
[junit4:junit4] 2> 479840 T918 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 479841 T918 oasc.SyncStrategy.syncToMe http://127.0.0.1:56012/jt/l/collection1/ has no replicas
[junit4:junit4] 2> 479841 T918 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:56012/jt/l/collection1/
[junit4:junit4] 2> 479841 T918 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 480859 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 480880 T915 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> 480924 T918 oasc.ZkController.register We are http://127.0.0.1:56012/jt/l/collection1/ and leader is http://127.0.0.1:56012/jt/l/collection1/
[junit4:junit4] 2> 480924 T918 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56012/jt/l
[junit4:junit4] 2> 480924 T918 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 480924 T918 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 480925 T918 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 480928 T918 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 480930 T893 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 480930 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 480930 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 480940 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 480942 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 480946 T922 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2c596924 name:ZooKeeperConnection Watcher:127.0.0.1:56005/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 480946 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 480948 T893 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 480953 T893 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 481348 T893 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 481352 T893 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56024
[junit4:junit4] 2> 481353 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 481353 T893 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 481353 T893 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370390635860
[junit4:junit4] 2> 481354 T893 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370390635860\solr.xml
[junit4:junit4] 2> 481354 T893 oasc.CoreContainer.<init> New CoreContainer 270676872
[junit4:junit4] 2> 481355 T893 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370390635860\'
[junit4:junit4] 2> 481355 T893 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370390635860\'
[junit4:junit4] 2> 481476 T893 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 481477 T893 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 481477 T893 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 481477 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 481478 T893 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 481478 T893 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 481478 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 481479 T893 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 481479 T893 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 481479 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 481489 T893 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 481490 T893 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:56005/solr
[junit4:junit4] 2> 481490 T893 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 481492 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 481507 T933 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e711daf name:ZooKeeperConnection Watcher:127.0.0.1:56005 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 481508 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 481512 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 481512 T895 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f11a595040005, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 481520 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 481525 T935 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@68893178 name:ZooKeeperConnection Watcher:127.0.0.1:56005/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 481526 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 481534 T893 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 482392 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 482394 T916 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:56012_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56012/jt/l"}
[junit4:junit4] 2> 482402 T922 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> 482402 T915 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> 482402 T935 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> 482539 T893 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56024_jt%2Fl
[junit4:junit4] 2> 482543 T893 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56024_jt%2Fl
[junit4:junit4] 2> 482554 T915 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> 482556 T922 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 482556 T922 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> 482559 T935 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 482559 T935 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> 482564 T915 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 482572 T936 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370390635860\collection1
[junit4:junit4] 2> 482573 T936 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 482574 T936 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 482574 T936 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 482576 T936 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370390635860\collection1\'
[junit4:junit4] 2> 482578 T936 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370390635860/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 482579 T936 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370390635860/collection1/lib/README' to classloader
[junit4:junit4] 2> 482631 T936 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 482699 T936 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 482703 T936 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 482718 T936 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 483316 T936 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 483319 T936 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 483321 T936 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 483329 T936 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 483372 T936 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 483373 T936 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370390635860\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty1\
[junit4:junit4] 2> 483373 T936 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f5dbf82
[junit4:junit4] 2> 483373 T936 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 483374 T936 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty1\
[junit4:junit4] 2> 483374 T936 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty1\index/
[junit4:junit4] 2> 483374 T936 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 483375 T936 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty1\index
[junit4:junit4] 2> 483379 T936 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5220d643 lockFactory=org.apache.lucene.store.NativeFSLockFactory@286b0b2a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 483379 T936 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 483383 T936 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 483384 T936 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 483384 T936 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 483385 T936 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 483385 T936 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 483386 T936 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 483386 T936 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 483387 T936 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 483387 T936 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 483397 T936 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 483402 T936 oass.SolrIndexSearcher.<init> Opening Searcher@224ac43b main
[junit4:junit4] 2> 483403 T936 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\jetty1\tlog
[junit4:junit4] 2> 483404 T936 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 483405 T936 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 483412 T937 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@224ac43b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 483414 T936 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 483414 T936 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 483912 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 483913 T916 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:56024_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56024/jt/l"}
[junit4:junit4] 2> 483914 T916 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 483914 T916 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 483941 T922 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> 483941 T935 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> 483941 T915 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> 484422 T936 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 484422 T936 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56024/jt/l collection:collection1 shard:shard1
[junit4:junit4] 2> 484425 T936 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 484458 T936 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 484471 T936 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 484471 T936 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 484472 T936 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:56024/jt/l/collection1/
[junit4:junit4] 2> 484472 T936 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 484473 T936 oasc.SyncStrategy.syncToMe http://127.0.0.1:56024/jt/l/collection1/ has no replicas
[junit4:junit4] 2> 484473 T936 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:56024/jt/l/collection1/
[junit4:junit4] 2> 484474 T936 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 485453 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 485494 T915 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> 485495 T935 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> 485495 T922 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> 485535 T936 oasc.ZkController.register We are http://127.0.0.1:56024/jt/l/collection1/ and leader is http://127.0.0.1:56024/jt/l/collection1/
[junit4:junit4] 2> 485535 T936 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56024/jt/l
[junit4:junit4] 2> 485535 T936 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 485535 T936 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 485536 T936 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 485541 T936 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 485543 T893 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 485543 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 485543 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 485958 T893 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 485963 T893 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56033
[junit4:junit4] 2> 485964 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 485964 T893 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 485964 T893 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370390640459
[junit4:junit4] 2> 485964 T893 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370390640459\solr.xml
[junit4:junit4] 2> 485965 T893 oasc.CoreContainer.<init> New CoreContainer 1933592443
[junit4:junit4] 2> 485965 T893 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370390640459\'
[junit4:junit4] 2> 485965 T893 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370390640459\'
[junit4:junit4] 2> 486085 T893 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 486085 T893 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 486086 T893 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 486086 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 486086 T893 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 486086 T893 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 486087 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 486087 T893 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 486087 T893 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 486088 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 486096 T893 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 486096 T893 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:56005/solr
[junit4:junit4] 2> 486096 T893 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 486098 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 486117 T949 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@892399 name:ZooKeeperConnection Watcher:127.0.0.1:56005 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 486118 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 486122 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 486134 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 486139 T951 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ce4ece3 name:ZooKeeperConnection Watcher:127.0.0.1:56005/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 486140 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 486149 T893 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 487017 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 487018 T916 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:56024_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56024/jt/l"}
[junit4:junit4] 2> 487030 T951 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> 487031 T922 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> 487032 T915 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> 487032 T935 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> 487153 T893 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56033_jt%2Fl
[junit4:junit4] 2> 487159 T893 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56033_jt%2Fl
[junit4:junit4] 2> 487169 T915 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> 487172 T922 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 487173 T922 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> 487174 T951 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 487174 T951 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> 487176 T935 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 487176 T935 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> 487181 T915 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 487201 T952 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370390640459\collection1
[junit4:junit4] 2> 487202 T952 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 487204 T952 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 487205 T952 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 487210 T952 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370390640459\collection1\'
[junit4:junit4] 2> 487214 T952 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370390640459/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 487216 T952 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370390640459/collection1/lib/README' to classloader
[junit4:junit4] 2> 487276 T952 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 487361 T952 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 487364 T952 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 487374 T952 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 487967 T952 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 487971 T952 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 487973 T952 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 487981 T952 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 488021 T952 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 488022 T952 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370390640459\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty2\
[junit4:junit4] 2> 488022 T952 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f5dbf82
[junit4:junit4] 2> 488022 T952 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 488023 T952 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty2\
[junit4:junit4] 2> 488023 T952 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty2\index/
[junit4:junit4] 2> 488023 T952 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 488023 T952 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty2\index
[junit4:junit4] 2> 488027 T952 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6bbe2f2b lockFactory=org.apache.lucene.store.NativeFSLockFactory@56ed932a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 488027 T952 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 488031 T952 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 488031 T952 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 488032 T952 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 488032 T952 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 488033 T952 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 488033 T952 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 488033 T952 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 488034 T952 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 488034 T952 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 488044 T952 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 488049 T952 oass.SolrIndexSearcher.<init> Opening Searcher@3f840be0 main
[junit4:junit4] 2> 488050 T952 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\jetty2\tlog
[junit4:junit4] 2> 488051 T952 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 488052 T952 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 488055 T953 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f840be0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 488058 T952 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 488058 T952 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 488545 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 488548 T916 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:56033_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56033/jt/l"}
[junit4:junit4] 2> 488548 T916 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 488549 T916 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 488576 T922 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> 488578 T915 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> 488578 T951 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> 488579 T935 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> 489061 T952 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 489061 T952 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56033/jt/l collection:collection1 shard:shard2
[junit4:junit4] 2> 489064 T952 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 489096 T952 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 489109 T952 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 489110 T952 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 489110 T952 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:56033/jt/l/collection1/
[junit4:junit4] 2> 489111 T952 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 489111 T952 oasc.SyncStrategy.syncToMe http://127.0.0.1:56033/jt/l/collection1/ has no replicas
[junit4:junit4] 2> 489111 T952 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:56033/jt/l/collection1/
[junit4:junit4] 2> 489111 T952 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 490100 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 490146 T922 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> 490147 T915 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> 490148 T951 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> 490148 T935 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> 490202 T952 oasc.ZkController.register We are http://127.0.0.1:56033/jt/l/collection1/ and leader is http://127.0.0.1:56033/jt/l/collection1/
[junit4:junit4] 2> 490202 T952 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56033/jt/l
[junit4:junit4] 2> 490203 T952 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 490203 T952 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 490203 T952 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 490210 T952 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 490213 T893 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 490214 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 490215 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 490638 T893 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 490644 T893 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56042
[junit4:junit4] 2> 490645 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 490645 T893 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 490645 T893 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370390645142
[junit4:junit4] 2> 490646 T893 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370390645142\solr.xml
[junit4:junit4] 2> 490647 T893 oasc.CoreContainer.<init> New CoreContainer 2140441471
[junit4:junit4] 2> 490647 T893 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370390645142\'
[junit4:junit4] 2> 490647 T893 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370390645142\'
[junit4:junit4] 2> 490774 T893 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 490775 T893 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 490775 T893 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 490775 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 490776 T893 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 490776 T893 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 490776 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 490777 T893 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 490777 T893 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 490777 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 490784 T893 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 490784 T893 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:56005/solr
[junit4:junit4] 2> 490785 T893 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 490787 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 490804 T965 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6a740737 name:ZooKeeperConnection Watcher:127.0.0.1:56005 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 490805 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 490809 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 490809 T895 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f11a595040009, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 490819 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 490822 T967 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@582938d4 name:ZooKeeperConnection Watcher:127.0.0.1:56005/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 490822 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 490833 T893 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 491675 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 491678 T916 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:56033_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56033/jt/l"}
[junit4:junit4] 2> 491697 T922 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> 491697 T967 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> 491700 T935 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> 491700 T951 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> 491701 T915 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> 491838 T893 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56042_jt%2Fl
[junit4:junit4] 2> 491844 T893 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56042_jt%2Fl
[junit4:junit4] 2> 491855 T967 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> 491855 T915 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> 491858 T922 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 491858 T922 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> 491860 T951 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 491861 T951 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> 491862 T935 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 491862 T935 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> 491870 T915 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 491871 T967 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 491890 T968 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370390645142\collection1
[junit4:junit4] 2> 491891 T968 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 491893 T968 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 491893 T968 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 491899 T968 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370390645142\collection1\'
[junit4:junit4] 2> 491902 T968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370390645142/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 491903 T968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370390645142/collection1/lib/README' to classloader
[junit4:junit4] 2> 491963 T968 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 492020 T968 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 492023 T968 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 492028 T968 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 492663 T968 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 492667 T968 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 492670 T968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 492677 T968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 492739 T968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 492739 T968 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370390645142\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty3\
[junit4:junit4] 2> 492740 T968 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f5dbf82
[junit4:junit4] 2> 492740 T968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 492741 T968 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty3\
[junit4:junit4] 2> 492741 T968 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty3\index/
[junit4:junit4] 2> 492741 T968 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 492742 T968 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty3\index
[junit4:junit4] 2> 492746 T968 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7c4d2ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771c97b7; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 492747 T968 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 492750 T968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 492751 T968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 492751 T968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 492752 T968 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 492753 T968 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 492753 T968 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 492753 T968 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 492754 T968 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 492754 T968 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 492765 T968 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 492772 T968 oass.SolrIndexSearcher.<init> Opening Searcher@22227624 main
[junit4:junit4] 2> 492773 T968 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\jetty3\tlog
[junit4:junit4] 2> 492774 T968 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 492775 T968 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 492779 T969 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@22227624 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 492781 T968 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 492782 T968 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 493219 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 493220 T916 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:56042_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56042/jt/l"}
[junit4:junit4] 2> 493220 T916 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 493221 T916 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 493231 T922 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> 493231 T915 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> 493232 T967 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> 493232 T951 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> 493232 T935 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> 493788 T968 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 493788 T968 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56042/jt/l collection:collection1 shard:shard1
[junit4:junit4] 2> 493801 T968 oasc.ZkController.register We are http://127.0.0.1:56042/jt/l/collection1/ and leader is http://127.0.0.1:56024/jt/l/collection1/
[junit4:junit4] 2> 493801 T968 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56042/jt/l
[junit4:junit4] 2> 493802 T968 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 493802 T968 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1963 name=collection1 org.apache.solr.core.SolrCore@4fd7cb28 url=http://127.0.0.1:56042/jt/l/collection1 node=127.0.0.1:56042_jt%2Fl C1963_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:56042_jt%2Fl, base_url=http://127.0.0.1:56042/jt/l}
[junit4:junit4] 2> 493803 T970 C1963 P56042 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 493805 T970 C1963 P56042 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 493805 T968 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 493806 T970 C1963 P56042 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 493807 T970 C1963 P56042 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 493809 T893 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 493810 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 493811 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 493813 T970 C1963 P56042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 493907 T927 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 494229 T893 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 494232 T893 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56052
[junit4:junit4] 2> 494233 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 494233 T893 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 494233 T893 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370390648742
[junit4:junit4] 2> 494233 T893 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370390648742\solr.xml
[junit4:junit4] 2> 494233 T893 oasc.CoreContainer.<init> New CoreContainer 1384755578
[junit4:junit4] 2> 494235 T893 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370390648742\'
[junit4:junit4] 2> 494235 T893 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370390648742\'
[junit4:junit4] 2> 494349 T893 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 494349 T893 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 494350 T893 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 494350 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 494350 T893 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 494351 T893 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 494351 T893 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 494351 T893 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 494352 T893 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 494352 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 494359 T893 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 494360 T893 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:56005/solr
[junit4:junit4] 2> 494360 T893 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 494361 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 494377 T982 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6498bd8 name:ZooKeeperConnection Watcher:127.0.0.1:56005 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 494378 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 494382 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 494382 T895 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f11a59504000b, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 494388 T893 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 494392 T984 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4ff9b491 name:ZooKeeperConnection Watcher:127.0.0.1:56005/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 494392 T893 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 494401 T893 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 494740 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 494742 T916 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:56042_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56042/jt/l"}
[junit4:junit4] 2> 494760 T984 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> 494760 T915 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> 494761 T967 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> 494761 T951 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> 494761 T935 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> 494760 T922 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> 494907 T927 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 494907 T927 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:56042_jt%252Fl&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1000
[junit4:junit4] 2> 495406 T893 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56052_jt%2Fl
[junit4:junit4] 2> 495411 T893 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56052_jt%2Fl
[junit4:junit4] 2> 495420 T984 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> 495421 T967 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> 495421 T915 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> 495427 T922 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 495427 T922 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> 495428 T935 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 495429 T935 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> 495431 T951 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 495431 T951 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> 495438 T967 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 495442 T984 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 495443 T915 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 495451 T985 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370390648742\collection1
[junit4:junit4] 2> 495451 T985 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 495452 T985 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 495452 T985 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 495454 T985 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370390648742\collection1\'
[junit4:junit4] 2> 495456 T985 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370390648742/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 495457 T985 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370390648742/collection1/lib/README' to classloader
[junit4:junit4] 2> 495505 T985 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 495564 T985 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 495566 T985 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 495571 T985 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 496184 T985 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 496187 T985 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 496189 T985 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 496194 T985 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 496250 T985 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 496251 T985 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370390648742\collection1\, dataDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\
[junit4:junit4] 2> 496251 T985 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5f5dbf82
[junit4:junit4] 2> 496251 T985 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 496252 T985 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\
[junit4:junit4] 2> 496252 T985 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index/
[junit4:junit4] 2> 496252 T985 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 496254 T985 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index
[junit4:junit4] 2> 496258 T985 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7e9da59a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b5e1c0d; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 496258 T985 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 496262 T985 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 496262 T985 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 496263 T985 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 496264 T985 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 496264 T985 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 496265 T985 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 496265 T985 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 496266 T985 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 496266 T985 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 496277 T985 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 496283 T985 oass.SolrIndexSearcher.<init> Opening Searcher@13df3996 main
[junit4:junit4] 2> 496284 T985 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\jetty4\tlog
[junit4:junit4] 2> 496286 T985 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 496286 T985 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 496293 T986 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13df3996 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 496295 T985 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 496295 T985 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C1964 name=collection1 org.apache.solr.core.SolrCore@4fd7cb28 url=http://127.0.0.1:56042/jt/l/collection1 node=127.0.0.1:56042_jt%2Fl C1964_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:56042_jt%2Fl, base_url=http://127.0.0.1:56042/jt/l}
[junit4:junit4] 2> 496910 T970 C1964 P56042 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:56024/jt/l/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 496910 T970 C1964 P56042 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56042/jt/l START replicas=[http://127.0.0.1:56024/jt/l/collection1/] nUpdates=100
[junit4:junit4] 2> 496912 T970 C1964 P56042 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 496912 T970 C1964 P56042 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 496912 T970 C1964 P56042 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 496913 T970 C1964 P56042 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 496913 T970 C1964 P56042 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 496914 T970 C1964 P56042 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:56024/jt/l/collection1/. core=collection1
[junit4:junit4] 2> 496915 T970 C1964 P56042 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1965 name=collection1 org.apache.solr.core.SolrCore@216181ac url=http://127.0.0.1:56024/jt/l/collection1 node=127.0.0.1:56024_jt%2Fl C1965_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:56024_jt%2Fl, base_url=http://127.0.0.1:56024/jt/l, leader=true}
[junit4:junit4] 2> 496935 T929 C1965 P56024 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 496942 T930 C1965 P56024 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 496945 T930 C1965 P56024 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5220d643 lockFactory=org.apache.lucene.store.NativeFSLockFactory@286b0b2a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 496946 T930 C1965 P56024 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 496946 T930 C1965 P56024 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5220d643 lockFactory=org.apache.lucene.store.NativeFSLockFactory@286b0b2a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5220d643 lockFactory=org.apache.lucene.store.NativeFSLockFactory@286b0b2a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 496946 T930 C1965 P56024 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 496947 T930 C1965 P56024 oass.SolrIndexSearcher.<init> Opening Searcher@24d81ca3 realtime
[junit4:junit4] 2> 496948 T930 C1965 P56024 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 496948 T930 C1965 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l 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> 496950 T970 C1964 P56042 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 496950 T970 C1964 P56042 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 496954 T926 C1965 P56024 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 496954 T926 C1965 P56024 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 496955 T970 C1964 P56042 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 496955 T970 C1964 P56042 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 496955 T970 C1964 P56042 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 496957 T928 C1965 P56024 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 496958 T970 C1964 P56042 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 496960 T970 C1964 P56042 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty3\index.20130605030411865
[junit4:junit4] 2> 496961 T970 C1964 P56042 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@687504cf lockFactory=org.apache.lucene.store.NativeFSLockFactory@952cf6e) fullCopy=false
[junit4:junit4] 2> 496963 T927 C1965 P56024 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 496964 T970 C1964 P56042 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 496967 T970 C1964 P56042 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 496968 T970 C1964 P56042 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 496970 T970 C1964 P56042 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7c4d2ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771c97b7; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7c4d2ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771c97b7; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 496971 T970 C1964 P56042 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 496971 T970 C1964 P56042 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 496971 T970 C1964 P56042 oass.SolrIndexSearcher.<init> Opening Searcher@4a8e74bc main
[junit4:junit4] 2> 496972 T969 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4a8e74bc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 496973 T970 C1964 P56042 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty3\index.20130605030411865 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty3\index.20130605030411865;done=true>>]
[junit4:junit4] 2> 496973 T970 C1964 P56042 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty3\index.20130605030411865
[junit4:junit4] 2> 496973 T970 C1964 P56042 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty3\index.20130605030411865
[junit4:junit4] 2> 496973 T970 C1964 P56042 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 496973 T970 C1964 P56042 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 496973 T970 C1964 P56042 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 496974 T970 C1964 P56042 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 496982 T970 C1964 P56042 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 497797 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 497800 T916 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:56052_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56052/jt/l"}
[junit4:junit4] 2> 497800 T916 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 497801 T916 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 497820 T916 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:56042_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56042/jt/l"}
[junit4:junit4] 2> 497841 T984 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> 497841 T915 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> 497842 T967 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> 497843 T951 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> 497841 T922 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> 497844 T935 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> 498299 T985 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 498299 T985 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56052/jt/l collection:collection1 shard:shard2
[junit4:junit4] 2> 498313 T985 oasc.ZkController.register We are http://127.0.0.1:56052/jt/l/collection1/ and leader is http://127.0.0.1:56033/jt/l/collection1/
[junit4:junit4] 2> 498313 T985 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56052/jt/l
[junit4:junit4] 2> 498313 T985 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 498314 T985 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1966 name=collection1 org.apache.solr.core.SolrCore@56bf19cc url=http://127.0.0.1:56052/jt/l/collection1 node=127.0.0.1:56052_jt%2Fl C1966_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:56052_jt%2Fl, base_url=http://127.0.0.1:56052/jt/l}
[junit4:junit4] 2> 498316 T989 C1966 P56052 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 498317 T989 C1966 P56052 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 498318 T985 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 498318 T989 C1966 P56052 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 498318 T989 C1966 P56052 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 498321 T893 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 498323 T893 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 498323 T893 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 498324 T989 C1966 P56052 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 498349 T943 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 498351 T893 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 498352 T893 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 498352 T893 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 498354 T893 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 499357 T893 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 499372 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 499374 T916 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:56052_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56052/jt/l"}
[junit4:junit4] 2> 499396 T984 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> 499396 T967 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> 499398 T951 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> 499399 T935 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> 499396 T915 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> 499397 T922 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> 500349 T943 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 500349 T943 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:56052_jt%252Fl&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2000
[junit4:junit4] 2> 500361 T893 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 501383 T893 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C1966_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:56052_jt%2Fl, base_url=http://127.0.0.1:56052/jt/l}
[junit4:junit4] 2> 502468 T989 C1966 P56052 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:56033/jt/l/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 502468 T989 C1966 P56052 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56052/jt/l START replicas=[http://127.0.0.1:56033/jt/l/collection1/] nUpdates=100
[junit4:junit4] 2> 502470 T989 C1966 P56052 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 502470 T989 C1966 P56052 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 502470 T989 C1966 P56052 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 502470 T989 C1966 P56052 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 502471 T989 C1966 P56052 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 502471 T989 C1966 P56052 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:56033/jt/l/collection1/. core=collection1
[junit4:junit4] 2> 502471 T989 C1966 P56052 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1967 name=collection1 org.apache.solr.core.SolrCore@57b5c312 url=http://127.0.0.1:56033/jt/l/collection1 node=127.0.0.1:56033_jt%2Fl C1967_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:56033_jt%2Fl, base_url=http://127.0.0.1:56033/jt/l, leader=true}
[junit4:junit4] 2> 502494 T943 C1967 P56033 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 502496 T893 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 502507 T942 C1967 P56033 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 502511 T942 C1967 P56033 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6bbe2f2b lockFactory=org.apache.lucene.store.NativeFSLockFactory@56ed932a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 502512 T942 C1967 P56033 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 502513 T942 C1967 P56033 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6bbe2f2b lockFactory=org.apache.lucene.store.NativeFSLockFactory@56ed932a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6bbe2f2b lockFactory=org.apache.lucene.store.NativeFSLockFactory@56ed932a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 502513 T942 C1967 P56033 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 502513 T942 C1967 P56033 oass.SolrIndexSearcher.<init> Opening Searcher@1dc6381b realtime
[junit4:junit4] 2> 502514 T942 C1967 P56033 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 502514 T942 C1967 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l 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> 502515 T989 C1966 P56052 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 502515 T989 C1966 P56052 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 502519 T945 C1967 P56033 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 502519 T945 C1967 P56033 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 502519 T989 C1966 P56052 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 502519 T989 C1966 P56052 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 502524 T989 C1966 P56052 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 502527 T946 C1967 P56033 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 502528 T989 C1966 P56052 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 502531 T989 C1966 P56052 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index.20130605030417436
[junit4:junit4] 2> 502531 T989 C1966 P56052 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@279fbb40 lockFactory=org.apache.lucene.store.NativeFSLockFactory@60e5618f) fullCopy=false
[junit4:junit4] 2> 502536 T947 C1967 P56033 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 502538 T989 C1966 P56052 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 502540 T989 C1966 P56052 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 502540 T989 C1966 P56052 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 502544 T989 C1966 P56052 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7e9da59a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b5e1c0d; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7e9da59a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b5e1c0d; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 502545 T989 C1966 P56052 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 502545 T989 C1966 P56052 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 502545 T989 C1966 P56052 oass.SolrIndexSearcher.<init> Opening Searcher@676a31f0 main
[junit4:junit4] 2> 502546 T986 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@676a31f0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 502547 T989 C1966 P56052 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index.20130605030417436 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index.20130605030417436;done=true>>]
[junit4:junit4] 2> 502547 T989 C1966 P56052 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index.20130605030417436
[junit4:junit4] 2> 502547 T989 C1966 P56052 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index.20130605030417436
[junit4:junit4] 2> 502548 T989 C1966 P56052 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 502548 T989 C1966 P56052 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 502548 T989 C1966 P56052 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 502548 T989 C1966 P56052 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 502562 T989 C1966 P56052 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 502565 T916 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 502566 T916 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:56052_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56052/jt/l"}
[junit4:junit4] 2> 502577 T984 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> 502577 T922 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> 502579 T915 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> 502579 T967 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> 502580 T951 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> 502581 T935 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> 503602 T893 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 503605 T893 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C1968 name=collection1 org.apache.solr.core.SolrCore@172459f6 url=http://127.0.0.1:56012/jt/l/collection1 node=127.0.0.1:56012_jt%2Fl C1968_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:56012_jt%2Fl, base_url=http://127.0.0.1:56012/jt/l, leader=true}
[junit4:junit4] 2> 503627 T906 C1968 P56012 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 503639 T906 C1968 P56012 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@11d6f520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d037a56; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> 503640 T906 C1968 P56012 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 503642 T906 C1968 P56012 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@11d6f520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d037a56; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@11d6f520 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d037a56; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_2,generation=2}
[junit4:junit4] 2> 503643 T906 C1968 P56012 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 503644 T906 C1968 P56012 oass.SolrIndexSearcher.<init> Opening Searcher@26911054 main
[junit4:junit4] 2> 503645 T906 C1968 P56012 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 503647 T919 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@26911054 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 503648 T906 C1968 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 2> 503658 T929 C1965 P56024 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 503660 T929 C1965 P56024 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5220d643 lockFactory=org.apache.lucene.store.NativeFSLockFactory@286b0b2a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5220d643 lockFactory=org.apache.lucene.store.NativeFSLockFactory@286b0b2a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 503660 T929 C1965 P56024 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 503661 T929 C1965 P56024 oass.SolrIndexSearcher.<init> Opening Searcher@11d5e909 main
[junit4:junit4] 2> 503661 T929 C1965 P56024 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 503663 T937 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@11d5e909 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 503663 T929 C1965 P56024 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:56042/jt/l/collection1/, StdNode: http://127.0.0.1:56033/jt/l/collection1/, StdNode: http://127.0.0.1:56052/jt/l/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C1966_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:56052_jt%2Fl, base_url=http://127.0.0.1:56052/jt/l}
[junit4:junit4] 2> 503681 T979 C1966 P56052 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 503684 T979 C1966 P56052 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7e9da59a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b5e1c0d; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7e9da59a lockFactory=org.apache.lucene.store.NativeFSLockFactory@5b5e1c0d; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 503684 T979 C1966 P56052 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 503686 T979 C1966 P56052 oass.SolrIndexSearcher.<init> Opening Searcher@6dc93bd9 main
[junit4:junit4] 2> 503686 T979 C1966 P56052 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 503687 T944 C1967 P56033 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 503690 T944 C1967 P56033 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6bbe2f2b lockFactory=org.apache.lucene.store.NativeFSLockFactory@56ed932a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@6bbe2f2b lockFactory=org.apache.lucene.store.NativeFSLockFactory@56ed932a; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 503690 T944 C1967 P56033 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 503690 T944 C1967 P56033 oass.SolrIndexSearcher.<init> Opening Searcher@2d364992 main
[junit4:junit4] 2> 503690 T944 C1967 P56033 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 503692 T953 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d364992 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 503694 T986 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6dc93bd9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 503694 T979 C1966 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> C1964_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:56042_jt%2Fl, base_url=http://127.0.0.1:56042/jt/l}
[junit4:junit4] 2> 503704 T962 C1964 P56042 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 503705 T962 C1964 P56042 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7c4d2ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771c97b7; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7c4d2ecd lockFactory=org.apache.lucene.store.NativeFSLockFactory@771c97b7; maxCacheMB=0.4677734375 maxMergeSizeMB=0.6552734375)),segFN=segments_3,generation=3}
[junit4:junit4] 2> 503705 T962 C1964 P56042 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 503706 T962 C1964 P56042 oass.SolrIndexSearcher.<init> Opening Searcher@3ebe80f1 main
[junit4:junit4] 2> 503706 T962 C1964 P56042 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 503708 T969 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ebe80f1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 503709 T944 C1967 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4] 2> 503710 T962 C1964 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l 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> 503711 T929 C1965 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 53
[junit4:junit4] 2> 503712 T893 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 503718 T930 C1965 P56024 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 503723 T963 C1964 P56042 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 503725 T945 C1967 P56033 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 503728 T980 C1966 P56052 oasc.SolrCore.execute [collection1] webapp=/jt/l path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 505932 T906 C1968 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436958757578866688)} 0 2
[junit4:junit4] 2> 505942 T963 C1964 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={update.distrib=FROMLEADER&_version_=-1436958757584109568&update.from=http://127.0.0.1:56024/jt/l/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436958757584109568)} 0 1
[junit4:junit4] 2> 505953 T980 C1966 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={update.distrib=FROMLEADER&_version_=-1436958757589352448&update.from=http://127.0.0.1:56033/jt/l/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436958757589352448)} 0 5
[junit4:junit4] 2> 505954 T945 C1967 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1436958757589352448)} 0 13
[junit4:junit4] 2> 505955 T930 C1965 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436958757584109568)} 0 19
[junit4:junit4] 2> 505960 T907 C1968 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[0 (1436958757608226816)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C1969 name=collection1 org.apache.solr.core.SolrCore@4fd7cb28 url=http://127.0.0.1:56042/jt/l/collection1 node=127.0.0.1:56042_jt%2Fl C1969_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:56042_jt%2Fl, base_url=http://127.0.0.1:56042/jt/l}
[junit4:junit4] 2> 505983 T958 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1436958757627101184)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C1970 name=collection1 org.apache.solr.core.SolrCore@216181ac url=http://127.0.0.1:56024/jt/l/collection1 node=127.0.0.1:56024_jt%2Fl C1970_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:56024_jt%2Fl, base_url=http://127.0.0.1:56024/jt/l, leader=true}
[junit4:junit4] 2> 505984 T931 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[0 (1436958757627101184)]} 0 7
[junit4:junit4] 2> ASYNC NEW_CORE C1971 name=collection1 org.apache.solr.core.SolrCore@172459f6 url=http://127.0.0.1:56012/jt/l/collection1 node=127.0.0.1:56012_jt%2Fl C1971_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:56012_jt%2Fl, base_url=http://127.0.0.1:56012/jt/l, leader=true}
[junit4:junit4] 2> 505989 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[1 (1436958757637586944)]} 0 2
[junit4:junit4] 2> 505999 T959 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1436958757647024128)]} 0 1
[junit4:junit4] 2> 506000 T926 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1436958757647024128)]} 0 6
[junit4:junit4] 2> ASYNC NEW_CORE C1972 name=collection1 org.apache.solr.core.SolrCore@57b5c312 url=http://127.0.0.1:56033/jt/l/collection1 node=127.0.0.1:56033_jt%2Fl C1972_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:56033_jt%2Fl, base_url=http://127.0.0.1:56033/jt/l, leader=true}
[junit4:junit4] 2> 506001 T946 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[1]} 0 9
[junit4:junit4] 2> 506004 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[2 (1436958757655412736)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C1973 name=collection1 org.apache.solr.core.SolrCore@56bf19cc url=http://127.0.0.1:56052/jt/l/collection1 node=127.0.0.1:56052_jt%2Fl C1973_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:56052_jt%2Fl, base_url=http://127.0.0.1:56052/jt/l}
[junit4:junit4] 2> 506014 T975 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1436958757661704192)]} 0 1
[junit4:junit4] 2> 506015 T947 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[2 (1436958757661704192)]} 0 5
[junit4:junit4] 2> 506018 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[3 (1436958757669044224)]} 0 1
[junit4:junit4] 2> 506027 T977 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1436958757674287104)]} 0 1
[junit4:junit4] 2> 506028 T943 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[3 (1436958757674287104)]} 0 7
[junit4:junit4] 2> 506031 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[4 (1436958757682675712)]} 0 1
[junit4:junit4] 2> 506042 T960 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1436958757690015744)]} 0 1
[junit4:junit4] 2> 506043 T928 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1436958757690015744)]} 0 7
[junit4:junit4] 2> 506044 T942 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[4]} 0 11
[junit4:junit4] 2> 506048 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[5 (1436958757700501504)]} 0 1
[junit4:junit4] 2> 506056 T978 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1436958757704695808)]} 0 1
[junit4:junit4] 2> 506057 T944 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[5 (1436958757704695808)]} 0 6
[junit4:junit4] 2> 506059 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[6 (1436958757713084416)]} 0 0
[junit4:junit4] 2> 506069 T976 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1436958757717278720)]} 0 1
[junit4:junit4] 2> 506070 T945 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[6 (1436958757717278720)]} 0 7
[junit4:junit4] 2> 506072 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[7 (1436958757726715904)]} 0 0
[junit4:junit4] 2> 506079 T979 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1436958757730910208)]} 0 1
[junit4:junit4] 2> 506080 T946 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[7 (1436958757730910208)]} 0 4
[junit4:junit4] 2> 506084 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[8 (1436958757739298816)]} 0 0
[junit4:junit4] 2> 506091 T961 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1436958757742444544)]} 0 1
[junit4:junit4] 2> 506092 T927 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[8 (1436958757742444544)]} 0 5
[junit4:junit4] 2> 506095 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[9 (1436958757750833152)]} 0 0
[junit4:junit4] 2> 506104 T980 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1436958757756076032)]} 0 1
[junit4:junit4] 2> 506104 T947 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[9 (1436958757756076032)]} 0 4
[junit4:junit4] 2> 506108 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[10 (1436958757763416064)]} 0 1
[junit4:junit4] 2> 506116 T962 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1436958757768658944)]} 0 1
[junit4:junit4] 2> 506117 T929 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[10 (1436958757768658944)]} 0 5
[junit4:junit4] 2> 506120 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[11 (1436958757777047552)]} 0 0
[junit4:junit4] 2> 506129 T963 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1436958757781241856)]} 0 1
[junit4:junit4] 2> 506130 T930 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[11 (1436958757781241856)]} 0 6
[junit4:junit4] 2> 506133 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[12 (1436958757790679040)]} 0 0
[junit4:junit4] 2> 506143 T958 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1436958757798019072)]} 0 0
[junit4:junit4] 2> 506145 T931 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1436958757798019072)]} 0 5
[junit4:junit4] 2> 506145 T943 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[12]} 0 9
[junit4:junit4] 2> 506148 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[13 (1436958757806407680)]} 0 0
[junit4:junit4] 2> 506164 T959 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1436958757816893440)]} 0 3
[junit4:junit4] 2> 506165 T926 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1436958757816893440)]} 0 7
[junit4:junit4] 2> 506166 T942 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[13]} 0 15
[junit4:junit4] 2> 506169 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[14 (1436958757828427776)]} 0 0
[junit4:junit4] 2> 506176 T960 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1436958757831573504)]} 0 1
[junit4:junit4] 2> 506177 T928 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[14 (1436958757831573504)]} 0 5
[junit4:junit4] 2> 506179 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[15 (1436958757838913536)]} 0 0
[junit4:junit4] 2> 506188 T961 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1436958757844156416)]} 0 1
[junit4:junit4] 2> 506189 T927 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[15 (1436958757844156416)]} 0 5
[junit4:junit4] 2> 506192 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[16 (1436958757852545024)]} 0 0
[junit4:junit4] 2> 506204 T962 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1436958757861982208)]} 0 0
[junit4:junit4] 2> 506205 T929 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1436958757861982208)]} 0 5
[junit4:junit4] 2> 506207 T944 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[16]} 0 11
[junit4:junit4] 2> 506213 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[17 (1436958757874565120)]} 0 2
[junit4:junit4] 2> 506228 T975 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1436958757882953728)]} 0 1
[junit4:junit4] 2> 506229 T945 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[17 (1436958757882953728)]} 0 8
[junit4:junit4] 2> 506231 T930 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[17]} 0 14
[junit4:junit4] 2> 506235 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[18 (1436958757897633792)]} 0 0
[junit4:junit4] 2> 506251 T977 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1436958757908119552)]} 0 1
[junit4:junit4] 2> 506253 T946 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1436958757908119552)]} 0 8
[junit4:junit4] 2> 506257 T931 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[18]} 0 17
[junit4:junit4] 2> 506263 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[19 (1436958757925945344)]} 0 1
[junit4:junit4] 2> 506268 T978 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1436958757930139648)]} 0 0
[junit4:junit4] 2> 506271 T947 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[19 (1436958757930139648)]} 0 5
[junit4:junit4] 2> 506277 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[20 (1436958757941673984)]} 0 0
[junit4:junit4] 2> 506285 T963 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1436958757945868288)]} 0 2
[junit4:junit4] 2> 506287 T926 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[20 (1436958757945868288)]} 0 6
[junit4:junit4] 2> 506290 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[21 (1436958757955305472)]} 0 0
[junit4:junit4] 2> 506296 T976 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1436958757958451200)]} 0 0
[junit4:junit4] 2> 506297 T943 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[21 (1436958757958451200)]} 0 4
[junit4:junit4] 2> 506301 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[22 (1436958757966839808)]} 0 0
[junit4:junit4] 2> 506311 T958 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1436958757973131264)]} 0 1
[junit4:junit4] 2> 506311 T928 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1436958757973131264)]} 0 4
[junit4:junit4] 2> 506312 T942 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[22]} 0 8
[junit4:junit4] 2> 506318 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[23 (1436958757984665600)]} 0 1
[junit4:junit4] 2> 506330 T979 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1436958757989908480)]} 0 1
[junit4:junit4] 2> 506331 T944 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[23 (1436958757989908480)]} 0 9
[junit4:junit4] 2> 506335 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[24 (1436958758002491392)]} 0 1
[junit4:junit4] 2> 506350 T959 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1436958758012977152)]} 0 1
[junit4:junit4] 2> 506353 T927 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1436958758012977152)]} 0 8
[junit4:junit4] 2> 506354 T946 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[24]} 0 14
[junit4:junit4] 2> 506358 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[25 (1436958758025560064)]} 0 1
[junit4:junit4] 2> 506369 T975 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1436958758031851520)]} 0 1
[junit4:junit4] 2> 506372 T947 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[25 (1436958758031851520)]} 0 9
[junit4:junit4] 2> 506378 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[26 (1436958758046531584)]} 0 1
[junit4:junit4] 2> 506394 T977 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1436958758058065920)]} 0 1
[junit4:junit4] 2> 506395 T943 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1436958758058065920)]} 0 7
[junit4:junit4] 2> 506397 T930 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[26]} 0 14
[junit4:junit4] 2> 506403 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[27 (1436958758073794560)]} 0 1
[junit4:junit4] 2> 506418 T961 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1436958758083231744)]} 0 1
[junit4:junit4] 2> 506420 T931 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1436958758083231744)]} 0 8
[junit4:junit4] 2> 506421 T942 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[27]} 0 13
[junit4:junit4] 2> 506426 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[28 (1436958758097911808)]} 0 1
[junit4:junit4] 2> 506437 T962 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1436958758104203264)]} 0 1
[junit4:junit4] 2> 506438 T926 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[28 (1436958758104203264)]} 0 6
[junit4:junit4] 2> 506444 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[29 (1436958758116786176)]} 0 0
[junit4:junit4] 2> 506455 T978 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1436958758123077632)]} 0 1
[junit4:junit4] 2> 506456 T944 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[29 (1436958758123077632)]} 0 7
[junit4:junit4] 2> 506464 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[30 (1436958758135660544)]} 0 2
[junit4:junit4] 2> 506473 T976 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1436958758141952000)]} 0 2
[junit4:junit4] 2> 506476 T945 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[30 (1436958758141952000)]} 0 8
[junit4:junit4] 2> 506480 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[31 (1436958758154534912)]} 0 1
[junit4:junit4] 2> 506492 T979 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1436958758163972096)]} 0 1
[junit4:junit4] 2> 506494 T946 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1436958758163972096)]} 0 6
[junit4:junit4] 2> 506497 T928 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[31]} 0 13
[junit4:junit4] 2> 506502 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[32 (1436958758177603584)]} 0 2
[junit4:junit4] 2> 506513 T963 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1436958758180749312)]} 0 0
[junit4:junit4] 2> 506514 T929 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[32 (1436958758180749312)]} 0 9
[junit4:junit4] 2> 506519 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[33 (1436958758195429376)]} 0 0
[junit4:junit4] 2> 506525 T980 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1436958758199623680)]} 0 0
[junit4:junit4] 2> 506526 T947 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[33 (1436958758199623680)]} 0 3
[junit4:junit4] 2> 506529 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[34 (1436958758205915136)]} 0 0
[junit4:junit4] 2> 506540 T958 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1436958758213255168)]} 0 0
[junit4:junit4] 2> 506541 T927 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[34 (1436958758213255168)]} 0 5
[junit4:junit4] 2> 506542 T943 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[34]} 0 9
[junit4:junit4] 2> 506546 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[35 (1436958758223740928)]} 0 0
[junit4:junit4] 2> 506557 T960 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1436958758232129536)]} 0 0
[junit4:junit4] 2> 506558 T930 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[35 (1436958758232129536)]} 0 5
[junit4:junit4] 2> 506563 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[36 (1436958758241566720)]} 0 0
[junit4:junit4] 2> 506571 T959 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1436958758247858176)]} 0 0
[junit4:junit4] 2> 506573 T931 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1436958758247858176)]} 0 4
[junit4:junit4] 2> 506575 T942 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[36]} 0 9
[junit4:junit4] 2> 506579 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[37 (1436958758258343936)]} 0 0
[junit4:junit4] 2> 506587 T975 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1436958758264635392)]} 0 0
[junit4:junit4] 2> 506589 T944 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[37 (1436958758264635392)]} 0 4
[junit4:junit4] 2> 506591 T926 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[37]} 0 9
[junit4:junit4] 2> 506595 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[38 (1436958758275121152)]} 0 0
[junit4:junit4] 2> 506605 T961 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1436958758282461184)]} 0 0
[junit4:junit4] 2> 506606 T928 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1436958758282461184)]} 0 4
[junit4:junit4] 2> 506607 T945 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[38]} 0 8
[junit4:junit4] 2> 506613 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[39 (1436958758293995520)]} 0 1
[junit4:junit4] 2> 506622 T977 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1436958758299238400)]} 0 1
[junit4:junit4] 2> 506623 T946 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[39 (1436958758299238400)]} 0 5
[junit4:junit4] 2> 506625 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[40 (1436958758306578432)]} 0 0
[junit4:junit4] 2> 506634 T962 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1436958758310772736)]} 0 0
[junit4:junit4] 2> 506635 T929 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[40 (1436958758310772736)]} 0 6
[junit4:junit4] 2> 506639 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[41 (1436958758320209920)]} 0 1
[junit4:junit4] 2> 506648 T963 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1436958758325452800)]} 0 1
[junit4:junit4] 2> 506649 T927 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[41 (1436958758325452800)]} 0 6
[junit4:junit4] 2> 506653 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[42 (1436958758335938560)]} 0 1
[junit4:junit4] 2> 506664 T958 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1436958758344327168)]} 0 0
[junit4:junit4] 2> 506666 T930 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[42 (1436958758344327168)]} 0 5
[junit4:junit4] 2> 506667 T947 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[42]} 0 10
[junit4:junit4] 2> 506669 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[43 (1436958758352715776)]} 0 0
[junit4:junit4] 2> 506676 T960 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1436958758355861504)]} 0 0
[junit4:junit4] 2> 506677 T931 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[43 (1436958758355861504)]} 0 5
[junit4:junit4] 2> 506679 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[44 (1436958758363201536)]} 0 0
[junit4:junit4] 2> 506684 T959 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1436958758366347264)]} 0 0
[junit4:junit4] 2> 506685 T926 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[44 (1436958758366347264)]} 0 3
[junit4:junit4] 2> 506688 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[45 (1436958758371590144)]} 0 1
[junit4:junit4] 2> 506693 T978 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1436958758375784448)]} 0 0
[junit4:junit4] 2> 506694 T943 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[45 (1436958758375784448)]} 0 3
[junit4:junit4] 2> 506697 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[46 (1436958758382075904)]} 0 0
[junit4:junit4] 2> 506710 T961 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1436958758391513088)]} 0 1
[junit4:junit4] 2> 506711 T928 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1436958758391513088)]} 0 6
[junit4:junit4] 2> 506711 T942 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[46]} 0 11
[junit4:junit4] 2> 506715 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[47 (1436958758400950272)]} 0 0
[junit4:junit4] 2> 506727 T962 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1436958758409338880)]} 0 1
[junit4:junit4] 2> 506727 T929 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[47 (1436958758409338880)]} 0 6
[junit4:junit4] 2> 506731 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[48 (1436958758417727488)]} 0 1
[junit4:junit4] 2> 506740 T963 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1436958758421921792)]} 0 0
[junit4:junit4] 2> 506741 T927 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[48 (1436958758421921792)]} 0 6
[junit4:junit4] 2> 506745 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[49 (1436958758432407552)]} 0 0
[junit4:junit4] 2> 506757 T958 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1436958758440796160)]} 0 1
[junit4:junit4] 2> 506760 T930 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[49 (1436958758440796160)]} 0 7
[junit4:junit4] 2> 506766 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[50 (1436958758453379072)]} 0 1
[junit4:junit4] 2> 506778 T959 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1436958758461767680)]} 0 1
[junit4:junit4] 2> 506779 T926 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[50 (1436958758461767680)]} 0 6
[junit4:junit4] 2> 506779 T944 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[50]} 0 9
[junit4:junit4] 2> 506782 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[51 (1436958758471204864)]} 0 0
[junit4:junit4] 2> 506789 T961 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1436958758475399168)]} 0 0
[junit4:junit4] 2> 506790 T928 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[51 (1436958758475399168)]} 0 4
[junit4:junit4] 2> 506794 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[52 (1436958758483787776)]} 0 0
[junit4:junit4] 2> 506804 T962 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1436958758490079232)]} 0 1
[junit4:junit4] 2> 506804 T929 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[52 (1436958758490079232)]} 0 4
[junit4:junit4] 2> 506806 T946 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[52]} 0 8
[junit4:junit4] 2> 506810 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[53 (1436958758499516416)]} 0 1
[junit4:junit4] 2> 506819 T976 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1436958758504759296)]} 0 0
[junit4:junit4] 2> 506822 T947 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[53 (1436958758504759296)]} 0 8
[junit4:junit4] 2> 506826 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[54 (1436958758517342208)]} 0 1
[junit4:junit4] 2> 506837 T963 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1436958758523633664)]} 0 1
[junit4:junit4] 2> 506839 T927 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[54 (1436958758523633664)]} 0 8
[junit4:junit4] 2> 506844 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[55 (1436958758535168000)]} 0 1
[junit4:junit4] 2> 506859 T960 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1436958758546702336)]} 0 1
[junit4:junit4] 2> 506861 T931 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[55 (1436958758546702336)]} 0 7
[junit4:junit4] 2> 506864 T943 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[55]} 0 16
[junit4:junit4] 2> 506868 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[56 (1436958758561382400)]} 0 1
[junit4:junit4] 2> 506879 T980 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1436958758566625280)]} 0 2
[junit4:junit4] 2> 506881 T942 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[56 (1436958758566625280)]} 0 8
[junit4:junit4] 2> 506887 T906 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[57 (1436958758580256768)]} 0 1
[junit4:junit4] 2> 506902 T975 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1436958758591791104)]} 0 1
[junit4:junit4] 2> 506904 T945 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[57 (1436958758591791104)]} 0 7
[junit4:junit4] 2> 506905 T930 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[57]} 0 12
[junit4:junit4] 2> 506912 T907 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[58 (1436958758607519744)]} 0 2
[junit4:junit4] 2> 506922 T977 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1436958758613811200)]} 0 0
[junit4:junit4] 2> 506923 T944 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[58 (1436958758613811200)]} 0 6
[junit4:junit4] 2> 506928 T908 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[59 (1436958758624296960)]} 0 2
[junit4:junit4] 2> 506938 T958 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1436958758628491264)]} 0 1
[junit4:junit4] 2> 506940 T926 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[59 (1436958758628491264)]} 0 9
[junit4:junit4] 2> 506943 T909 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[60 (1436958758640025600)]} 0 0
[junit4:junit4] 2> 506954 T978 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1436958758645268480)]} 0 1
[junit4:junit4] 2> 506956 T946 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[60 (1436958758645268480)]} 0 8
[junit4:junit4] 2> 506961 T910 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[61 (1436958758658899968)]} 0 0
[junit4:junit4] 2> 506978 T959 C1969 P56042 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56024/jt/l/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1436958758671482880)]} 0 1
[junit4:junit4] 2> 506981 T928 C1970 P56024 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={distrib.from=http://127.0.0.1:56033/jt/l/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[61 (1436958758671482880)]} 0 9
[junit4:junit4] 2> 506983 T947 C1972 P56033 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[61]} 0 16
[junit4:junit4] 2> 506987 T911 C1971 P56012 oasup.LogUpdateProcessor.finish [collection1] webapp=/jt/l path=/update params={wt=javabin&version=2} {add=[62 (1436958758686162944)]} 0 1
[junit4:junit4] 2> 507004 T979 C1973 P56052 oasup.LogUpdateProcessor.finish [collection1] webapp
[...truncated too long message...]
rseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:56042_jt%2Fl_collection1_shard1_0_replica1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1_0",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":null,
[junit4:junit4] 2> "core":"collection1_shard1_0_replica1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:56042_jt%2Fl",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56042/jt/l"}
[junit4:junit4] 2> 547774 T984 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> 547809 T893 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 56052
[junit4:junit4] 2> 547809 T893 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1384755578
[junit4:junit4] 2> 548891 T893 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 548892 T893 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 548904 T893 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@56bf19cc
[junit4:junit4] 2> 548907 T893 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=286,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 548909 T893 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 548909 T893 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 548911 T893 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 548920 T893 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 548920 T893 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 548921 T893 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index;done=false>>]
[junit4:junit4] 2> 548921 T893 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\index
[junit4:junit4] 2> 548921 T893 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\ [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\;done=false>>]
[junit4:junit4] 2> 548921 T893 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669/jetty4\
[junit4:junit4] 2> 548923 T1042 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89809920438042636-127.0.0.1:56052_jt%2Fl-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 548931 T984 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> 548946 T893 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/jt/l,null}
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\zookeeper\server1\data\version-2\log.1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\zookeeper\server1\data\version-2 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\zookeeper\server1\data FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\zookeeper\server1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669\zookeeper FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370390631669 FAILED !!!!!
[junit4:junit4] 2> 549057 T893 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 549060 T893 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:56005 56005
[junit4:junit4] 2> 549098 T967 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 551488 T967 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 550334 T984 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 551492 T984 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 551494 T893 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 56012
[junit4:junit4] 2> 551512 T893 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 551513 T893 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:56005 56005
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=145A3F58FB755781 -Dtests.slow=true -Dtests.locale=be -Dtests.timezone=Europe/Simferopol -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 74.8s | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:56024/jt/l returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([145A3F58FB755781:95BCB1408C2A37BD]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 551526 T893 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene3x, sim=DefaultSimilarity, locale=be, timezone=Europe/Simferopol
[junit4:junit4] 2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=2,threads=1,free=20115888,total=175165440
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestSchemaNameResource, DateFieldTest, TestStressVersions, TestBM25SimilarityFactory, TestSystemIdResolver, TestIBSimilarityFactory, SyncSliceTest, TestSchemaVersionResource, JsonLoaderTest, SpellCheckComponentTest, CurrencyFieldXmlFileTest, ZkSolrClientTest, TestConfig, TermsComponentTest, TestCopyFieldCollectionResource, NotRequiredUniqueKeyTest, TermVectorComponentTest, ChaosMonkeySafeLeaderTest, SchemaVersionSpecificBehaviorTest, AlternateDirectoryTest, TestRandomDVFaceting, TestSolrJ, TestMergePolicyConfig, TestDynamicFieldCollectionResource, IndexReaderFactoryTest, DefaultValueUpdateProcessorTest, TestSolr4Spatial, TestPHPSerializedResponseWriter, ResourceLoaderTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed in 74.81s, 1 test, 1 error <<< FAILURES!
[...truncated 832 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:386: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:366: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:1243: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:887: There were test failures: 297 suites, 1238 tests, 1 error, 18 ignored (12 assumptions)
Total time: 67 minutes 25 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure