lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-4.x-Windows (64bit/jdk1.7.0_25) - Build # 2915 - Still Failing!
Date Fri, 21 Jun 2013 17:10:29 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Windows/2915/
Java: 64bit/jdk1.7.0_25 -XX:-UseCompressedOops -XX:+UseSerialGC

1 tests failed.
REGRESSION:  org.apache.solr.cloud.SyncSliceTest.testDistribSearch

Error Message:
shard1 is not consistent.  Got 305 from http://127.0.0.1:57282/collection1lastClient and got 261 from http://127.0.0.1:57301/collection1

Stack Trace:
java.lang.AssertionError: shard1 is not consistent.  Got 305 from http://127.0.0.1:57282/collection1lastClient and got 261 from http://127.0.0.1:57301/collection1
	at __randomizedtesting.SeedInfo.seed([676177279F0E4CF8:E687F93FE8512CC4]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
	at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	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:724)




Build Log:
[...truncated 9275 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4]   2> 163708 T394 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 163714 T394 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-SyncSliceTest-1371831935091
[junit4:junit4]   2> 163717 T394 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 163718 T395 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 163818 T394 oasc.ZkTestServer.run start zk server on port:57263
[junit4:junit4]   2> 163820 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 163838 T401 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@30f74da2 name:ZooKeeperConnection Watcher:127.0.0.1:57263 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 163838 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 163838 T394 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 163846 T396 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f678e207c0000, 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:724)
[junit4:junit4]   2> 
[junit4:junit4]   2> 163849 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 163852 T403 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13c57e38 name:ZooKeeperConnection Watcher:127.0.0.1:57263/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 163853 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 163853 T394 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 163859 T394 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 163865 T394 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 163870 T394 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 163876 T394 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> 163876 T394 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 163886 T394 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema.xml to /configs/conf1/schema.xml
[junit4:junit4]   2> 163886 T394 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 163896 T394 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> 163896 T394 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 163902 T394 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> 163903 T394 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 163908 T394 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> 163909 T394 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 163917 T394 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> 163917 T394 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 163923 T394 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> 163924 T394 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 163930 T394 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> 163930 T394 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 163936 T394 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> 163936 T394 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 163944 T396 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f678e207c0001, 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:724)
[junit4:junit4]   2> 
[junit4:junit4]   2> 164380 T394 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 164388 T394 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57270
[junit4:junit4]   2> 164388 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 164388 T394 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 164388 T394 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.SyncSliceTest-controljetty-1371831935318
[junit4:junit4]   2> 164389 T394 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.SyncSliceTest-controljetty-1371831935318\solr.xml
[junit4:junit4]   2> 164389 T394 oasc.CoreContainer.<init> New CoreContainer 998914099
[junit4:junit4]   2> 164390 T394 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.SyncSliceTest-controljetty-1371831935318\'
[junit4:junit4]   2> 164390 T394 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.SyncSliceTest-controljetty-1371831935318\'
[junit4:junit4]   2> 164520 T394 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 164521 T394 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 164521 T394 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 164522 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 164522 T394 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 164522 T394 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 164523 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 164523 T394 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 164523 T394 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 164524 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 164534 T394 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 164535 T394 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57263/solr
[junit4:junit4]   2> 164535 T394 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 164537 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 164556 T414 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7ecff012 name:ZooKeeperConnection Watcher:127.0.0.1:57263 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 164557 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 164563 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 164571 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 164581 T416 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c82f61c name:ZooKeeperConnection Watcher:127.0.0.1:57263/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 164581 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 164586 T394 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 164595 T394 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 164600 T394 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 164604 T394 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57270_
[junit4:junit4]   2> 164606 T394 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57270_
[junit4:junit4]   2> 164611 T394 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 164623 T394 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 164628 T394 oasc.Overseer.start Overseer (id=89904377698713603-127.0.0.1:57270_-n_0000000000) starting
[junit4:junit4]   2> 164636 T394 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 164644 T418 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 164646 T394 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 164649 T394 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 164653 T394 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 164659 T417 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 164662 T419 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 164662 T419 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 166169 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 166173 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57270_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57270"}
[junit4:junit4]   2> 166173 T417 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 166183 T417 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 166207 T416 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> 166665 T419 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.SyncSliceTest-controljetty-1371831935318\collection1
[junit4:junit4]   2> 166665 T419 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 166668 T419 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 166668 T419 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 166675 T419 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.SyncSliceTest-controljetty-1371831935318\collection1\'
[junit4:junit4]   2> 166678 T419 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371831935318/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 166679 T419 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371831935318/collection1/lib/README' to classloader
[junit4:junit4]   2> 166758 T419 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 166967 T3 oasc.CoreContainer.finalize ERROR CoreContainer was not shutdown prior to finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!!  instance=2023084316
[junit4:junit4]   2> 166983 T419 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 166986 T419 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 166995 T419 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 167663 T419 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 167665 T419 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 167665 T419 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 167676 T419 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 167680 T419 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 167705 T419 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 167710 T419 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 167716 T419 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 167718 T419 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 167718 T419 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 167719 T419 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 167722 T419 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 167722 T419 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 167722 T419 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 167753 T419 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.SyncSliceTest-controljetty-1371831935318\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/control/data\
[junit4:junit4]   2> 167753 T419 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@36bc6f46
[junit4:junit4]   2> 167762 T419 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 167763 T419 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\control\data
[junit4:junit4]   2> 167763 T419 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/control/data\index/
[junit4:junit4]   2> 167764 T419 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371831935089\control\data\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 167765 T419 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\control\data\index
[junit4:junit4]   2> 167774 T419 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@140de896; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 167775 T419 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 167779 T419 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 167780 T419 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 167780 T419 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 167782 T419 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 167782 T419 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 167782 T419 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 167783 T419 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 167783 T419 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 167784 T419 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 167794 T419 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 167803 T419 oass.SolrIndexSearcher.<init> Opening Searcher@123923e0 main
[junit4:junit4]   2> 167806 T419 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 167806 T419 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 167810 T420 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@123923e0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 167811 T419 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 167811 T419 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57270 collection:control_collection shard:shard1
[junit4:junit4]   2> 167813 T419 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 167830 T419 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 167836 T419 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 167836 T419 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 167836 T419 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57270/collection1/
[junit4:junit4]   2> 167836 T419 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 167836 T419 oasc.SyncStrategy.syncToMe http://127.0.0.1:57270/collection1/ has no replicas
[junit4:junit4]   2> 167837 T419 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57270/collection1/
[junit4:junit4]   2> 167837 T419 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 169227 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 169249 T416 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> 169278 T419 oasc.ZkController.register We are http://127.0.0.1:57270/collection1/ and leader is http://127.0.0.1:57270/collection1/
[junit4:junit4]   2> 169278 T419 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57270
[junit4:junit4]   2> 169278 T419 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 169278 T419 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 169278 T419 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 169283 T419 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 169285 T394 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 169285 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 169286 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 169299 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 169306 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 169310 T423 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5349f05d name:ZooKeeperConnection Watcher:127.0.0.1:57263/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 169310 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 169313 T394 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 169320 T394 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 169724 T394 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 169729 T394 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57282
[junit4:junit4]   2> 169730 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 169730 T394 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 169730 T394 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.SyncSliceTest-jetty1-1371831940695
[junit4:junit4]   2> 169730 T394 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.SyncSliceTest-jetty1-1371831940695\solr.xml
[junit4:junit4]   2> 169732 T394 oasc.CoreContainer.<init> New CoreContainer 655239937
[junit4:junit4]   2> 169732 T394 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.SyncSliceTest-jetty1-1371831940695\'
[junit4:junit4]   2> 169732 T394 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.SyncSliceTest-jetty1-1371831940695\'
[junit4:junit4]   2> 169848 T394 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 169849 T394 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 169849 T394 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 169850 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 169850 T394 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 169850 T394 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 169851 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 169851 T394 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 169851 T394 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 169852 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 169860 T394 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 169861 T394 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57263/solr
[junit4:junit4]   2> 169861 T394 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 169864 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 169879 T434 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1cf3f568 name:ZooKeeperConnection Watcher:127.0.0.1:57263 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 169880 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 169884 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 169884 T396 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f678e207c0005, 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:724)
[junit4:junit4]   2> 
[junit4:junit4]   2> 169896 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 169900 T436 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4b82998c name:ZooKeeperConnection Watcher:127.0.0.1:57263/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 169901 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 169910 T394 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 170765 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 170767 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57270__collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57270_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57270"}
[junit4:junit4]   2> 170784 T436 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> 170785 T416 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> 170785 T423 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> 170917 T394 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57282_
[junit4:junit4]   2> 170921 T394 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57282_
[junit4:junit4]   2> 170925 T436 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> 170926 T416 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 170927 T416 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> 170928 T423 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 170928 T423 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> 170931 T436 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 170939 T437 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 170940 T437 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 172303 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 172306 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57282_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57282"}
[junit4:junit4]   2> 172306 T417 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4]   2> 172306 T417 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 172337 T416 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> 172338 T436 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> 172338 T423 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> 172943 T437 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.SyncSliceTest-jetty1-1371831940695\collection1
[junit4:junit4]   2> 172943 T437 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 172945 T437 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 172945 T437 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 172951 T437 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.SyncSliceTest-jetty1-1371831940695\collection1\'
[junit4:junit4]   2> 172956 T437 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371831940695/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 172958 T437 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371831940695/collection1/lib/README' to classloader
[junit4:junit4]   2> 173034 T437 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 173108 T437 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 173111 T437 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 173118 T437 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 173784 T437 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 173785 T437 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 173785 T437 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 173796 T437 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 173799 T437 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 173829 T437 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 173835 T437 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 173840 T437 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 173843 T437 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 173843 T437 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 173843 T437 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 173845 T437 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 173845 T437 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 173845 T437 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 173846 T437 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.SyncSliceTest-jetty1-1371831940695\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/jetty1\
[junit4:junit4]   2> 173846 T437 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@36bc6f46
[junit4:junit4]   2> 173846 T437 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 173848 T437 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1
[junit4:junit4]   2> 173848 T437 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/jetty1\index/
[junit4:junit4]   2> 173849 T437 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 173849 T437 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index
[junit4:junit4]   2> 173860 T437 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 173860 T437 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 173863 T437 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 173863 T437 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 173864 T437 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 173865 T437 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 173865 T437 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 173865 T437 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 173866 T437 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 173867 T437 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 173867 T437 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 173876 T437 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 173886 T437 oass.SolrIndexSearcher.<init> Opening Searcher@c2e1e5e main
[junit4:junit4]   2> 173888 T437 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 173888 T437 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 173894 T438 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c2e1e5e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 173896 T437 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 173897 T437 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57282 collection:collection1 shard:shard1
[junit4:junit4]   2> 173898 T437 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 173915 T437 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 173923 T437 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 173923 T437 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 173923 T437 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57282/collection1/
[junit4:junit4]   2> 173924 T437 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 173924 T437 oasc.SyncStrategy.syncToMe http://127.0.0.1:57282/collection1/ has no replicas
[junit4:junit4]   2> 173924 T437 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57282/collection1/
[junit4:junit4]   2> 173925 T437 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 175443 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 175497 T416 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> 175498 T436 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> 175498 T423 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> 175511 T437 oasc.ZkController.register We are http://127.0.0.1:57282/collection1/ and leader is http://127.0.0.1:57282/collection1/
[junit4:junit4]   2> 175512 T437 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57282
[junit4:junit4]   2> 175512 T437 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 175514 T437 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 175515 T437 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 175524 T437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 175532 T394 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 175533 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 175535 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 175977 T394 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 175984 T394 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57291
[junit4:junit4]   2> 175986 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 175986 T394 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 175987 T394 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.SyncSliceTest-jetty2-1371831946921
[junit4:junit4]   2> 175987 T394 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.SyncSliceTest-jetty2-1371831946921\solr.xml
[junit4:junit4]   2> 175989 T394 oasc.CoreContainer.<init> New CoreContainer 1040765233
[junit4:junit4]   2> 175989 T394 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.SyncSliceTest-jetty2-1371831946921\'
[junit4:junit4]   2> 175989 T394 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.SyncSliceTest-jetty2-1371831946921\'
[junit4:junit4]   2> 176143 T394 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 176144 T394 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 176145 T394 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 176146 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 176147 T394 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 176147 T394 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 176148 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 176149 T394 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 176149 T394 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 176150 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 176162 T394 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 176163 T394 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57263/solr
[junit4:junit4]   2> 176163 T394 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 176166 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 176187 T450 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d4bc924 name:ZooKeeperConnection Watcher:127.0.0.1:57263 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 176187 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 176192 T396 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f678e207c0007, 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:724)
[junit4:junit4]   2> 
[junit4:junit4]   2> 176192 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 176201 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 176205 T452 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2a7e471a name:ZooKeeperConnection Watcher:127.0.0.1:57263/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 176206 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 176216 T394 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 177184 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 177187 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57282__collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57282_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57282"}
[junit4:junit4]   2> 177204 T452 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> 177205 T423 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> 177205 T436 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> 177205 T416 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> 177325 T394 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57291_
[junit4:junit4]   2> 177330 T394 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57291_
[junit4:junit4]   2> 177335 T452 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> 177336 T436 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> 177337 T423 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 177338 T423 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> 177339 T416 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 177339 T416 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> 177345 T436 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 177346 T452 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 177359 T453 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 177359 T453 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 178869 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 178871 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57291_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57291"}
[junit4:junit4]   2> 178871 T417 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 178871 T417 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 178887 T423 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> 178887 T452 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> 178887 T436 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> 178887 T416 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> 179563 T453 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.SyncSliceTest-jetty2-1371831946921\collection1
[junit4:junit4]   2> 179563 T453 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 179566 T453 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 179567 T453 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 179572 T453 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.SyncSliceTest-jetty2-1371831946921\collection1\'
[junit4:junit4]   2> 179576 T453 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371831946921/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 179595 T453 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371831946921/collection1/lib/README' to classloader
[junit4:junit4]   2> 179658 T453 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 179732 T453 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 179736 T453 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 179743 T453 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> 180499 T453 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 180501 T453 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 180501 T453 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 180518 T453 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 180522 T453 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 180551 T453 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 180557 T453 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 180563 T453 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 180566 T453 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 180566 T453 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 180566 T453 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 180568 T453 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 180568 T453 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 180568 T453 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 180569 T453 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.SyncSliceTest-jetty2-1371831946921\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/jetty2\
[junit4:junit4]   2> 180569 T453 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@36bc6f46
[junit4:junit4]   2> 180570 T453 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 180571 T453 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2
[junit4:junit4]   2> 180571 T453 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/jetty2\index/
[junit4:junit4]   2> 180573 T453 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 180574 T453 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index
[junit4:junit4]   2> 180584 T453 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ec2255; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 180585 T453 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 180590 T453 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 180590 T453 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 180591 T453 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 180592 T453 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 180592 T453 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 180592 T453 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 180593 T453 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 180593 T453 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 180595 T453 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 180608 T453 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 180623 T453 oass.SolrIndexSearcher.<init> Opening Searcher@29dc96ce main
[junit4:junit4]   2> 180627 T453 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 180627 T453 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 180642 T454 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@29dc96ce main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 180648 T453 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 180648 T453 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57291 collection:collection1 shard:shard1
[junit4:junit4]   2> 180683 T453 oasc.ZkController.register We are http://127.0.0.1:57291/collection1/ and leader is http://127.0.0.1:57282/collection1/
[junit4:junit4]   2> 180684 T453 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57291
[junit4:junit4]   2> 180684 T453 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 180684 T453 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C187 name=collection1 org.apache.solr.core.SolrCore@2a941c4e url=http://127.0.0.1:57291/collection1 node=127.0.0.1:57291_ C187_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:57291_, base_url=http://127.0.0.1:57291}
[junit4:junit4]   2> 180693 T455 C187 P57291 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 180695 T455 C187 P57291 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 180696 T453 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 180696 T455 C187 P57291 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 180696 T455 C187 P57291 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 180700 T394 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 180700 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 180701 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 180701 T455 C187 P57291 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 180723 T431 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:57291__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 181155 T394 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 181159 T394 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57301
[junit4:junit4]   2> 181161 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 181161 T394 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 181161 T394 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.SyncSliceTest-jetty3-1371831952088
[junit4:junit4]   2> 181162 T394 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.SyncSliceTest-jetty3-1371831952088\solr.xml
[junit4:junit4]   2> 181162 T394 oasc.CoreContainer.<init> New CoreContainer 1392687607
[junit4:junit4]   2> 181163 T394 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.SyncSliceTest-jetty3-1371831952088\'
[junit4:junit4]   2> 181163 T394 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.SyncSliceTest-jetty3-1371831952088\'
[junit4:junit4]   2> 181302 T394 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 181302 T394 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 181303 T394 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 181303 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 181304 T394 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 181304 T394 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 181304 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 181305 T394 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 181305 T394 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 181305 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 181315 T394 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 181316 T394 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57263/solr
[junit4:junit4]   2> 181316 T394 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 181318 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 181338 T467 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@287001ed name:ZooKeeperConnection Watcher:127.0.0.1:57263 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 181339 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 181344 T396 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f678e207c0009, 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:724)
[junit4:junit4]   2> 
[junit4:junit4]   2> 181344 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 181353 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 181358 T469 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@361e0c23 name:ZooKeeperConnection Watcher:127.0.0.1:57263/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 181358 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 181369 T394 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 182205 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 182210 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57291__collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[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:57291_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57291"}
[junit4:junit4]   2> 182232 T469 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> 182234 T423 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> 182236 T452 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> 182238 T436 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> 182242 T416 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> 182476 T394 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57301_
[junit4:junit4]   2> 182482 T394 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57301_
[junit4:junit4]   2> 182493 T436 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> 182493 T452 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> 182499 T416 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 182500 T416 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> 182502 T423 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 182505 T423 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> 182502 T469 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 182507 T469 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> 182516 T452 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 182518 T436 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 182544 T470 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 182545 T470 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 182924 T431 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:57291__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 182925 T431 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:57291__collection1&state=recovering&nodeName=127.0.0.1:57291_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2202 
[junit4:junit4]   2> 183910 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 183912 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57301_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57301"}
[junit4:junit4]   2> 183912 T417 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 183912 T417 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 183927 T469 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> 183928 T416 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> 183928 T423 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> 183928 T452 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> 183928 T436 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> 184750 T470 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.SyncSliceTest-jetty3-1371831952088\collection1
[junit4:junit4]   2> 184750 T470 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 184753 T470 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 184753 T470 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 184760 T470 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.SyncSliceTest-jetty3-1371831952088\collection1\'
[junit4:junit4]   2> 184764 T470 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371831952088/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 184764 T470 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371831952088/collection1/lib/README' to classloader
[junit4:junit4]   2> 184832 T470 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 184909 T470 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 184913 T470 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 184926 T470 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C188 name=collection1 org.apache.solr.core.SolrCore@2a941c4e url=http://127.0.0.1:57291/collection1 node=127.0.0.1:57291_ C188_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57291_, base_url=http://127.0.0.1:57291}
[junit4:junit4]   2> 185128 T455 C188 P57291 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:57282/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 185138 T455 C188 P57291 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4]   2> 185155 T455 C188 P57291 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57291 START replicas=[http://127.0.0.1:57282/collection1/] nUpdates=100
[junit4:junit4]   2> 185156 T455 C188 P57291 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 185157 T455 C188 P57291 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 185158 T455 C188 P57291 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 185159 T455 C188 P57291 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 185159 T455 C188 P57291 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 185159 T455 C188 P57291 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:57282/collection1/. core=collection1
[junit4:junit4]   2> 185159 T455 C188 P57291 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C189 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C189_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 185183 T432 C189 P57282 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1 
[junit4:junit4]   2> ASYNC  NEW_CORE C190 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C190_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 185233 T432 C190 P57282 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 185241 T432 C190 P57282 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 185242 T432 C190 P57282 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 185253 T432 C190 P57282 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 185253 T432 C190 P57282 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 185257 T432 C190 P57282 oass.SolrIndexSearcher.<init> Opening Searcher@6ea37e0d realtime
[junit4:junit4]   2> 185257 T432 C190 P57282 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 185258 T432 C190 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 72
[junit4:junit4]   2> ASYNC  NEW_CORE C191 name=collection1 org.apache.solr.core.SolrCore@2a941c4e url=http://127.0.0.1:57291/collection1 node=127.0.0.1:57291_ C191_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57291_, base_url=http://127.0.0.1:57291}
[junit4:junit4]   2> 185345 T455 C191 P57291 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 185346 T455 C191 P57291 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4]   2> 185362 T455 C191 P57291 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> ASYNC  NEW_CORE C192 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C192_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 185368 T429 C192 P57282 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 185369 T429 C192 P57282 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2 
[junit4:junit4]   2> 185370 T455 C191 P57291 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 185371 T455 C191 P57291 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 185372 T455 C191 P57291 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> ASYNC  NEW_CORE C193 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C193_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 185384 T430 C193 P57282 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=2 
[junit4:junit4]   2> ASYNC  NEW_CORE C194 name=collection1 org.apache.solr.core.SolrCore@2a941c4e url=http://127.0.0.1:57291/collection1 node=127.0.0.1:57291_ C194_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57291_, base_url=http://127.0.0.1:57291}
[junit4:junit4]   2> 185385 T455 C194 P57291 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 185388 T455 C194 P57291 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index.20130621212556762
[junit4:junit4]   2> 185389 T455 C194 P57291 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index.20130621212556762 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ea1bf09; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4]   2> 185404 T431 C193 P57282 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=4 
[junit4:junit4]   2> 185420 T455 C194 P57291 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 185427 T455 C194 P57291 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 185427 T455 C194 P57291 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C195 name=collection1 org.apache.solr.core.SolrCore@2a941c4e url=http://127.0.0.1:57291/collection1 node=127.0.0.1:57291_ C195_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57291_, base_url=http://127.0.0.1:57291}
[junit4:junit4]   2> 185446 T455 C195 P57291 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ec2255; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ec2255; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 185447 T455 C195 P57291 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 185447 T455 C195 P57291 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 185450 T455 C195 P57291 oass.SolrIndexSearcher.<init> Opening Searcher@3e1bbe6f main
[junit4:junit4]   2> 185452 T454 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3e1bbe6f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 185453 T455 C195 P57291 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index.20130621212556762 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index.20130621212556762;done=true>>]
[junit4:junit4]   2> 185453 T455 C195 P57291 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index.20130621212556762
[junit4:junit4]   2> 185453 T455 C195 P57291 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index.20130621212556762
[junit4:junit4]   2> 185455 T455 C195 P57291 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 185456 T455 C195 P57291 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 185456 T455 C195 P57291 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 185456 T455 C195 P57291 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 185460 T455 C195 P57291 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 185590 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 185594 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57291__collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57291_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57291"}
[junit4:junit4]   2> 185610 T416 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> 185611 T469 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> 185611 T452 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> 185611 T436 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> 185612 T423 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> 185818 T470 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 185818 T470 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 185820 T470 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 185830 T470 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 185834 T470 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 185865 T470 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 185882 T470 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 185886 T470 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 185889 T470 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 185889 T470 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 185890 T470 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 185892 T470 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 185892 T470 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 185892 T470 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 185893 T470 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.SyncSliceTest-jetty3-1371831952088\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/jetty3\
[junit4:junit4]   2> 185893 T470 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@36bc6f46
[junit4:junit4]   2> 185894 T470 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 185894 T470 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3
[junit4:junit4]   2> 185896 T470 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/jetty3\index/
[junit4:junit4]   2> 185897 T470 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 185897 T470 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index
[junit4:junit4]   2> 185908 T470 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6820e9ae; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 185908 T470 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 185912 T470 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 185912 T470 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 185912 T470 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 185913 T470 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 185914 T470 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 185914 T470 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 185929 T470 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 185930 T470 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 185930 T470 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 185941 T470 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 185949 T470 oass.SolrIndexSearcher.<init> Opening Searcher@8f81e9 main
[junit4:junit4]   2> 185951 T470 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 185951 T470 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 185957 T473 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8f81e9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 185959 T470 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 185960 T470 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57301 collection:collection1 shard:shard1
[junit4:junit4]   2> 185967 T470 oasc.ZkController.register We are http://127.0.0.1:57301/collection1/ and leader is http://127.0.0.1:57282/collection1/
[junit4:junit4]   2> 185967 T470 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57301
[junit4:junit4]   2> 185967 T470 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 185967 T470 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C196 name=collection1 org.apache.solr.core.SolrCore@de68f9e url=http://127.0.0.1:57301/collection1 node=127.0.0.1:57301_ C196_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:57301_, base_url=http://127.0.0.1:57301}
[junit4:junit4]   2> 185968 T474 C196 P57301 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 185970 T474 C196 P57301 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 185970 T474 C196 P57301 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 185970 T474 C196 P57301 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 185970 T470 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 185972 T474 C196 P57301 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 185974 T394 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 185975 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 185975 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 185986 T432 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:57301__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 186370 T394 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4]   2> 186377 T394 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57314
[junit4:junit4]   2> 186379 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 186379 T394 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 186379 T394 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.SyncSliceTest-jetty4-1371831957357
[junit4:junit4]   2> 186380 T394 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.SyncSliceTest-jetty4-1371831957357\solr.xml
[junit4:junit4]   2> 186380 T394 oasc.CoreContainer.<init> New CoreContainer 127172800
[junit4:junit4]   2> 186380 T394 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.SyncSliceTest-jetty4-1371831957357\'
[junit4:junit4]   2> 186380 T394 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.SyncSliceTest-jetty4-1371831957357\'
[junit4:junit4]   2> 186504 T394 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 186504 T394 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 186505 T394 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 186505 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 186506 T394 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 186506 T394 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 186507 T394 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 186507 T394 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 186507 T394 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 186509 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 186520 T394 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4]   2> 186520 T394 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57263/solr
[junit4:junit4]   2> 186521 T394 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 186523 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 186537 T486 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5ea3980 name:ZooKeeperConnection Watcher:127.0.0.1:57263 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 186538 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 186542 T396 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f678e207c000b, 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:724)
[junit4:junit4]   2> 
[junit4:junit4]   2> 186542 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 186551 T394 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 186556 T488 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4f28847 name:ZooKeeperConnection Watcher:127.0.0.1:57263/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 186557 T394 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 186565 T394 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 187108 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 187109 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57301__collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[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:57301_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57301"}
[junit4:junit4]   2> 187124 T469 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> 187125 T488 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> 187125 T423 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> 187128 T436 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> 187128 T452 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> 187129 T416 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> 187561 T394 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57314_
[junit4:junit4]   2> 187568 T394 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57314_
[junit4:junit4]   2> 187579 T488 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> 187579 T452 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> 187581 T469 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 187581 T469 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> 187579 T436 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> 187582 T423 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 187582 T423 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> 187583 T416 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 187583 T416 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> 187590 T452 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 187590 T488 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 187591 T436 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 187599 T489 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 187599 T489 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 187966 T432 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:57301__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 187966 T432 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:57301__collection1&state=recovering&nodeName=127.0.0.1:57301_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1980 
[junit4:junit4]   2> 188626 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 188629 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57314_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57314"}
[junit4:junit4]   2> 188629 T417 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4]   2> 188629 T417 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4]   2> 188644 T469 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> 188644 T488 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> 188645 T416 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> 188645 T423 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> 188646 T452 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> 188646 T436 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> 189583 T489 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.SyncSliceTest-jetty4-1371831957357\collection1
[junit4:junit4]   2> 189583 T489 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 189587 T489 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 189587 T489 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 189592 T489 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.SyncSliceTest-jetty4-1371831957357\collection1\'
[junit4:junit4]   2> 189596 T489 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371831957357/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 189598 T489 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371831957357/collection1/lib/README' to classloader
[junit4:junit4]   2> 189669 T489 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4]   2> 189738 T489 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 189741 T489 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4]   2> 189748 T489 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C197 name=collection1 org.apache.solr.core.SolrCore@de68f9e url=http://127.0.0.1:57301/collection1 node=127.0.0.1:57301_ C197_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57301_, base_url=http://127.0.0.1:57301}
[junit4:junit4]   2> 189947 T474 C197 P57301 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:57282/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 189947 T474 C197 P57301 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57301 START replicas=[http://127.0.0.1:57282/collection1/] nUpdates=100
[junit4:junit4]   2> 189948 T474 C197 P57301 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 189950 T474 C197 P57301 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 189951 T474 C197 P57301 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 189951 T474 C197 P57301 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 189951 T474 C197 P57301 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 189951 T474 C197 P57301 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:57282/collection1/. core=collection1
[junit4:junit4]   2> 189952 T474 C197 P57301 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C198 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C198_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 189960 T429 C198 P57282 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 189969 T430 C198 P57282 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> ASYNC  NEW_CORE C199 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C199_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 190025 T430 C199 P57282 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 190025 T430 C199 P57282 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 190028 T430 C199 P57282 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 190028 T430 C199 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 60
[junit4:junit4]   2> ASYNC  NEW_CORE C200 name=collection1 org.apache.solr.core.SolrCore@de68f9e url=http://127.0.0.1:57301/collection1 node=127.0.0.1:57301_ C200_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57301_, base_url=http://127.0.0.1:57301}
[junit4:junit4]   2> 190030 T474 C200 P57301 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 190031 T474 C200 P57301 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 190038 T427 C199 P57282 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 190039 T474 C200 P57301 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4]   2> 190039 T474 C200 P57301 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 190039 T474 C200 P57301 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 190053 T428 C199 P57282 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=11 
[junit4:junit4]   2> 190054 T474 C200 P57301 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 190056 T474 C200 P57301 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index.20130621212601430
[junit4:junit4]   2> 190058 T474 C200 P57301 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index.20130621212601430 lockFactory=org.apache.lucene.store.NativeFSLockFactory@49dfce80; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4]   2> ASYNC  NEW_CORE C201 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C201_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 190069 T429 C201 P57282 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=1 
[junit4:junit4]   2> ASYNC  NEW_CORE C202 name=collection1 org.apache.solr.core.SolrCore@de68f9e url=http://127.0.0.1:57301/collection1 node=127.0.0.1:57301_ C202_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57301_, base_url=http://127.0.0.1:57301}
[junit4:junit4]   2> 190072 T474 C202 P57301 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> ASYNC  NEW_CORE C203 name=collection1 org.apache.solr.core.SolrCore@de68f9e url=http://127.0.0.1:57301/collection1 node=127.0.0.1:57301_ C203_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57301_, base_url=http://127.0.0.1:57301}
[junit4:junit4]   2> 190186 T474 C203 P57301 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 190187 T474 C203 P57301 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 190193 T474 C203 P57301 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6820e9ae; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6820e9ae; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 190195 T474 C203 P57301 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 190196 T474 C203 P57301 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 190198 T474 C203 P57301 oass.SolrIndexSearcher.<init> Opening Searcher@16115bef main
[junit4:junit4]   2> 190210 T473 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16115bef main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4]   2> 190211 T474 C203 P57301 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index.20130621212601430 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index.20130621212601430;done=true>>]
[junit4:junit4]   2> 190212 T474 C203 P57301 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index.20130621212601430
[junit4:junit4]   2> 190212 T474 C203 P57301 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index.20130621212601430
[junit4:junit4]   2> 190213 T474 C203 P57301 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 190213 T474 C203 P57301 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 190214 T474 C203 P57301 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 190214 T474 C203 P57301 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 190218 T474 C203 P57301 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 190221 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 190222 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57301__collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57301_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57301"}
[junit4:junit4]   2> 190234 T488 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> 190234 T416 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> 190235 T436 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> 190236 T452 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> 190236 T469 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> 190237 T423 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> 190495 T489 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 190497 T489 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4]   2> 190498 T489 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 190510 T489 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 190513 T489 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 190542 T489 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 190554 T489 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 190560 T489 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 190562 T489 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 190562 T489 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 190562 T489 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 190564 T489 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 190564 T489 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4]   2> 190564 T489 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 190565 T489 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.SyncSliceTest-jetty4-1371831957357\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/jetty4\
[junit4:junit4]   2> 190565 T489 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@36bc6f46
[junit4:junit4]   2> 190566 T489 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4]   2> 190567 T489 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4
[junit4:junit4]   2> 190567 T489 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371831935089/jetty4\index/
[junit4:junit4]   2> 190568 T489 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4]   2> 190569 T489 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index
[junit4:junit4]   2> 190578 T489 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2731ef5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 190578 T489 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 190582 T489 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 190582 T489 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 190583 T489 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 190584 T489 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 190584 T489 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 190584 T489 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 190589 T489 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 190590 T489 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 190590 T489 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 190600 T489 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 190610 T489 oass.SolrIndexSearcher.<init> Opening Searcher@727efb8d main
[junit4:junit4]   2> 190612 T489 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 190612 T489 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 190617 T492 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@727efb8d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 190620 T489 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 190620 T489 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57314 collection:collection1 shard:shard1
[junit4:junit4]   2> 190628 T489 oasc.ZkController.register We are http://127.0.0.1:57314/collection1/ and leader is http://127.0.0.1:57282/collection1/
[junit4:junit4]   2> 190628 T489 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57314
[junit4:junit4]   2> 190628 T489 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 190629 T489 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C204 name=collection1 org.apache.solr.core.SolrCore@1f2c3a40 url=http://127.0.0.1:57314/collection1 node=127.0.0.1:57314_ C204_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:57314_, base_url=http://127.0.0.1:57314}
[junit4:junit4]   2> 190630 T493 C204 P57314 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 190631 T493 C204 P57314 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 190631 T493 C204 P57314 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 190631 T493 C204 P57314 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 190632 T489 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 190634 T493 C204 P57314 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 190636 T394 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4]   2> 190636 T394 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 190636 T394 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 190651 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 190654 T394 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4]   2> 190654 T394 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4]   2> 190656 T430 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:57314__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4]   2> 190656 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 191649 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 191765 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 191766 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57314__collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[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:57314_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57314"}
[junit4:junit4]   2> 191793 T469 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> 191794 T423 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> 191794 T488 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> 191795 T416 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> 191796 T436 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> 191796 T452 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> 192636 T430 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:57314__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4]   2> 192637 T430 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:57314__collection1&state=recovering&nodeName=127.0.0.1:57314_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1982 
[junit4:junit4]   2> 192644 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 193638 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> ASYNC  NEW_CORE C205 name=collection1 org.apache.solr.core.SolrCore@1f2c3a40 url=http://127.0.0.1:57314/collection1 node=127.0.0.1:57314_ C205_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:57314_, base_url=http://127.0.0.1:57314}
[junit4:junit4]   2> 194619 T493 C205 P57314 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:57282/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 194619 T493 C205 P57314 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:57314 START replicas=[http://127.0.0.1:57282/collection1/] nUpdates=100
[junit4:junit4]   2> 194620 T493 C205 P57314 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 194620 T493 C205 P57314 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 194620 T493 C205 P57314 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 194621 T493 C205 P57314 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 194621 T493 C205 P57314 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 194622 T493 C205 P57314 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:57282/collection1/. core=collection1
[junit4:junit4]   2> 194622 T493 C205 P57314 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C206 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C206_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 194624 T427 C206 P57282 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0 
[junit4:junit4]   2> 194632 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 194642 T430 C206 P57282 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 194666 T430 C206 P57282 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4]   2> 194667 T430 C206 P57282 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4]   2> 194671 T430 C206 P57282 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 194671 T430 C206 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 29
[junit4:junit4]   2> 194672 T493 C205 P57314 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 194672 T493 C205 P57314 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 194677 T432 C206 P57282 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0 
[junit4:junit4]   2> 194678 T493 C205 P57314 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4]   2> 194678 T493 C205 P57314 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 194678 T493 C205 P57314 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 194684 T431 C206 P57282 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=3 
[junit4:junit4]   2> 194686 T493 C205 P57314 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 194688 T493 C205 P57314 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index.20130621212606061
[junit4:junit4]   2> 194689 T493 C205 P57314 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index.20130621212606061 lockFactory=org.apache.lucene.store.NativeFSLockFactory@711ee528; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4]   2> 194695 T427 C206 P57282 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=1 
[junit4:junit4]   2> 194697 T493 C205 P57314 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 194702 T493 C205 P57314 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 194702 T493 C205 P57314 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 194707 T493 C205 P57314 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2731ef5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2731ef5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4]   2> 194709 T493 C205 P57314 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4]   2> 194710 T493 C205 P57314 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 194712 T493 C205 P57314 oass.SolrIndexSearcher.<init> Opening Searcher@513b3976 main
[junit4:junit4]   2> 194713 T492 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@513b3976 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4]   2> 194715 T493 C205 P57314 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index.20130621212606061 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index.20130621212606061;done=true>>]
[junit4:junit4]   2> 194715 T493 C205 P57314 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index.20130621212606061
[junit4:junit4]   2> 194715 T493 C205 P57314 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index.20130621212606061
[junit4:junit4]   2> 194716 T493 C205 P57314 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 194717 T493 C205 P57314 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 194717 T493 C205 P57314 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 194717 T493 C205 P57314 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 194720 T493 C205 P57314 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 194794 T417 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 194797 T417 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:57314__collection1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "shard_state":"active",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "shard_range":null,
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:57314_",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:57314"}
[junit4:junit4]   2> 194818 T469 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> 194819 T488 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> 194820 T416 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> 194819 T423 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> 194822 T436 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> 194822 T452 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> 195612 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 195615 T394 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4]   2> ASYNC  NEW_CORE C207 name=collection1 org.apache.solr.core.SolrCore@160e6784 url=http://127.0.0.1:57270/collection1 node=127.0.0.1:57270_ C207_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:57270_, base_url=http://127.0.0.1:57270, leader=true}
[junit4:junit4]   2> 195640 T408 C207 P57270 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 195646 T408 C207 P57270 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@140de896; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 195647 T408 C207 P57270 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4]   2> 195657 T408 C207 P57270 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@140de896; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@140de896; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 195657 T408 C207 P57270 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4]   2> 195663 T408 C207 P57270 oass.SolrIndexSearcher.<init> Opening Searcher@79079b7a main
[junit4:junit4]   2> 195664 T408 C207 P57270 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 195665 T420 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@79079b7a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 195666 T408 C207 P57270 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 26
[junit4:junit4]   2> ASYNC  NEW_CORE C208 name=collection1 org.apache.solr.core.SolrCore@2a941c4e url=http://127.0.0.1:57291/collection1 node=127.0.0.1:57291_ C208_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57291_, base_url=http://127.0.0.1:57291}
[junit4:junit4]   2> 195697 T448 C208 P57291 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:57282/collection1/, StdNode: http://127.0.0.1:57291/collection1/, StdNode: http://127.0.0.1:57301/collection1/, StdNode: http://127.0.0.1:57314/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> 195709 T430 C206 P57282 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> ASYNC  NEW_CORE C209 name=collection1 org.apache.solr.core.SolrCore@2a941c4e url=http://127.0.0.1:57291/collection1 node=127.0.0.1:57291_ C209_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57291_, base_url=http://127.0.0.1:57291}
[junit4:junit4]   2> 195722 T444 C209 P57291 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 195732 T444 C209 P57291 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ec2255; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ec2255; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 195732 T444 C209 P57291 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> ASYNC  NEW_CORE C210 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C210_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 195732 T430 C210 P57282 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4]   2> 195734 T430 C210 P57282 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4]   2> 195736 T444 C209 P57291 oass.SolrIndexSearcher.<init> Opening Searcher@5aae535d main
[junit4:junit4]   2> 195736 T444 C209 P57291 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 195737 T454 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5aae535d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 195738 T444 C209 P57291 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 28
[junit4:junit4]   2> 195739 T430 C210 P57282 oass.SolrIndexSearcher.<init> Opening Searcher@68ab1c2d main
[junit4:junit4]   2> 195739 T430 C210 P57282 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 195740 T438 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@68ab1c2d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 195740 T430 C210 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 31
[junit4:junit4]   2> ASYNC  NEW_CORE C211 name=collection1 org.apache.solr.core.SolrCore@de68f9e url=http://127.0.0.1:57301/collection1 node=127.0.0.1:57301_ C211_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57301_, base_url=http://127.0.0.1:57301}
[junit4:junit4]   2> 195742 T464 C211 P57301 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> ASYNC  NEW_CORE C212 name=collection1 org.apache.solr.core.SolrCore@1f2c3a40 url=http://127.0.0.1:57314/collection1 node=127.0.0.1:57314_ C212_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57314_, base_url=http://127.0.0.1:57314}
[junit4:junit4]   2> 195744 T484 C212 P57314 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 195753 T464 C211 P57301 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6820e9ae; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6820e9ae; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4]   2> 195753 T464 C211 P57301 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4]   2> 195753 T484 C212 P57314 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2731ef5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2731ef5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4]   2> 195753 T484 C212 P57314 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4]   2> 195756 T464 C211 P57301 oass.SolrIndexSearcher.<init> Opening Searcher@5887abd8 main
[junit4:junit4]   2> 195756 T464 C211 P57301 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 195757 T473 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5887abd8 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4]   2> 195760 T464 C211 P57301 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 18
[junit4:junit4]   2> 195761 T484 C212 P57314 oass.SolrIndexSearcher.<init> Opening Searcher@4cc2947e main
[junit4:junit4]   2> 195761 T484 C212 P57314 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 195762 T492 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4cc2947e main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4]   2> 195763 T484 C212 P57314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4]   2> 195764 T448 C209 P57291 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 68
[junit4:junit4]   2> 195766 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 195770 T432 C210 P57282 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1 
[junit4:junit4]   2> 195773 T443 C209 P57291 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 195778 T460 C211 P57301 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> 195781 T480 C212 P57314 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0 
[junit4:junit4]   2> ASYNC  NEW_CORE C213 name=collection1 org.apache.solr.core.SolrCore@160e6784 url=http://127.0.0.1:57270/collection1 node=127.0.0.1:57270_ C213_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:57270_, base_url=http://127.0.0.1:57270, leader=true}
[junit4:junit4]   2> 197582 T411 C213 P57270 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438470078672666624)} 0 14
[junit4:junit4]   2> 197615 T465 C211 P57301 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438470078696783872&update.from=http://127.0.0.1:57282/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438470078696783872)} 0 5
[junit4:junit4]   2> 197627 T448 C209 P57291 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438470078696783872&update.from=http://127.0.0.1:57282/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438470078696783872)} 0 6
[junit4:junit4]   2> 197629 T479 C212 P57314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438470078696783872&update.from=http://127.0.0.1:57282/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438470078696783872)} 0 5
[junit4:junit4]   2> 197631 T429 C210 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438470078696783872)} 0 35
[junit4:junit4]   2> 197632 T444 C209 P57291 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 48
[junit4:junit4]   2> 197640 T407 C213 P57270 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438470078736629760)]} 0 5
[junit4:junit4]   2> 197669 T443 C209 P57291 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57282/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438470078760747008)]} 0 3
[junit4:junit4]   2> 197672 T464 C211 P57301 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57282/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438470078760747008)]} 0 6
[junit4:junit4]   2> 197675 T480 C212 P57314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57282/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438470078760747008)]} 0 7
[junit4:junit4]   2> 197675 T430 C210 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57314/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1438470078760747008)]} 0 17
[junit4:junit4]   2> 197676 T484 C212 P57314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 33
[junit4:junit4]   2> 197682 T408 C213 P57270 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438470078783815680)]} 0 2
[junit4:junit4]   2> 197695 T460 C211 P57301 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57282/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438470078792204288)]} 0 3
[junit4:junit4]   2> 197698 T481 C212 P57314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57282/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438470078792204288)]} 0 6
[junit4:junit4]   2> 197700 T446 C209 P57291 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57282/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438470078792204288)]} 0 5
[junit4:junit4]   2> 197701 T432 C210 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57291/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1438470078792204288)]} 0 13
[junit4:junit4]   2> 197702 T445 C209 P57291 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 18
[junit4:junit4]   2> 197709 T409 C213 P57270 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438470078811078656)]} 0 4
[junit4:junit4]   2> 197715 T431 C210 P57282 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:57291/collection1/]
[junit4:junit4]   2> 197716 T431 C210 P57282 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:57291/collection1/ against:[http://127.0.0.1:57291/collection1/] result:true
[junit4:junit4]   2> 197716 T431 C210 P57282 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:57301/collection1/ against:[http://127.0.0.1:57291/collection1/] result:false
[junit4:junit4]   2> 197716 T431 C210 P57282 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:57314/collection1/ against:[http://127.0.0.1:57291/collection1/] result:false
[junit4:junit4]   2> 197728 T461 C211 P57301 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57282/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:57291/collection1/&wt=javabin&version=2} {add=[2 (1438470078821564416)]} 0 6
[junit4:junit4]   2> 197729 T482 C212 P57314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57282/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:57291/collection1/&wt=javabin&version=2} {add=[2 (1438470078821564416)]} 0 2
[junit4:junit4]   2> 197729 T431 C210 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57291/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:57291/collection1/&wt=javabin&version=2} {add=[2 (1438470078821564416)]} 0 14
[junit4:junit4]   2> 197729 T447 C209 P57291 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:57291/collection1/&wt=javabin&version=2} {add=[2]} 0 17
[junit4:junit4]   2> 197739 T410 C213 P57270 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438470078842535936)]} 0 3
[junit4:junit4]   2> 197748 T427 C210 P57282 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:57291/collection1/, http://127.0.0.1:57301/collection1/]
[junit4:junit4]   2> 197748 T427 C210 P57282 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:57291/collection1/ against:[http://127.0.0.1:57291/collection1/, http://127.0.0.1:57301/collection1/] result:true
[junit4:junit4]   2> 197749 T427 C210 P57282 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:57301/collection1/ against:[http://127.0.0.1:57291/collection1/, http://127.0.0.1:57301/collection1/] result:true
[junit4:junit4]   2> 197749 T427 C210 P57282 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:57314/collection1/ against:[http://127.0.0.1:57291/collection1/, http://127.0.0.1:57301/collection1/] result:false
[junit4:junit4]   2> 197760 T483 C212 P57314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57282/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:57291/collection1/&wt=javabin&version=2} {add=[3 (1438470078856167424)]} 0 6
[junit4:junit4]   2> 197762 T427 C210 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:57291/collection1/&test.distrib.skip.servers=http://127.0.0.1:57301/collection1/&wt=javabin&version=2} {add=[3 (1438470078856167424)]} 0 15
[junit4:junit4]   2> 197768 T412 C213 P57270 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 197853 T412 C213 P57270 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@140de896; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@140de896; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 197853 T412 C213 P57270 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4]   2> 197870 T412 C213 P57270 oass.SolrIndexSearcher.<init> Opening Searcher@73fb47e7 main
[junit4:junit4]   2> 197871 T412 C213 P57270 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 197872 T420 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@73fb47e7 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):C4)}
[junit4:junit4]   2> 197873 T412 C213 P57270 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 106
[junit4:junit4]   2> 197876 T479 C212 P57314 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:57282/collection1/, StdNode: http://127.0.0.1:57291/collection1/, StdNode: http://127.0.0.1:57301/collection1/, StdNode: http://127.0.0.1:57314/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4]   2> 197880 T428 C210 P57282 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 197888 T448 C209 P57291 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 197889 T480 C212 P57314 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 197889 T462 C211 P57301 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> ASYNC  NEW_CORE C214 name=collection1 org.apache.solr.core.SolrCore@7465364 url=http://127.0.0.1:57282/collection1 node=127.0.0.1:57282_ C214_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57282_, base_url=http://127.0.0.1:57282, leader=true}
[junit4:junit4]   2> 198006 T428 C214 P57282 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15944165; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4]   2> 198007 T428 C214 P57282 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4]   2> 198018 T428 C214 P57282 oass.SolrIndexSearcher.<init> Opening Searcher@44288c6d main
[junit4:junit4]   2> 198019 T428 C214 P57282 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> ASYNC  NEW_CORE C215 name=collection1 org.apache.solr.core.SolrCore@2a941c4e url=http://127.0.0.1:57291/collection1 node=127.0.0.1:57291_ C215_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57291_, base_url=http://127.0.0.1:57291}
[junit4:junit4]   2> 198020 T448 C215 P57291 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ec2255; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ec2255; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4]   2> 198021 T448 C215 P57291 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4]   2> ASYNC  NEW_CORE C216 name=collection1 org.apache.solr.core.SolrCore@1f2c3a40 url=http://127.0.0.1:57314/collection1 node=127.0.0.1:57314_ C216_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57314_, base_url=http://127.0.0.1:57314}
[junit4:junit4]   2> 198021 T480 C216 P57314 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2731ef5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@2731ef5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4]   2> 198022 T480 C216 P57314 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4]   2> 198030 T448 C215 P57291 oass.SolrIndexSearcher.<init> Opening Searcher@7bcb6cdd main
[junit4:junit4]   2> 198030 T448 C215 P57291 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 198032 T480 C216 P57314 oass.SolrIndexSearcher.<init> Opening Searcher@6e64f905 main
[junit4:junit4]   2> 198033 T438 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@44288c6d main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):C4)}
[junit4:junit4]   2> 198033 T480 C216 P57314 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 198033 T428 C214 P57282 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 153
[junit4:junit4]   2> 198035 T454 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7bcb6cdd main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):C2)}
[junit4:junit4]   2> 198036 T448 C215 P57291 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 148
[junit4:junit4]   2> 198037 T492 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6e64f905 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):C4)}
[junit4:junit4]   2> 198037 T480 C216 P57314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 149
[junit4:junit4]   2> ASYNC  NEW_CORE C217 name=collection1 org.apache.solr.core.SolrCore@de68f9e url=http://127.0.0.1:57301/collection1 node=127.0.0.1:57301_ C217_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57301_, base_url=http://127.0.0.1:57301}
[junit4:junit4]   2> 198042 T462 C217 P57301 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6820e9ae; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4]   2> 		commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371831935089\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6820e9ae; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4]   2> 198042 T462 C217 P57301 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4]   2> 198052 T462 C217 P57301 oass.SolrIndexSearcher.<init> Opening Searcher@169cc168 main
[junit4:junit4]   2> 198052 T462 C217 P57301 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 198053 T473 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@169cc168 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):C3)}
[junit4:junit4]   2> 198054 T462 C217 P57301 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 165
[junit4:junit4]   2> 198054 T479 C216 P57314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 178
[junit4:junit4]   2> 198055 T394 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 198056 T394 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 

[...truncated too long message...]

4]   1>                   "state":"down",
[junit4:junit4]   1>                   "core":"collection1",
[junit4:junit4]   1>                   "collection":"collection1",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:57291_",
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:57291"},
[junit4:junit4]   1>                 "127.0.0.1:57301__collection1":{
[junit4:junit4]   1>                   "shard":"shard1",
[junit4:junit4]   1>                   "state":"active",
[junit4:junit4]   1>                   "core":"collection1",
[junit4:junit4]   1>                   "collection":"collection1",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:57301_",
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:57301"},
[junit4:junit4]   1>                 "127.0.0.1:57314__collection1":{
[junit4:junit4]   1>                   "shard":"shard1",
[junit4:junit4]   1>                   "state":"active",
[junit4:junit4]   1>                   "core":"collection1",
[junit4:junit4]   1>                   "collection":"collection1",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:57314_",
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:57314",
[junit4:junit4]   1>                   "leader":"true"}}}},
[junit4:junit4]   1>           "router":"compositeId"},
[junit4:junit4]   1>         "control_collection":{
[junit4:junit4]   1>           "shards":{"shard1":{
[junit4:junit4]   1>               "range":"80000000-7fffffff",
[junit4:junit4]   1>               "state":"active",
[junit4:junit4]   1>               "replicas":{"127.0.0.1:57270__collection1":{
[junit4:junit4]   1>                   "shard":"shard1",
[junit4:junit4]   1>                   "state":"active",
[junit4:junit4]   1>                   "core":"collection1",
[junit4:junit4]   1>                   "collection":"control_collection",
[junit4:junit4]   1>                   "node_name":"127.0.0.1:57270_",
[junit4:junit4]   1>                   "base_url":"http://127.0.0.1:57270",
[junit4:junit4]   1>                   "leader":"true"}}}},
[junit4:junit4]   1>           "router":"compositeId"}}
[junit4:junit4]   1>   /solr/aliases.json (0)
[junit4:junit4]   1>   /solr/live_nodes (4)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:57314_ (0)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:57270_ (0)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:57282_ (0)
[junit4:junit4]   1>    /solr/live_nodes/127.0.0.1:57301_ (0)
[junit4:junit4]   1>   /solr/overseer (3)
[junit4:junit4]   1>   DATA:
[junit4:junit4]   1>       
[junit4:junit4]   1>    /solr/overseer/queue (0)
[junit4:junit4]   1>    /solr/overseer/queue-work (0)
[junit4:junit4]   1>    /solr/overseer/collection-queue-work (0)
[junit4:junit4]   1>   /solr/collections (2)
[junit4:junit4]   1>    /solr/collections/collection1 (3)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"configName":"conf1"}
[junit4:junit4]   1>     /solr/collections/collection1/shards (0)
[junit4:junit4]   1>     /solr/collections/collection1/leader_elect (1)
[junit4:junit4]   1>      /solr/collections/collection1/leader_elect/shard1 (1)
[junit4:junit4]   1>       /solr/collections/collection1/leader_elect/shard1/election (3)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard1/election/89904377698713612-127.0.0.1:57314__collection1-n_0000000003 (0)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard1/election/89904377698713610-127.0.0.1:57301__collection1-n_0000000005 (0)
[junit4:junit4]   1>        /solr/collections/collection1/leader_elect/shard1/election/89904377698713614-127.0.0.1:57282__collection1-n_0000000004 (0)
[junit4:junit4]   1>     /solr/collections/collection1/leaders (1)
[junit4:junit4]   1>      /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "core":"collection1",
[junit4:junit4]   1>            "node_name":"127.0.0.1:57314_",
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:57314"}
[junit4:junit4]   1>    /solr/collections/control_collection (3)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"configName":"conf1"}
[junit4:junit4]   1>     /solr/collections/control_collection/shards (0)
[junit4:junit4]   1>     /solr/collections/control_collection/leader_elect (1)
[junit4:junit4]   1>      /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4]   1>       /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4]   1>        /solr/collections/control_collection/leader_elect/shard1/election/89904377698713603-127.0.0.1:57270__collection1-n_0000000000 (0)
[junit4:junit4]   1>     /solr/collections/control_collection/leaders (1)
[junit4:junit4]   1>      /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4]   1>      DATA:
[junit4:junit4]   1>          {
[junit4:junit4]   1>            "core":"collection1",
[junit4:junit4]   1>            "node_name":"127.0.0.1:57270_",
[junit4:junit4]   1>            "base_url":"http://127.0.0.1:57270"}
[junit4:junit4]   1>   /solr/overseer_elect (2)
[junit4:junit4]   1>    /solr/overseer_elect/election (4)
[junit4:junit4]   1>     /solr/overseer_elect/election/89904377698713614-127.0.0.1:57282_-n_0000000005 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89904377698713610-127.0.0.1:57301_-n_0000000003 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89904377698713612-127.0.0.1:57314_-n_0000000004 (0)
[junit4:junit4]   1>     /solr/overseer_elect/election/89904377698713603-127.0.0.1:57270_-n_0000000000 (0)
[junit4:junit4]   1>    /solr/overseer_elect/leader (0)
[junit4:junit4]   1>    DATA:
[junit4:junit4]   1>        {"id":"89904377698713603-127.0.0.1:57270_-n_0000000000"}
[junit4:junit4]   1>  /zookeeper (1)
[junit4:junit4]   1>  DATA:
[junit4:junit4]   1>      
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=676177279F0E4CF8 -Dtests.slow=true -Dtests.locale=et -Dtests.timezone=Asia/Dushanbe -Dtests.file.encoding=Cp1252
[junit4:junit4] FAILURE  151s | SyncSliceTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: java.lang.AssertionError: shard1 is not consistent.  Got 305 from http://127.0.0.1:57282/collection1lastClient and got 261 from http://127.0.0.1:57301/collection1
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([676177279F0E4CF8:E687F93FE8512CC4]:0)
[junit4:junit4]    > 	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4]    > 	at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
[junit4:junit4]    > 	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4]    > 	at java.lang.Thread.run(Thread.java:724)
[junit4:junit4]   2> 314991 T394 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {range_facet_l=PostingsFormat(name=Asserting), text=Pulsing41(freqCutoff=10 minBlockSize=95 maxBlockSize=209), _version_=PostingsFormat(name=Asserting), rnd_b=Lucene41(blocksize=128), intDefault=PostingsFormat(name=Asserting), timestamp=PostingsFormat(name=Asserting), id=Lucene41(blocksize=128), a_t=PostingsFormat(name=Asserting), range_facet_sl=Pulsing41(freqCutoff=10 minBlockSize=95 maxBlockSize=209), range_facet_si=PostingsFormat(name=NestedPulsing), other_tl1=PostingsFormat(name=Asserting), multiDefault=PostingsFormat(name=NestedPulsing), a_si=PostingsFormat(name=NestedPulsing)}, docValues:{}, sim=DefaultSimilarity, locale=et, timezone=Asia/Dushanbe
[junit4:junit4]   2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=1,free=31906456,total=89612288
[junit4:junit4]   2> NOTE: All tests run in this JVM: [SuggesterFSTTest, SolrCoreTest, SolrIndexConfigTest, TestSurroundQueryParser, TestDocumentBuilder, TestUniqueKeyFieldResource, PrimitiveFieldTypeTest, ClusterStateUpdateTest, TestReversedWildcardFilterFactory, ConvertedLegacyTest, TestJmxMonitoredMap, CoreAdminHandlerTest, TestSolrXMLSerializer, TestQueryUtils, TestAtomicUpdateErrorCases, TestIndexSearcher, TestBadConfig, XmlUpdateRequestHandlerTest, TestCharFilters, TestSolrQueryParser, TestLazyCores, TestSolrXml, DistributedQueryElevationComponentTest, TestTrie, ZkCLITest, SyncSliceTest]
[junit4:junit4] Completed in 151.32s, 1 test, 1 failure <<< FAILURES!

[...truncated 857 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:392: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:372: 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:1246: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:890: There were test failures: 298 suites, 1254 tests, 1 failure, 18 ignored (12 assumptions)

Total time: 71 minutes 45 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_25 -XX:-UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message