You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/18 12:58:29 UTC
[JENKINS] Lucene-Solr-4.x-Linux (64bit/jdk1.6.0_45) - Build # 6119
- Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6119/
Java: 64bit/jdk1.6.0_45 -XX:-UseCompressedOops -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:38764/collection1lastClient and got 254 from http://127.0.0.1:43360/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:38764/collection1lastClient and got 254 from http://127.0.0.1:43360/collection1
at __randomizedtesting.SeedInfo.seed([B59629D0C8B8BD7F:3470A7C8BFE7DD43]: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:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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:662)
Build Log:
[...truncated 8913 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 387590 T1705 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 387594 T1705 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1371552169536
[junit4:junit4] 2> 387594 T1705 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 387595 T1706 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 387695 T1705 oasc.ZkTestServer.run start zk server on port:38009
[junit4:junit4] 2> 387696 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 387798 T1712 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3211c7f9 name:ZooKeeperConnection Watcher:127.0.0.1:38009 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 387799 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 387799 T1705 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 387805 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 387806 T1714 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6d5498c name:ZooKeeperConnection Watcher:127.0.0.1:38009/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 387806 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 387807 T1705 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 387809 T1705 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 387811 T1705 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 387813 T1705 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 387815 T1705 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 387815 T1705 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 387818 T1705 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 387818 T1705 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 387821 T1705 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 387821 T1705 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 387824 T1705 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 387824 T1705 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 387826 T1705 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 387826 T1705 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 387829 T1705 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 387829 T1705 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 387831 T1705 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 387832 T1705 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 387834 T1705 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 387834 T1705 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 387837 T1705 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 387837 T1705 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 387903 T1705 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 387905 T1705 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50200
[junit4:junit4] 2> 387906 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 387906 T1705 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 387906 T1705 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371552169781
[junit4:junit4] 2> 387907 T1705 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371552169781/solr.xml
[junit4:junit4] 2> 387907 T1705 oasc.CoreContainer.<init> New CoreContainer 1636747671
[junit4:junit4] 2> 387907 T1705 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371552169781/'
[junit4:junit4] 2> 387907 T1705 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371552169781/'
[junit4:junit4] 2> 387953 T1705 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 387953 T1705 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 387954 T1705 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 387954 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 387954 T1705 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 387955 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 387955 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 387955 T1705 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 387955 T1705 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 387956 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 387958 T1705 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 387959 T1705 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38009/solr
[junit4:junit4] 2> 387959 T1705 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 387960 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 387962 T1725 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d61d74d name:ZooKeeperConnection Watcher:127.0.0.1:38009 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 387962 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 387964 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 387966 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 387968 T1727 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@62818036 name:ZooKeeperConnection Watcher:127.0.0.1:38009/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 387968 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 387970 T1705 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 387977 T1705 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 387980 T1705 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 387982 T1705 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50200_
[junit4:junit4] 2> 387983 T1705 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50200_
[junit4:junit4] 2> 387986 T1705 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 387991 T1705 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 387993 T1705 oasc.Overseer.start Overseer (id=89886042982842371-127.0.0.1:50200_-n_0000000000) starting
[junit4:junit4] 2> 387997 T1705 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 388001 T1729 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 388001 T1705 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 388004 T1705 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 388006 T1705 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 388008 T1728 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 388011 T1730 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 388011 T1730 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 389513 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 389514 T1728 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:50200_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50200"}
[junit4:junit4] 2> 389514 T1728 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 389515 T1728 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 389521 T1727 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> 390012 T1730 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371552169781/collection1
[junit4:junit4] 2> 390013 T1730 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 390014 T1730 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 390014 T1730 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 390017 T1730 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371552169781/collection1/'
[junit4:junit4] 2> 390018 T1730 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371552169781/collection1/lib/README' to classloader
[junit4:junit4] 2> 390018 T1730 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371552169781/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 390054 T1730 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 390085 T1730 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 390087 T1730 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 390091 T1730 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 390422 T1730 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 390428 T1730 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 390430 T1730 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 390450 T1730 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 390453 T1730 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 390457 T1730 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 390459 T1730 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 390459 T1730 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 390459 T1730 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 390461 T1730 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 390461 T1730 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 390462 T1730 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 390474 T1730 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371552169781/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/
[junit4:junit4] 2> 390475 T1730 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52cd19d
[junit4:junit4] 2> 390475 T1730 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 390476 T1730 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data
[junit4:junit4] 2> 390477 T1730 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index/
[junit4:junit4] 2> 390477 T1730 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 390478 T1730 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index
[junit4:junit4] 2> 390483 T1730 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 390483 T1730 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 390486 T1730 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 390487 T1730 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 390488 T1730 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 390488 T1730 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 390489 T1730 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 390489 T1730 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 390490 T1730 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 390491 T1730 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 390491 T1730 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 390494 T1730 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 390499 T1730 oass.SolrIndexSearcher.<init> Opening Searcher@dbfb969 main
[junit4:junit4] 2> 390500 T1730 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 390500 T1730 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 390503 T1731 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@dbfb969 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 390504 T1730 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 390504 T1730 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50200 collection:control_collection shard:shard1
[junit4:junit4] 2> 390506 T1730 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 390512 T1730 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 390514 T1730 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 390514 T1730 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 390514 T1730 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50200/collection1/
[junit4:junit4] 2> 390515 T1730 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 390515 T1730 oasc.SyncStrategy.syncToMe http://127.0.0.1:50200/collection1/ has no replicas
[junit4:junit4] 2> 390515 T1730 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50200/collection1/
[junit4:junit4] 2> 390515 T1730 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 391028 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 391039 T1727 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> 391075 T1730 oasc.ZkController.register We are http://127.0.0.1:50200/collection1/ and leader is http://127.0.0.1:50200/collection1/
[junit4:junit4] 2> 391075 T1730 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50200
[junit4:junit4] 2> 391075 T1730 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 391076 T1730 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 391076 T1730 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 391079 T1730 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 391080 T1705 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 391081 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 391082 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 391087 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 391089 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 391091 T1734 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a39bd1b name:ZooKeeperConnection Watcher:127.0.0.1:38009/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 391092 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 391095 T1705 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 391099 T1705 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 391178 T1705 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 391180 T1705 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38764
[junit4:junit4] 2> 391181 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 391181 T1705 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 391182 T1705 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371552173042
[junit4:junit4] 2> 391182 T1705 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371552173042/solr.xml
[junit4:junit4] 2> 391182 T1705 oasc.CoreContainer.<init> New CoreContainer 1067258602
[junit4:junit4] 2> 391183 T1705 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371552173042/'
[junit4:junit4] 2> 391183 T1705 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371552173042/'
[junit4:junit4] 2> 391222 T1705 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 391222 T1705 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 391223 T1705 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 391223 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 391223 T1705 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 391223 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 391224 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 391224 T1705 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 391224 T1705 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 391225 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 391227 T1705 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 391227 T1705 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38009/solr
[junit4:junit4] 2> 391228 T1705 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 391229 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 391230 T1745 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7121ec8d name:ZooKeeperConnection Watcher:127.0.0.1:38009 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 391230 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 391233 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 391235 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 391237 T1747 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2cc3e2fa name:ZooKeeperConnection Watcher:127.0.0.1:38009/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 391237 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 391243 T1705 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 392248 T1705 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38764_
[junit4:junit4] 2> 392250 T1705 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38764_
[junit4:junit4] 2> 392254 T1734 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 392255 T1747 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 392254 T1727 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 392255 T1727 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> 392263 T1748 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 392264 T1748 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 392547 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 392549 T1728 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50200__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:50200_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50200"}
[junit4:junit4] 2> 392554 T1728 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:38764_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38764"}
[junit4:junit4] 2> 392554 T1728 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 392554 T1728 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 392560 T1727 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> 392560 T1747 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> 392560 T1734 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> 393266 T1748 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371552173042/collection1
[junit4:junit4] 2> 393266 T1748 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 393267 T1748 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 393268 T1748 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 393270 T1748 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371552173042/collection1/'
[junit4:junit4] 2> 393271 T1748 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371552173042/collection1/lib/README' to classloader
[junit4:junit4] 2> 393271 T1748 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371552173042/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 393298 T1748 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 393331 T1748 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 393333 T1748 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 393337 T1748 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 393669 T1748 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 393675 T1748 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 393677 T1748 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 393695 T1748 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 393698 T1748 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 393703 T1748 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 393705 T1748 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 393705 T1748 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 393706 T1748 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 393708 T1748 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 393708 T1748 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 393708 T1748 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 393709 T1748 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371552173042/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/
[junit4:junit4] 2> 393709 T1748 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52cd19d
[junit4:junit4] 2> 393710 T1748 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 393711 T1748 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1
[junit4:junit4] 2> 393711 T1748 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index/
[junit4:junit4] 2> 393712 T1748 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 393712 T1748 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index
[junit4:junit4] 2> 393717 T1748 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 393718 T1748 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 393721 T1748 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 393721 T1748 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 393722 T1748 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 393723 T1748 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 393724 T1748 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 393724 T1748 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 393725 T1748 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 393726 T1748 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 393726 T1748 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 393730 T1748 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 393735 T1748 oass.SolrIndexSearcher.<init> Opening Searcher@2928a5f3 main
[junit4:junit4] 2> 393736 T1748 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 393736 T1748 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 393744 T1749 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2928a5f3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 393748 T1748 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 393748 T1748 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38764 collection:collection1 shard:shard1
[junit4:junit4] 2> 393749 T1748 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 393759 T1748 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 393763 T1748 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 393763 T1748 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 393763 T1748 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:38764/collection1/
[junit4:junit4] 2> 393764 T1748 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 393764 T1748 oasc.SyncStrategy.syncToMe http://127.0.0.1:38764/collection1/ has no replicas
[junit4:junit4] 2> 393764 T1748 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:38764/collection1/
[junit4:junit4] 2> 393765 T1748 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 394066 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 394078 T1727 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> 394078 T1747 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> 394078 T1734 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> 394125 T1748 oasc.ZkController.register We are http://127.0.0.1:38764/collection1/ and leader is http://127.0.0.1:38764/collection1/
[junit4:junit4] 2> 394125 T1748 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38764
[junit4:junit4] 2> 394125 T1748 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 394126 T1748 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 394126 T1748 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 394128 T1748 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 394130 T1705 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 394130 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 394131 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 394210 T1705 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 394216 T1705 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53003
[junit4:junit4] 2> 394216 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 394217 T1705 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 394217 T1705 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371552176078
[junit4:junit4] 2> 394218 T1705 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371552176078/solr.xml
[junit4:junit4] 2> 394218 T1705 oasc.CoreContainer.<init> New CoreContainer 60318894
[junit4:junit4] 2> 394218 T1705 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371552176078/'
[junit4:junit4] 2> 394219 T1705 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371552176078/'
[junit4:junit4] 2> 394265 T1705 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 394265 T1705 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 394266 T1705 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 394266 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 394267 T1705 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 394267 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 394268 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 394268 T1705 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 394269 T1705 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 394269 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 394273 T1705 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 394274 T1705 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38009/solr
[junit4:junit4] 2> 394274 T1705 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 394275 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 394277 T1761 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@733344d3 name:ZooKeeperConnection Watcher:127.0.0.1:38009 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 394277 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 394279 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 394282 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 394283 T1763 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5941b254 name:ZooKeeperConnection Watcher:127.0.0.1:38009/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 394283 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 394288 T1705 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 395291 T1705 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53003_
[junit4:junit4] 2> 395293 T1705 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53003_
[junit4:junit4] 2> 395297 T1734 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> 395298 T1727 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 395298 T1747 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 395298 T1727 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> 395298 T1763 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 395298 T1747 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> 395300 T1734 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 395306 T1764 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 395307 T1764 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 395586 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 395587 T1728 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38764__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:38764_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38764"}
[junit4:junit4] 2> 395592 T1728 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:53003_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53003"}
[junit4:junit4] 2> 395592 T1728 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 395592 T1728 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 395597 T1747 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> 395597 T1734 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> 395597 T1727 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> 395597 T1763 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> 396308 T1764 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371552176078/collection1
[junit4:junit4] 2> 396309 T1764 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 396310 T1764 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 396311 T1764 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 396313 T1764 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371552176078/collection1/'
[junit4:junit4] 2> 396314 T1764 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371552176078/collection1/lib/README' to classloader
[junit4:junit4] 2> 396314 T1764 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371552176078/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 396351 T1764 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 396382 T1764 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 396383 T1764 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 396388 T1764 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 396732 T1764 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 396737 T1764 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 396739 T1764 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 396755 T1764 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 396759 T1764 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 396764 T1764 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 396766 T1764 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 396767 T1764 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 396767 T1764 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 396769 T1764 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 396769 T1764 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 396769 T1764 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 396770 T1764 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371552176078/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/
[junit4:junit4] 2> 396770 T1764 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52cd19d
[junit4:junit4] 2> 396771 T1764 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 396772 T1764 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2
[junit4:junit4] 2> 396772 T1764 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index/
[junit4:junit4] 2> 396773 T1764 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 396773 T1764 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index
[junit4:junit4] 2> 396779 T1764 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 396779 T1764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 396782 T1764 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 396783 T1764 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 396784 T1764 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 396785 T1764 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 396785 T1764 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 396786 T1764 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 396786 T1764 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 396787 T1764 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 396788 T1764 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 396791 T1764 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 396796 T1764 oass.SolrIndexSearcher.<init> Opening Searcher@1d2f6cb6 main
[junit4:junit4] 2> 396797 T1764 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 396798 T1764 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 396802 T1765 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d2f6cb6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 396804 T1764 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 396805 T1764 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53003 collection:collection1 shard:shard1
[junit4:junit4] 2> 396809 T1764 oasc.ZkController.register We are http://127.0.0.1:53003/collection1/ and leader is http://127.0.0.1:38764/collection1/
[junit4:junit4] 2> 396810 T1764 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53003
[junit4:junit4] 2> 396810 T1764 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 396810 T1764 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C830 name=collection1 org.apache.solr.core.SolrCore@8d0f23a url=http://127.0.0.1:53003/collection1 node=127.0.0.1:53003_ C830_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53003_, base_url=http://127.0.0.1:53003}
[junit4:junit4] 2> 396811 T1766 C830 P53003 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 396811 T1764 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 396812 T1766 C830 P53003 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 396812 T1766 C830 P53003 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 396812 T1766 C830 P53003 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 396813 T1705 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 396814 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 396814 T1766 C830 P53003 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 396814 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 396820 T1741 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:53003__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 396892 T1705 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 396895 T1705 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:43360
[junit4:junit4] 2> 396895 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 396895 T1705 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 396896 T1705 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371552178761
[junit4:junit4] 2> 396896 T1705 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371552178761/solr.xml
[junit4:junit4] 2> 396896 T1705 oasc.CoreContainer.<init> New CoreContainer 82736514
[junit4:junit4] 2> 396897 T1705 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371552178761/'
[junit4:junit4] 2> 396897 T1705 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371552178761/'
[junit4:junit4] 2> 396937 T1705 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 396937 T1705 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 396938 T1705 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 396938 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 396938 T1705 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 396938 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 396939 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 396939 T1705 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 396939 T1705 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 396940 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 396942 T1705 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 396942 T1705 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38009/solr
[junit4:junit4] 2> 396943 T1705 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 396944 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 396945 T1778 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@66e2304 name:ZooKeeperConnection Watcher:127.0.0.1:38009 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 396945 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 396948 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 396950 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 396952 T1780 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@287d5023 name:ZooKeeperConnection Watcher:127.0.0.1:38009/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 396952 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 396958 T1705 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 397106 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 397107 T1728 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53003__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:53003_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53003"}
[junit4:junit4] 2> 397113 T1727 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> 397113 T1734 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> 397114 T1780 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> 397113 T1763 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> 397113 T1747 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> 397821 T1741 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:53003__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 397822 T1741 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:53003__collection1&state=recovering&nodeName=127.0.0.1:53003_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 397962 T1705 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43360_
[junit4:junit4] 2> 397964 T1705 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43360_
[junit4:junit4] 2> 397967 T1763 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> 397967 T1734 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> 397968 T1747 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 397968 T1727 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 397969 T1727 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> 397968 T1747 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> 397968 T1780 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 397970 T1780 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> 397970 T1763 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 397971 T1734 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 397978 T1781 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 397978 T1781 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 398621 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 398622 T1728 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:43360_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43360"}
[junit4:junit4] 2> 398623 T1728 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 398623 T1728 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 398630 T1763 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> 398630 T1727 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> 398630 T1734 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> 398630 T1747 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> 398630 T1780 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> 398980 T1781 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371552178761/collection1
[junit4:junit4] 2> 398980 T1781 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 398982 T1781 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 398982 T1781 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 398984 T1781 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371552178761/collection1/'
[junit4:junit4] 2> 398985 T1781 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371552178761/collection1/lib/README' to classloader
[junit4:junit4] 2> 398986 T1781 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371552178761/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 399018 T1781 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 399054 T1781 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 399055 T1781 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 399060 T1781 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 399401 T1781 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 399407 T1781 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 399409 T1781 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 399428 T1781 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 399433 T1781 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 399438 T1781 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 399440 T1781 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 399440 T1781 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 399441 T1781 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 399443 T1781 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 399443 T1781 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 399443 T1781 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 399444 T1781 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371552178761/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/
[junit4:junit4] 2> 399444 T1781 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52cd19d
[junit4:junit4] 2> 399445 T1781 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 399445 T1781 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3
[junit4:junit4] 2> 399445 T1781 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index/
[junit4:junit4] 2> 399446 T1781 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 399446 T1781 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index
[junit4:junit4] 2> 399451 T1781 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 399451 T1781 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 399455 T1781 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 399455 T1781 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 399456 T1781 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 399457 T1781 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 399458 T1781 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 399458 T1781 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 399459 T1781 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 399459 T1781 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 399460 T1781 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 399463 T1781 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 399466 T1781 oass.SolrIndexSearcher.<init> Opening Searcher@45ac1115 main
[junit4:junit4] 2> 399466 T1781 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 399466 T1781 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 399474 T1782 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@45ac1115 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 399478 T1781 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 399478 T1781 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43360 collection:collection1 shard:shard1
[junit4:junit4] 2> 399484 T1781 oasc.ZkController.register We are http://127.0.0.1:43360/collection1/ and leader is http://127.0.0.1:38764/collection1/
[junit4:junit4] 2> 399484 T1781 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43360
[junit4:junit4] 2> 399484 T1781 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 399484 T1781 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C831 name=collection1 org.apache.solr.core.SolrCore@5736b751 url=http://127.0.0.1:43360/collection1 node=127.0.0.1:43360_ C831_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:43360_, base_url=http://127.0.0.1:43360}
[junit4:junit4] 2> 399485 T1783 C831 P43360 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 399486 T1783 C831 P43360 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 399486 T1781 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 399486 T1783 C831 P43360 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 399487 T1783 C831 P43360 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 399488 T1705 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 399488 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 399488 T1783 C831 P43360 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 399489 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 399498 T1742 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:43360__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 399576 T1705 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 399577 T1705 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58026
[junit4:junit4] 2> 399578 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 399578 T1705 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 399579 T1705 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371552181438
[junit4:junit4] 2> 399579 T1705 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371552181438/solr.xml
[junit4:junit4] 2> 399580 T1705 oasc.CoreContainer.<init> New CoreContainer 1828331376
[junit4:junit4] 2> 399581 T1705 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371552181438/'
[junit4:junit4] 2> 399581 T1705 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371552181438/'
[junit4:junit4] 2> 399632 T1705 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 399632 T1705 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 399633 T1705 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 399633 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 399633 T1705 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 399633 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 399634 T1705 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 399634 T1705 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 399634 T1705 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 399635 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 399637 T1705 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 399638 T1705 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:38009/solr
[junit4:junit4] 2> 399638 T1705 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 399639 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 399640 T1795 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@188ca0b9 name:ZooKeeperConnection Watcher:127.0.0.1:38009 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 399641 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 399642 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 399645 T1705 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 399646 T1797 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@34b9101a name:ZooKeeperConnection Watcher:127.0.0.1:38009/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 399646 T1705 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 399649 T1705 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C832 name=collection1 org.apache.solr.core.SolrCore@8d0f23a url=http://127.0.0.1:53003/collection1 node=127.0.0.1:53003_ C832_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53003_, base_url=http://127.0.0.1:53003}
[junit4:junit4] 2> 399823 T1766 C832 P53003 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:38764/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 399823 T1766 C832 P53003 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53003 START replicas=[http://127.0.0.1:38764/collection1/] nUpdates=100
[junit4:junit4] 2> 399824 T1766 C832 P53003 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 399824 T1766 C832 P53003 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 399825 T1766 C832 P53003 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 399825 T1766 C832 P53003 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 399825 T1766 C832 P53003 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 399825 T1766 C832 P53003 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:38764/collection1/. core=collection1
[junit4:junit4] 2> 399825 T1766 C832 P53003 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C833 name=collection1 org.apache.solr.core.SolrCore@225e7bd5 url=http://127.0.0.1:38764/collection1 node=127.0.0.1:38764_ C833_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:38764_, base_url=http://127.0.0.1:38764, leader=true}
[junit4:junit4] 2> 399834 T1740 C833 P38764 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> 399837 T1741 C833 P38764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 399840 T1741 C833 P38764 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 399840 T1741 C833 P38764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 399846 T1741 C833 P38764 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 399847 T1741 C833 P38764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 399848 T1741 C833 P38764 oass.SolrIndexSearcher.<init> Opening Searcher@5f6510d9 realtime
[junit4:junit4] 2> 399848 T1741 C833 P38764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 399848 T1741 C833 P38764 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 11
[junit4:junit4] 2> 399849 T1766 C832 P53003 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 399850 T1766 C832 P53003 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 399852 T1740 C833 P38764 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 399852 T1740 C833 P38764 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 399853 T1766 C832 P53003 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 399853 T1766 C832 P53003 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 399853 T1766 C832 P53003 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 399856 T1741 C833 P38764 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 399857 T1766 C832 P53003 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 399858 T1766 C832 P53003 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index.20130618074301799
[junit4:junit4] 2> 399858 T1766 C832 P53003 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index.20130618074301799 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2a536434 fullCopy=false
[junit4:junit4] 2> 399861 T1743 C833 P38764 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 399863 T1766 C832 P53003 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 399867 T1766 C832 P53003 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 399867 T1766 C832 P53003 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 399870 T1766 C832 P53003 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 399871 T1766 C832 P53003 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 399872 T1766 C832 P53003 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 399872 T1766 C832 P53003 oass.SolrIndexSearcher.<init> Opening Searcher@d85b711 main
[junit4:junit4] 2> 399874 T1765 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d85b711 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 399874 T1766 C832 P53003 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index.20130618074301799 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index.20130618074301799;done=true>>]
[junit4:junit4] 2> 399875 T1766 C832 P53003 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index.20130618074301799
[junit4:junit4] 2> 399875 T1766 C832 P53003 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index.20130618074301799
[junit4:junit4] 2> 399876 T1766 C832 P53003 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 399876 T1766 C832 P53003 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 399876 T1766 C832 P53003 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 399877 T1766 C832 P53003 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 399879 T1766 C832 P53003 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 400135 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 400136 T1728 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43360__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:43360_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43360"}
[junit4:junit4] 2> 400138 T1728 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53003__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:53003_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53003"}
[junit4:junit4] 2> 400156 T1727 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> 400157 T1780 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> 400157 T1797 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> 400157 T1734 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> 400157 T1763 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> 400156 T1747 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> 400499 T1742 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:43360__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 400500 T1742 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:43360__collection1&state=recovering&nodeName=127.0.0.1:43360_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 400653 T1705 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58026_
[junit4:junit4] 2> 400655 T1705 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58026_
[junit4:junit4] 2> 400658 T1763 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> 400659 T1797 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> 400659 T1734 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> 400660 T1747 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 400660 T1727 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 400660 T1780 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 400660 T1727 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> 400660 T1747 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> 400661 T1780 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> 400662 T1763 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 400663 T1734 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 400664 T1797 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 400671 T1800 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 400671 T1800 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 401665 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 401666 T1728 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:58026_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58026"}
[junit4:junit4] 2> 401667 T1728 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 401667 T1728 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 401673 T1727 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> 401673 T1797 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> 401673 T1780 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> 401673 T1734 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> 401673 T1763 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> 401673 T1747 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> ASYNC NEW_CORE C834 name=collection1 org.apache.solr.core.SolrCore@5736b751 url=http://127.0.0.1:43360/collection1 node=127.0.0.1:43360_ C834_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:43360_, base_url=http://127.0.0.1:43360}
[junit4:junit4] 2> 402501 T1783 C834 P43360 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:38764/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 402501 T1783 C834 P43360 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43360 START replicas=[http://127.0.0.1:38764/collection1/] nUpdates=100
[junit4:junit4] 2> 402502 T1783 C834 P43360 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 402502 T1783 C834 P43360 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 402503 T1783 C834 P43360 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 402504 T1783 C834 P43360 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 402504 T1783 C834 P43360 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 402504 T1783 C834 P43360 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:38764/collection1/. core=collection1
[junit4:junit4] 2> 402505 T1783 C834 P43360 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 402505 T1742 C833 P38764 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> 402512 T1740 C833 P38764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 402516 T1740 C833 P38764 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 402517 T1740 C833 P38764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 402518 T1740 C833 P38764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 402519 T1740 C833 P38764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 402520 T1783 C834 P43360 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 402520 T1783 C834 P43360 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 402523 T1743 C833 P38764 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 402524 T1783 C834 P43360 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 402524 T1783 C834 P43360 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 402525 T1783 C834 P43360 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 402527 T1742 C833 P38764 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=0
[junit4:junit4] 2> 402529 T1783 C834 P43360 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 402530 T1783 C834 P43360 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index.20130618074304471
[junit4:junit4] 2> 402530 T1783 C834 P43360 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index.20130618074304471 lockFactory=org.apache.lucene.store.NativeFSLockFactory@13526c77 fullCopy=false
[junit4:junit4] 2> 402533 T1740 C833 P38764 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 402535 T1783 C834 P43360 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 402538 T1783 C834 P43360 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 402538 T1783 C834 P43360 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 402541 T1783 C834 P43360 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 402542 T1783 C834 P43360 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 402542 T1783 C834 P43360 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 402543 T1783 C834 P43360 oass.SolrIndexSearcher.<init> Opening Searcher@78c7dee2 main
[junit4:junit4] 2> 402545 T1782 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@78c7dee2 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 402545 T1783 C834 P43360 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index.20130618074304471 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index.20130618074304471;done=true>>]
[junit4:junit4] 2> 402546 T1783 C834 P43360 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index.20130618074304471
[junit4:junit4] 2> 402546 T1783 C834 P43360 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index.20130618074304471
[junit4:junit4] 2> 402547 T1783 C834 P43360 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 402547 T1783 C834 P43360 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 402547 T1783 C834 P43360 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 402548 T1783 C834 P43360 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 402549 T1783 C834 P43360 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 402673 T1800 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371552181438/collection1
[junit4:junit4] 2> 402674 T1800 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 402675 T1800 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 402675 T1800 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 402677 T1800 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371552181438/collection1/'
[junit4:junit4] 2> 402678 T1800 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371552181438/collection1/lib/README' to classloader
[junit4:junit4] 2> 402679 T1800 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371552181438/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 402715 T1800 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 402746 T1800 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 402747 T1800 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 402751 T1800 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 403099 T1800 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 403104 T1800 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 403106 T1800 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 403117 T1800 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 403120 T1800 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 403122 T1800 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 403123 T1800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 403123 T1800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 403123 T1800 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 403124 T1800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 403124 T1800 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 403124 T1800 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 403125 T1800 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371552181438/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/
[junit4:junit4] 2> 403125 T1800 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@52cd19d
[junit4:junit4] 2> 403125 T1800 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 403125 T1800 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4
[junit4:junit4] 2> 403126 T1800 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index/
[junit4:junit4] 2> 403126 T1800 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 403126 T1800 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index
[junit4:junit4] 2> 403129 T1800 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 403130 T1800 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 403132 T1800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 403132 T1800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 403133 T1800 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 403134 T1800 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 403134 T1800 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 403134 T1800 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 403137 T1800 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 403138 T1800 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 403139 T1800 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 403142 T1800 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 403146 T1800 oass.SolrIndexSearcher.<init> Opening Searcher@77c601e3 main
[junit4:junit4] 2> 403146 T1800 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 403147 T1800 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 403151 T1803 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@77c601e3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 403153 T1800 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 403153 T1800 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58026 collection:collection1 shard:shard1
[junit4:junit4] 2> 403156 T1800 oasc.ZkController.register We are http://127.0.0.1:58026/collection1/ and leader is http://127.0.0.1:38764/collection1/
[junit4:junit4] 2> 403156 T1800 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58026
[junit4:junit4] 2> 403156 T1800 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 403156 T1800 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C835 name=collection1 org.apache.solr.core.SolrCore@1ccc94f0 url=http://127.0.0.1:58026/collection1 node=127.0.0.1:58026_ C835_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:58026_, base_url=http://127.0.0.1:58026}
[junit4:junit4] 2> 403157 T1804 C835 P58026 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 403157 T1804 C835 P58026 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 403158 T1800 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 403158 T1804 C835 P58026 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 403158 T1804 C835 P58026 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 403159 T1705 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 403159 T1705 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 403159 T1804 C835 P58026 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 403160 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 403163 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 403163 T1742 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:58026__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 403164 T1705 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 403164 T1705 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 403165 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 403179 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 403179 T1728 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:43360__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:43360_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43360"}
[junit4:junit4] 2> 403182 T1728 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58026__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:58026_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58026"}
[junit4:junit4] 2> 403185 T1727 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> 403185 T1734 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> 403185 T1797 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> 403185 T1780 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> 403185 T1763 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> 403185 T1747 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> 404164 T1742 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:58026__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 404164 T1742 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:58026__collection1&state=recovering&nodeName=127.0.0.1:58026_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 404167 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 405169 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C835_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58026_, base_url=http://127.0.0.1:58026}
[junit4:junit4] 2> 406165 T1804 C835 P58026 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:38764/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 406166 T1804 C835 P58026 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58026 START replicas=[http://127.0.0.1:38764/collection1/] nUpdates=100
[junit4:junit4] 2> 406166 T1804 C835 P58026 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 406166 T1804 C835 P58026 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 406166 T1804 C835 P58026 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 406166 T1804 C835 P58026 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 406167 T1804 C835 P58026 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 406167 T1804 C835 P58026 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:38764/collection1/. core=collection1
[junit4:junit4] 2> 406167 T1804 C835 P58026 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C836 name=collection1 org.apache.solr.core.SolrCore@225e7bd5 url=http://127.0.0.1:38764/collection1 node=127.0.0.1:38764_ C836_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:38764_, base_url=http://127.0.0.1:38764, leader=true}
[junit4:junit4] 2> 406168 T1740 C836 P38764 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> 406170 T1741 C836 P38764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 406171 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 406176 T1741 C836 P38764 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 406177 T1741 C836 P38764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 406177 T1741 C836 P38764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 406177 T1741 C836 P38764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 406178 T1804 C835 P58026 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 406178 T1804 C835 P58026 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 406180 T1742 C836 P38764 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 406181 T1804 C835 P58026 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 406181 T1804 C835 P58026 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 406181 T1804 C835 P58026 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 406183 T1740 C836 P38764 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 406183 T1804 C835 P58026 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 406184 T1804 C835 P58026 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index.20130618074308126
[junit4:junit4] 2> 406184 T1804 C835 P58026 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index.20130618074308126 lockFactory=org.apache.lucene.store.NativeFSLockFactory@47b94293 fullCopy=false
[junit4:junit4] 2> 406187 T1741 C836 P38764 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> 406188 T1804 C835 P58026 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 406190 T1804 C835 P58026 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 406190 T1804 C835 P58026 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 406192 T1804 C835 P58026 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 406192 T1804 C835 P58026 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 406192 T1804 C835 P58026 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 406193 T1804 C835 P58026 oass.SolrIndexSearcher.<init> Opening Searcher@35f975e2 main
[junit4:junit4] 2> 406193 T1803 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@35f975e2 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 406194 T1804 C835 P58026 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index.20130618074308126 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index.20130618074308126;done=true>>]
[junit4:junit4] 2> 406194 T1804 C835 P58026 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index.20130618074308126
[junit4:junit4] 2> 406194 T1804 C835 P58026 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index.20130618074308126
[junit4:junit4] 2> 406195 T1804 C835 P58026 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 406195 T1804 C835 P58026 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 406195 T1804 C835 P58026 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 406195 T1804 C835 P58026 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 406196 T1804 C835 P58026 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 407173 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 407694 T1728 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 407695 T1728 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58026__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:58026_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58026"}
[junit4:junit4] 2> 407698 T1727 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> 407698 T1747 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> 407698 T1763 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> 407698 T1734 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> 407698 T1797 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> 407698 T1780 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> 408175 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 408177 T1705 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C837 name=collection1 org.apache.solr.core.SolrCore@460a4b8a url=http://127.0.0.1:50200/collection1 node=127.0.0.1:50200_ C837_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50200_, base_url=http://127.0.0.1:50200, leader=true}
[junit4:junit4] 2> 408185 T1720 C837 P50200 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 408189 T1720 C837 P50200 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 408189 T1720 C837 P50200 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 408396 T1720 C837 P50200 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 408397 T1720 C837 P50200 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 408398 T1720 C837 P50200 oass.SolrIndexSearcher.<init> Opening Searcher@53481a66 main
[junit4:junit4] 2> 408399 T1720 C837 P50200 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 408400 T1731 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@53481a66 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 408400 T1720 C837 P50200 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 215
[junit4:junit4] 2> 408403 T1740 C836 P38764 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:38764/collection1/, StdNode: http://127.0.0.1:53003/collection1/, StdNode: http://127.0.0.1:43360/collection1/, StdNode: http://127.0.0.1:58026/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 408407 T1743 C836 P38764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C835_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58026_, base_url=http://127.0.0.1:58026}
[junit4:junit4] 2> 408411 T1791 C835 P58026 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C838 name=collection1 org.apache.solr.core.SolrCore@5736b751 url=http://127.0.0.1:43360/collection1 node=127.0.0.1:43360_ C838_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43360_, base_url=http://127.0.0.1:43360}
[junit4:junit4] 2> 408411 T1775 C838 P43360 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C839 name=collection1 org.apache.solr.core.SolrCore@8d0f23a url=http://127.0.0.1:53003/collection1 node=127.0.0.1:53003_ C839_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53003_, base_url=http://127.0.0.1:53003}
[junit4:junit4] 2> 408412 T1759 C839 P53003 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 408416 T1743 C836 P38764 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 408417 T1743 C836 P38764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 408418 T1743 C836 P38764 oass.SolrIndexSearcher.<init> Opening Searcher@43a8c21c main
[junit4:junit4] 2> 408419 T1743 C836 P38764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 408419 T1749 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@43a8c21c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 408420 T1743 C836 P38764 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 14
[junit4:junit4] 2> 408436 T1759 C839 P53003 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 408437 T1759 C839 P53003 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 408437 T1759 C839 P53003 oass.SolrIndexSearcher.<init> Opening Searcher@7a2769eb main
[junit4:junit4] 2> 408438 T1791 C835 P58026 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 408438 T1775 C838 P43360 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 408438 T1791 C835 P58026 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 408438 T1759 C839 P53003 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 408438 T1765 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7a2769eb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 408438 T1775 C838 P43360 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 408440 T1759 C839 P53003 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> 408439 T1791 C835 P58026 oass.SolrIndexSearcher.<init> Opening Searcher@379d539d main
[junit4:junit4] 2> 408441 T1775 C838 P43360 oass.SolrIndexSearcher.<init> Opening Searcher@3c9c07e4 main
[junit4:junit4] 2> 408441 T1791 C835 P58026 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 408442 T1775 C838 P43360 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 408442 T1803 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@379d539d main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 408443 T1782 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3c9c07e4 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 408443 T1791 C835 P58026 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 32
[junit4:junit4] 2> 408444 T1775 C838 P43360 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 33
[junit4:junit4] 2> 408445 T1740 C836 P38764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 42
[junit4:junit4] 2> 408447 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 408450 T1742 C836 P38764 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> 408453 T1756 C839 P53003 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> 408455 T1776 C838 P43360 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> 408457 T1793 C835 P58026 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> 410461 T1720 C837 P50200 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438176711700119552)} 0 1
[junit4:junit4] 2> 410468 T1774 C838 P43360 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438176711705362432&update.from=http://127.0.0.1:38764/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438176711705362432)} 0 0
[junit4:junit4] 2> 410469 T1759 C839 P53003 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438176711705362432&update.from=http://127.0.0.1:38764/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438176711705362432)} 0 1
[junit4:junit4] 2> 410469 T1791 C835 P58026 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438176711705362432&update.from=http://127.0.0.1:38764/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438176711705362432)} 0 1
[junit4:junit4] 2> 410470 T1742 C836 P38764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438176711705362432)} 0 5
[junit4:junit4] 2> 410470 T1790 C835 P58026 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 7
[junit4:junit4] 2> 410474 T1721 C837 P50200 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438176711713751040)]} 0 1
[junit4:junit4] 2> 410484 T1757 C839 P53003 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38764/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438176711720042496)]} 0 2
[junit4:junit4] 2> 410484 T1793 C835 P58026 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38764/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438176711720042496)]} 0 2
[junit4:junit4] 2> 410484 T1773 C838 P43360 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38764/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438176711720042496)]} 0 2
[junit4:junit4] 2> 410485 T1741 C836 P38764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58026/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1438176711720042496)]} 0 6
[junit4:junit4] 2> 410486 T1792 C835 P58026 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 9
[junit4:junit4] 2> 410489 T1722 C837 P50200 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438176711729479680)]} 0 1
[junit4:junit4] 2> 410495 T1791 C835 P58026 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38764/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438176711732625408)]} 0 1
[junit4:junit4] 2> 410495 T1775 C838 P43360 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38764/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438176711732625408)]} 0 1
[junit4:junit4] 2> 410495 T1758 C839 P53003 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38764/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438176711732625408)]} 0 1
[junit4:junit4] 2> 410496 T1743 C836 P38764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438176711732625408)]} 0 5
[junit4:junit4] 2> 410500 T1723 C837 P50200 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438176711741014016)]} 0 1
[junit4:junit4] 2> 410505 T1742 C836 P38764 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:53003/collection1/]
[junit4:junit4] 2> 410506 T1742 C836 P38764 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53003/collection1/ against:[http://127.0.0.1:53003/collection1/] result:true
[junit4:junit4] 2> 410506 T1742 C836 P38764 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:43360/collection1/ against:[http://127.0.0.1:53003/collection1/] result:false
[junit4:junit4] 2> 410507 T1742 C836 P38764 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:58026/collection1/ against:[http://127.0.0.1:53003/collection1/] result:false
[junit4:junit4] 2> 410511 T1793 C835 P58026 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38764/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:53003/collection1/&wt=javabin&version=2} {add=[2 (1438176711749402624)]} 0 1
[junit4:junit4] 2> 410511 T1776 C838 P43360 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38764/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:53003/collection1/&wt=javabin&version=2} {add=[2 (1438176711749402624)]} 0 1
[junit4:junit4] 2> 410512 T1742 C836 P38764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:58026/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:53003/collection1/&wt=javabin&version=2} {add=[2 (1438176711749402624)]} 0 7
[junit4:junit4] 2> 410513 T1790 C835 P58026 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:53003/collection1/&wt=javabin&version=2} {add=[2]} 0 10
[junit4:junit4] 2> 410516 T1720 C837 P50200 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438176711757791232)]} 0 1
[junit4:junit4] 2> 410519 T1741 C836 P38764 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:53003/collection1/, http://127.0.0.1:43360/collection1/]
[junit4:junit4] 2> 410519 T1741 C836 P38764 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53003/collection1/ against:[http://127.0.0.1:53003/collection1/, http://127.0.0.1:43360/collection1/] result:true
[junit4:junit4] 2> 410520 T1741 C836 P38764 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:43360/collection1/ against:[http://127.0.0.1:53003/collection1/, http://127.0.0.1:43360/collection1/] result:true
[junit4:junit4] 2> 410520 T1741 C836 P38764 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:58026/collection1/ against:[http://127.0.0.1:53003/collection1/, http://127.0.0.1:43360/collection1/] result:false
[junit4:junit4] 2> 410524 T1792 C835 P58026 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:38764/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:53003/collection1/&wt=javabin&version=2} {add=[3 (1438176711764082688)]} 0 1
[junit4:junit4] 2> 410525 T1741 C836 P38764 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:53003/collection1/&test.distrib.skip.servers=http://127.0.0.1:43360/collection1/&wt=javabin&version=2} {add=[3 (1438176711764082688)]} 0 7
[junit4:junit4] 2> 410527 T1721 C837 P50200 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 410546 T1721 C837 P50200 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 410547 T1721 C837 P50200 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 410549 T1721 C837 P50200 oass.SolrIndexSearcher.<init> Opening Searcher@336ac022 main
[junit4:junit4] 2> 410550 T1721 C837 P50200 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410550 T1731 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@336ac022 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 410551 T1721 C837 P50200 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 410552 T1756 C839 P53003 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:38764/collection1/, StdNode: http://127.0.0.1:53003/collection1/, StdNode: http://127.0.0.1:43360/collection1/, StdNode: http://127.0.0.1:58026/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 410555 T1774 C838 P43360 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 410555 T1793 C835 P58026 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 410555 T1757 C839 P53003 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 410555 T1740 C836 P38764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C840 name=collection1 org.apache.solr.core.SolrCore@1ccc94f0 url=http://127.0.0.1:58026/collection1 node=127.0.0.1:58026_ C840_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58026_, base_url=http://127.0.0.1:58026}
[junit4:junit4] 2> 410606 T1793 C840 P58026 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> 410607 T1793 C840 P58026 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 410609 T1793 C840 P58026 oass.SolrIndexSearcher.<init> Opening Searcher@e9c6c54 main
[junit4:junit4] 2> 410609 T1793 C840 P58026 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410610 T1803 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e9c6c54 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 410611 T1793 C840 P58026 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 56
[junit4:junit4] 2> ASYNC NEW_CORE C841 name=collection1 org.apache.solr.core.SolrCore@8d0f23a url=http://127.0.0.1:53003/collection1 node=127.0.0.1:53003_ C841_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53003_, base_url=http://127.0.0.1:53003}
[junit4:junit4] 2> 410626 T1757 C841 P53003 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> ASYNC NEW_CORE C842 name=collection1 org.apache.solr.core.SolrCore@225e7bd5 url=http://127.0.0.1:38764/collection1 node=127.0.0.1:38764_ C842_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:38764_, base_url=http://127.0.0.1:38764, leader=true}
[junit4:junit4] 2> 410626 T1740 C842 P38764 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> 410627 T1740 C842 P38764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> ASYNC NEW_CORE C843 name=collection1 org.apache.solr.core.SolrCore@5736b751 url=http://127.0.0.1:43360/collection1 node=127.0.0.1:43360_ C843_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:43360_, base_url=http://127.0.0.1:43360}
[junit4:junit4] 2> 410626 T1774 C843 P43360 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 410627 T1757 C841 P53003 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 410628 T1774 C843 P43360 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 410630 T1740 C842 P38764 oass.SolrIndexSearcher.<init> Opening Searcher@3abe8a64 main
[junit4:junit4] 2> 410630 T1757 C841 P53003 oass.SolrIndexSearcher.<init> Opening Searcher@4e7db115 main
[junit4:junit4] 2> 410631 T1774 C843 P43360 oass.SolrIndexSearcher.<init> Opening Searcher@3c4c41b7 main
[junit4:junit4] 2> 410631 T1774 C843 P43360 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410632 T1765 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4e7db115 main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):c2)}
[junit4:junit4] 2> 410632 T1782 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3c4c41b7 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):c3)}
[junit4:junit4] 2> 410630 T1740 C842 P38764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410633 T1774 C843 P43360 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 78
[junit4:junit4] 2> 410631 T1749 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3abe8a64 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 410631 T1757 C841 P53003 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410634 T1757 C841 P53003 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 79
[junit4:junit4] 2> 410634 T1740 C842 P38764 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 79
[junit4:junit4] 2> 410634 T1756 C841 P53003 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 82
[junit4:junit4] 2> 410635 T1705 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 410636 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 410637 T1705 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 410639 T1743 C842 P38764 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 410642 T1758 C841 P53003 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=1
[junit4:junit4] 2> 410644 T1773 C843 P43360 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=3 status=0 QTime=0
[junit4:junit4] 2> 410647 T1790 C840 P58026 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 410649 T1705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 410654 T1775 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 410655 T1775 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 410659 T1742 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 410659 T1742 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:38764/collection1/
[junit4:junit4] 2> 410659 T1742 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38764 START replicas=[http://127.0.0.1:53003/collection1/, http://127.0.0.1:43360/collection1/, http://127.0.0.1:58026/collection1/] nUpdates=100
[junit4:junit4] 2> 410662 T1757 C841 P53003 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> 410662 T1774 C843 P43360 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> 410662 T1791 C840 P58026 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> 410662 T1742 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38764 Received 3 versions from 127.0.0.1:53003/collection1/
[junit4:junit4] 2> 410663 T1742 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38764 Our versions are newer. ourLowThreshold=1438176711705362432 otherHigh=1438176711732625408
[junit4:junit4] 2> 410663 T1742 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38764 Received 5 versions from 127.0.0.1:58026/collection1/
[junit4:junit4] 2> 410664 T1742 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38764 Our versions are newer. ourLowThreshold=1438176711705362432 otherHigh=1438176711749402624
[junit4:junit4] 2> 410664 T1742 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38764 Received 4 versions from 127.0.0.1:43360/collection1/
[junit4:junit4] 2> 410664 T1742 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38764 Our versions are newer. ourLowThreshold=1438176711705362432 otherHigh=1438176711749402624
[junit4:junit4] 2> 410665 T1742 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38764 DONE. sync succeeded
[junit4:junit4] 2> 410665 T1742 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 410665 T1742 oasc.SyncStrategy.syncToMe http://127.0.0.1:38764/collection1/: try and ask http://127.0.0.1:53003/collection1/ to sync
[junit4:junit4] 2> 410666 T1742 oasc.SyncStrategy.syncToMe http://127.0.0.1:38764/collection1/: try and ask http://127.0.0.1:43360/collection1/ to sync
[junit4:junit4] 2> 410666 T1742 oasc.SyncStrategy.syncToMe http://127.0.0.1:38764/collection1/: try and ask http://127.0.0.1:58026/collection1/ to sync
[junit4:junit4] 2> 410668 T1756 C841 P53003 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53003 START replicas=[http://127.0.0.1:38764/collection1/] nUpdates=100
[junit4:junit4] 2> 410669 T1790 C840 P58026 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58026 START replicas=[http://127.0.0.1:38764/collection1/] nUpdates=100
[junit4:junit4] 2> 410670 T1773 C843 P43360 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43360 START replicas=[http://127.0.0.1:38764/collection1/] nUpdates=100
[junit4:junit4] 2> 410670 T1741 C842 P38764 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> 410671 T1743 C842 P38764 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> 410671 T1756 C841 P53003 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:53003 Received 5 versions from 127.0.0.1:38764/collection1/
[junit4:junit4] 2> 410671 T1790 C840 P58026 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58026 Received 5 versions from 127.0.0.1:38764/collection1/
[junit4:junit4] 2> 410672 T1756 C841 P53003 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:53003 Requesting updates from 127.0.0.1:38764/collection1/n=2 versions=[1438176711764082688, 1438176711749402624]
[junit4:junit4] 2> 410671 T1740 C842 P38764 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> 410672 T1790 C840 P58026 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58026 Our versions are newer. ourLowThreshold=1438176711705362432 otherHigh=1438176711749402624
[junit4:junit4] 2> 410673 T1773 C843 P43360 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:43360 Received 5 versions from 127.0.0.1:38764/collection1/
[junit4:junit4] 2> 410673 T1790 C840 P58026 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58026 DONE. sync succeeded
[junit4:junit4] 2> 410674 T1773 C843 P43360 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:43360 Requesting updates from 127.0.0.1:38764/collection1/n=1 versions=[1438176711764082688]
[junit4:junit4] 2> 410674 T1790 C840 P58026 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:38764/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=5
[junit4:junit4] 2> 410675 T1742 oasc.SyncStrategy.syncToMe http://127.0.0.1:38764/collection1/: sync completed with http://127.0.0.1:58026/collection1/
[junit4:junit4] 2> 410676 T1741 C842 P38764 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&getUpdates=1438176711764082688,1438176711749402624&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 410677 T1743 C842 P38764 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&getUpdates=1438176711764082688&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 410679 T1773 C843 P43360 oasup.LogUpdateProcessor.finish [collection1] {add=[3 (1438176711764082688)]} 0 1
[junit4:junit4] 2> 410680 T1773 C843 P43360 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43360 DONE. sync succeeded
[junit4:junit4] 2> 410680 T1756 C841 P53003 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438176711749402624), 3 (1438176711764082688)]} 0 4
[junit4:junit4] 2> 410680 T1773 C843 P43360 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:38764/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=10
[junit4:junit4] 2> 410680 T1756 C841 P53003 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53003 DONE. sync succeeded
[junit4:junit4] 2> 410681 T1742 oasc.SyncStrategy.syncToMe http://127.0.0.1:38764/collection1/: sync completed with http://127.0.0.1:43360/collection1/
[junit4:junit4] 2> 410681 T1756 C841 P53003 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:38764/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=13
[junit4:junit4] 2> 410682 T1742 oasc.SyncStrategy.syncToMe http://127.0.0.1:38764/collection1/: sync completed with http://127.0.0.1:53003/collection1/
[junit4:junit4] 2> 410682 T1742 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={shard=shard1&action=REQUESTSYNCSHARD&core=collection1&collection=collection1&wt=javabin&version=2} status=0 QTime=24
[junit4:junit4] 2> 410682 T1775 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2} status=0 QTime=29
[junit4:junit4] 2> 410683 T1705 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 410683 T1705 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 410684 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 410684 T1705 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C844 name=collection1 org.apache.solr.core.SolrCore@460a4b8a url=http://127.0.0.1:50200/collection1 node=127.0.0.1:50200_ C844_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50200_, base_url=http://127.0.0.1:50200, leader=true}
[junit4:junit4] 2> 410686 T1722 C844 P50200 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 410746 T1722 C844 P50200 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/control/data/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 410747 T1722 C844 P50200 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 410748 T1722 C844 P50200 oass.SolrIndexSearcher.<init> Opening Searcher@72c0a56d main
[junit4:junit4] 2> 410748 T1722 C844 P50200 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410749 T1731 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@72c0a56d main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 410749 T1722 C844 P50200 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 63
[junit4:junit4] 2> 410752 T1758 C841 P53003 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:38764/collection1/, StdNode: http://127.0.0.1:53003/collection1/, StdNode: http://127.0.0.1:43360/collection1/, StdNode: http://127.0.0.1:58026/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 410754 T1759 C841 P53003 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 410754 T1792 C840 P58026 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 410754 T1776 C843 P43360 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 410754 T1740 C842 P38764 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 410776 T1792 C840 P58026 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty4/index,segFN=segments_7,generation=7}
[junit4:junit4] 2> 410777 T1792 C840 P58026 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 410778 T1792 C840 P58026 oass.SolrIndexSearcher.<init> Opening Searcher@46bafa68 main
[junit4:junit4] 2> 410778 T1792 C840 P58026 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410779 T1803 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@46bafa68 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 410779 T1792 C840 P58026 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 25
[junit4:junit4] 2> 410786 T1740 C842 P38764 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty1/index,segFN=segments_7,generation=7}
[junit4:junit4] 2> 410787 T1740 C842 P38764 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 410788 T1740 C842 P38764 oass.SolrIndexSearcher.<init> Opening Searcher@4eff0c61 main
[junit4:junit4] 2> 410788 T1740 C842 P38764 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410789 T1749 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4eff0c61 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 410789 T1740 C842 P38764 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 35
[junit4:junit4] 2> 410826 T1759 C841 P53003 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty2/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 410827 T1759 C841 P53003 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 410826 T1776 C843 P43360 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371552169536/jetty3/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> 410828 T1776 C843 P43360 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 410829 T1759 C841 P53003 oass.SolrIndexSearcher.<init> Opening Searcher@511a90e2 main
[junit4:junit4] 2> 410829 T1776 C843 P43360 oass.SolrIndexSearcher.<init> Opening Searcher@4f025f06 main
[junit4:junit4] 2> 410830 T1776 C843 P43360 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410830 T1782 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:453)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.internal_addObject(DefaultMBeanServerInterceptor.java:1484)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:963)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:917)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:312)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:483)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:298)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1846)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1723)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] 2>
[junit4:junit4] 2> 410831 T1759 C841 P53003 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 410831 T1782 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4f025f06 main{StandardDirectoryReader(segments_6:5:nrt _0(4.4):c3 _1(4.4):c1)}
[junit4:junit4] 2> 410831 T1765 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@511a90e2 main{StandardDirectoryReader(segments_5:5:nrt _0(4.4):c2 _1(4.4):c2)}
[junit4:junit4] 2> 410832 T1776 C843 P43360 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 78
[junit4:junit4] 2> 410832 T1759 C841 P53003 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 78
[junit4:junit4] 2> 410833 T1758 C841 P53003 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 82
[junit4:junit4] 2> 410833 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 410836 T1741 C842 P38764 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 410839 T1757 C841 P53003 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 410842 T1774 C843 P43360 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 410845 T1791 C840 P58026 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 412846 T1705 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> check const of shard1
[junit4:junit4] 2> client0
[junit4:junit4] 2> PROPS:127.0.0.1:38764__collection1:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:38764_","base_url":"http://127.0.0.1:38764","leader":"true"}
[junit4:junit4] 2> 412849 T1740 C842 P38764 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> client1
[junit4:junit4] 2> PROPS:127.0.0.1:53003__collection1:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:53003_","base_url":"http://127.0.0.1:53003"}
[junit4:junit4] 2> 412852 T1756 C841 P53003 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> client2
[junit4:junit4] 2> PROPS:127.0.0.1:43360__collection1:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:43360_","base_url":"http://127.0.0.1:43360"}
[junit4:junit4] 2> 412854 T1776 C843 P43360 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> client3
[junit4:junit4] 2> PROPS:127.0.0.1:58026__collection1:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:58026_","base_url":"http://127.0.0.1:58026"}
[junit4:junit4] 2> 412856 T1792 C840 P58026 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> 412858 T1759 C841 P53003 oasc.SolrCore.execute [collecti
[...truncated too long message...]
"leader":"true"},
[junit4:junit4] 1> "127.0.0.1:58026__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:58026_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:58026"}}}},
[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:50200__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:50200_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:50200",
[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:38764_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:43360_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:50200_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:58026_ (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/89886042982842378-127.0.0.1:43360__collection1-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89886042982842380-127.0.0.1:58026__collection1-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89886042982842382-127.0.0.1:38764__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:43360_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:43360"}
[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/89886042982842371-127.0.0.1:50200__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:50200_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:50200"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (4)
[junit4:junit4] 1> /solr/overseer_elect/election/89886042982842378-127.0.0.1:43360_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89886042982842380-127.0.0.1:58026_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89886042982842371-127.0.0.1:50200_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89886042982842382-127.0.0.1:38764_-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89886042982842371-127.0.0.1:50200_-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=B59629D0C8B8BD7F -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=hr -Dtests.timezone=America/Argentina/San_Luis -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 100s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:38764/collection1lastClient and got 254 from http://127.0.0.1:43360/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([B59629D0C8B8BD7F:3470A7C8BFE7DD43]: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:662)
[junit4:junit4] 2> 487612 T1705 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 100024 T1704 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 487733 T1780 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 487733 T1780 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> 487733 T1780 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Appending, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=hr, timezone=America/Argentina/San_Luis
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic amd64/Sun Microsystems Inc. 1.6.0_45 (64-bit)/cpus=8,threads=3,free=195581544,total=466747392
[junit4:junit4] 2> NOTE: All tests run in this JVM: [DocumentBuilderTest, JsonLoaderTest, TestSerializedLuceneMatchVersion, FieldMutatingUpdateProcessorTest, AnalysisAfterCoreReloadTest, TestReplicationHandler, TestReversedWildcardFilterFactory, TestWriterPerf, TestSolrDeletionPolicy2, UUIDFieldTest, SuggesterTest, TestPropInjectDefaults, TestPseudoReturnFields, SolrCoreTest, TestTrie, TestFastWriter, TestRealTimeGet, LegacyHTMLStripCharFilterTest, CSVRequestHandlerTest, PluginInfoTest, TestValueSourceCache, ResponseLogComponentTest, FastVectorHighlighterTest, TestSolrCoreProperties, RecoveryZkTest, TestPerFieldSimilarity, BadComponentTest, DirectSolrConnectionTest, TestFieldCollectionResource, TestGroupingSearch, DateFieldTest, TestConfig, LukeRequestHandlerTest, TestCloudManagedSchemaAddField, ClusterStateUpdateTest, OverseerCollectionProcessorTest, TestDocumentBuilder, ScriptEngineTest, TestCharFilters, TestRandomDVFaceting, UpdateRequestProcessorFactoryTest, QueryEqualityTest, AlternateDirectoryTest, TestFaceting, TestSearchPerf, TestXIncludeConfig, BadCopyFieldTest, ChaosMonkeyNothingIsSafeTest, TestSchemaVersionResource, TestSurroundQueryParser, SOLR749Test, DistributedTermsComponentTest, CachingDirectoryFactoryTest, PreAnalyzedFieldTest, SearchHandlerTest, SynonymTokenizerTest, CircularListTest, SoftAutoCommitTest, RegexBoostProcessorTest, BinaryUpdateRequestHandlerTest, TestLRUCache, TestManagedSchema, FileBasedSpellCheckerTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 100.55s, 1 test, 1 failure <<< FAILURES!
[...truncated 608 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:392: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:372: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1246: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:890: There were test failures: 298 suites, 1253 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 39 minutes 8 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.6.0_45 -XX:-UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure