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/19 01:11:27 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b93) - Build #
6199 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6199/
Java: 32bit/jdk1.8.0-ea-b93 -server -XX:+UseG1GC
1 tests failed.
FAILED: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:33880/r/collection1lastClient and got 266 from http://127.0.0.1:45699/r/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:33880/r/collection1lastClient and got 266 from http://127.0.0.1:45699/r/collection1
at __randomizedtesting.SeedInfo.seed([14FA98A28E8105C6:951C16BAF9DE65FA]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:491)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9577 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 443369 T1801 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /r/
[junit4:junit4] 2> 443374 T1801 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-SyncSliceTest-1371596432910
[junit4:junit4] 2> 443375 T1801 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 443376 T1802 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 443476 T1801 oasc.ZkTestServer.run start zk server on port:54259
[junit4:junit4] 2> 443477 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 443530 T1808 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1335018 name:ZooKeeperConnection Watcher:127.0.0.1:54259 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 443531 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 443531 T1801 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 443538 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 443541 T1810 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f4ab0e name:ZooKeeperConnection Watcher:127.0.0.1:54259/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 443541 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 443542 T1801 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 443547 T1801 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 443551 T1801 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 443554 T1801 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 443557 T1801 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 443558 T1801 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 443562 T1801 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 443563 T1801 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 443570 T1801 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 443571 T1801 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 443574 T1801 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 443574 T1801 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 443577 T1801 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 443577 T1801 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 443580 T1801 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 443580 T1801 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 443582 T1801 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 443583 T1801 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 443585 T1801 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 443585 T1801 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 443588 T1801 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 443589 T1801 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 443593 T1803 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f5984a6100001, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 443664 T1801 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 443672 T1801 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40647
[junit4:junit4] 2> 443673 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 443674 T1801 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 443674 T1801 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371596433127
[junit4:junit4] 2> 443674 T1801 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371596433127/solr.xml
[junit4:junit4] 2> 443675 T1801 oasc.CoreContainer.<init> New CoreContainer 27867822
[junit4:junit4] 2> 443675 T1801 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371596433127/'
[junit4:junit4] 2> 443675 T1801 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371596433127/'
[junit4:junit4] 2> 443723 T1801 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 443724 T1801 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 443724 T1801 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 443724 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 443725 T1801 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 443725 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 443725 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 443726 T1801 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 443726 T1801 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 443726 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 443729 T1801 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 443730 T1801 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54259/solr
[junit4:junit4] 2> 443730 T1801 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 443731 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 443733 T1821 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b38c68 name:ZooKeeperConnection Watcher:127.0.0.1:54259 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 443733 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 443735 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 443738 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 443741 T1823 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11f7408 name:ZooKeeperConnection Watcher:127.0.0.1:54259/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 443741 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 443743 T1801 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 443745 T1801 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 443747 T1801 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 443749 T1801 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40647_r
[junit4:junit4] 2> 443750 T1801 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40647_r
[junit4:junit4] 2> 443752 T1801 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 443758 T1801 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 443760 T1801 oasc.Overseer.start Overseer (id=89888943827320835-127.0.0.1:40647_r-n_0000000000) starting
[junit4:junit4] 2> 443764 T1801 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 443766 T1825 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 443767 T1801 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 443769 T1801 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 443770 T1801 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 443772 T1824 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 443778 T1826 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 443778 T1826 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 445275 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 445275 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "node_name":"127.0.0.1:40647_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40647/r"}
[junit4:junit4] 2> 445276 T1824 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 445276 T1824 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 445296 T1823 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> 445779 T1826 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371596433127/collection1
[junit4:junit4] 2> 445780 T1826 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 445781 T1826 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 445781 T1826 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 445782 T1826 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371596433127/collection1/'
[junit4:junit4] 2> 445782 T1826 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1371596433127/collection1/lib/README' to classloader
[junit4:junit4] 2> 445783 T1826 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1371596433127/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 445813 T1826 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 445850 T1826 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 445852 T1826 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 445856 T1826 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 446251 T1826 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 446257 T1826 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 446259 T1826 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 446270 T1826 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 446273 T1826 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 446276 T1826 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 446277 T1826 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 446277 T1826 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 446277 T1826 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 446278 T1826 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 446278 T1826 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 446278 T1826 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 446286 T1826 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371596433127/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/
[junit4:junit4] 2> 446286 T1826 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@48a8dd
[junit4:junit4] 2> 446286 T1826 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 446287 T1826 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data
[junit4:junit4] 2> 446287 T1826 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index/
[junit4:junit4] 2> 446287 T1826 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 446287 T1826 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index
[junit4:junit4] 2> 446293 T1826 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@245e05; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 446294 T1826 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 446296 T1826 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 446297 T1826 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 446297 T1826 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 446298 T1826 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 446298 T1826 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 446299 T1826 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 446299 T1826 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 446300 T1826 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 446300 T1826 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 446302 T1826 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 446307 T1826 oass.SolrIndexSearcher.<init> Opening Searcher@1fea415 main
[junit4:junit4] 2> 446308 T1826 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 446308 T1826 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 446312 T1827 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1fea415 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 446314 T1826 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 446314 T1826 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40647/r collection:control_collection shard:shard1
[junit4:junit4] 2> 446315 T1826 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 446322 T1826 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 446324 T1826 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 446324 T1826 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 446325 T1826 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40647/r/collection1/
[junit4:junit4] 2> 446325 T1826 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 446325 T1826 oasc.SyncStrategy.syncToMe http://127.0.0.1:40647/r/collection1/ has no replicas
[junit4:junit4] 2> 446325 T1826 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40647/r/collection1/
[junit4:junit4] 2> 446326 T1826 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 446799 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 446806 T1823 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> 446831 T1826 oasc.ZkController.register We are http://127.0.0.1:40647/r/collection1/ and leader is http://127.0.0.1:40647/r/collection1/
[junit4:junit4] 2> 446831 T1826 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40647/r
[junit4:junit4] 2> 446832 T1826 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 446832 T1826 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 446832 T1826 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 446833 T1826 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 446834 T1801 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 446835 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 446835 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 446840 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 446841 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 446843 T1830 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@69e0d2 name:ZooKeeperConnection Watcher:127.0.0.1:54259/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 446843 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 446844 T1801 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 446846 T1801 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 446915 T1801 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 446917 T1801 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:33880
[junit4:junit4] 2> 446919 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 446919 T1801 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 446919 T1801 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371596436381
[junit4:junit4] 2> 446920 T1801 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371596436381/solr.xml
[junit4:junit4] 2> 446920 T1801 oasc.CoreContainer.<init> New CoreContainer 23752950
[junit4:junit4] 2> 446920 T1801 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371596436381/'
[junit4:junit4] 2> 446921 T1801 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371596436381/'
[junit4:junit4] 2> 446964 T1801 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 446965 T1801 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 446965 T1801 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 446965 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 446966 T1801 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 446966 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 446966 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 446967 T1801 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 446967 T1801 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 446967 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 446970 T1801 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 446971 T1801 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54259/solr
[junit4:junit4] 2> 446971 T1801 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 446972 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 446973 T1841 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f0f72c name:ZooKeeperConnection Watcher:127.0.0.1:54259 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 446974 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 446975 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 446978 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 446979 T1843 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1780e82 name:ZooKeeperConnection Watcher:127.0.0.1:54259/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 446980 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 446983 T1801 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 447985 T1801 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33880_r
[junit4:junit4] 2> 447986 T1801 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:33880_r
[junit4:junit4] 2> 447989 T1823 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 447989 T1830 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 447989 T1843 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 447990 T1823 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 447994 T1844 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 447995 T1844 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 448310 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 448311 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "node_name":"127.0.0.1:40647_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40647/r"}
[junit4:junit4] 2> 448314 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "node_name":"127.0.0.1:33880_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33880/r"}
[junit4:junit4] 2> 448314 T1824 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 448314 T1824 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 448319 T1843 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> 448319 T1830 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> 448320 T1823 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> 448996 T1844 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371596436381/collection1
[junit4:junit4] 2> 448996 T1844 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 448997 T1844 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 448997 T1844 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 448998 T1844 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371596436381/collection1/'
[junit4:junit4] 2> 448998 T1844 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1371596436381/collection1/lib/README' to classloader
[junit4:junit4] 2> 448999 T1844 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1371596436381/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 449028 T1844 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 449069 T1844 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 449071 T1844 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 449074 T1844 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 449463 T1844 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 449469 T1844 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 449471 T1844 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 449488 T1844 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 449491 T1844 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 449494 T1844 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 449495 T1844 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 449495 T1844 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 449495 T1844 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 449497 T1844 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 449497 T1844 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 449497 T1844 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 449497 T1844 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371596436381/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/
[junit4:junit4] 2> 449497 T1844 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@48a8dd
[junit4:junit4] 2> 449498 T1844 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 449498 T1844 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1
[junit4:junit4] 2> 449498 T1844 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index/
[junit4:junit4] 2> 449499 T1844 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 449499 T1844 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index
[junit4:junit4] 2> 449504 T1844 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 449504 T1844 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 449507 T1844 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 449507 T1844 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 449508 T1844 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 449509 T1844 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 449519 T1844 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 449520 T1844 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 449520 T1844 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 449520 T1844 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 449521 T1844 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 449522 T1844 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 449525 T1844 oass.SolrIndexSearcher.<init> Opening Searcher@107181 main
[junit4:junit4] 2> 449526 T1844 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 449526 T1844 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 449533 T1845 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@107181 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 449534 T1844 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 449534 T1844 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:33880/r collection:collection1 shard:shard1
[junit4:junit4] 2> 449535 T1844 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 449541 T1844 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 449544 T1844 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 449544 T1844 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 449544 T1844 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 449545 T1844 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 449545 T1844 oasc.SyncStrategy.syncToMe http://127.0.0.1:33880/r/collection1/ has no replicas
[junit4:junit4] 2> 449545 T1844 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 449545 T1844 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 449825 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 449830 T1830 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> 449830 T1823 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> 449830 T1843 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> 449852 T1844 oasc.ZkController.register We are http://127.0.0.1:33880/r/collection1/ and leader is http://127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 449852 T1844 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:33880/r
[junit4:junit4] 2> 449853 T1844 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 449853 T1844 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 449853 T1844 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 449857 T1844 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 449858 T1801 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 449859 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 449859 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 449958 T1801 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 449962 T1801 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50641
[junit4:junit4] 2> 449963 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 449963 T1801 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 449964 T1801 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371596439399
[junit4:junit4] 2> 449964 T1801 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371596439399/solr.xml
[junit4:junit4] 2> 449964 T1801 oasc.CoreContainer.<init> New CoreContainer 26462235
[junit4:junit4] 2> 449965 T1801 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371596439399/'
[junit4:junit4] 2> 449965 T1801 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371596439399/'
[junit4:junit4] 2> 450021 T1801 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 450022 T1801 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 450022 T1801 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 450022 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 450022 T1801 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 450023 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 450023 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 450023 T1801 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 450024 T1801 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 450024 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 450027 T1801 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 450028 T1801 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54259/solr
[junit4:junit4] 2> 450028 T1801 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 450029 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 450032 T1857 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11ad9c3 name:ZooKeeperConnection Watcher:127.0.0.1:54259 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 450032 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 450034 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 450041 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 450042 T1859 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ff0a0a name:ZooKeeperConnection Watcher:127.0.0.1:54259/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 450043 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 450046 T1801 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 451049 T1801 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50641_r
[junit4:junit4] 2> 451050 T1801 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50641_r
[junit4:junit4] 2> 451053 T1830 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 451053 T1843 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 451053 T1859 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 451054 T1843 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> 451053 T1823 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 451054 T1823 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> 451053 T1830 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> 451059 T1860 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 451059 T1860 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 451335 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 451336 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "node_name":"127.0.0.1:33880_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33880/r"}
[junit4:junit4] 2> 451339 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "node_name":"127.0.0.1:50641_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50641/r"}
[junit4:junit4] 2> 451339 T1824 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 451339 T1824 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 451342 T1843 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> 451342 T1830 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> 451342 T1859 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> 451342 T1823 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> 452061 T1860 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371596439399/collection1
[junit4:junit4] 2> 452061 T1860 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 452061 T1860 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 452062 T1860 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 452062 T1860 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371596439399/collection1/'
[junit4:junit4] 2> 452063 T1860 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1371596439399/collection1/lib/README' to classloader
[junit4:junit4] 2> 452063 T1860 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1371596439399/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 452092 T1860 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 452124 T1860 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 452125 T1860 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 452129 T1860 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 452506 T1860 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 452511 T1860 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 452514 T1860 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 452527 T1860 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 452529 T1860 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 452532 T1860 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 452533 T1860 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 452534 T1860 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 452534 T1860 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 452535 T1860 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 452535 T1860 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 452535 T1860 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 452535 T1860 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371596439399/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/
[junit4:junit4] 2> 452535 T1860 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@48a8dd
[junit4:junit4] 2> 452536 T1860 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 452536 T1860 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2
[junit4:junit4] 2> 452537 T1860 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index/
[junit4:junit4] 2> 452537 T1860 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 452537 T1860 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index
[junit4:junit4] 2> 452541 T1860 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cc4fba; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 452541 T1860 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 452543 T1860 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 452543 T1860 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 452544 T1860 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 452544 T1860 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 452545 T1860 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 452545 T1860 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 452545 T1860 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 452546 T1860 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 452546 T1860 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 452547 T1860 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 452550 T1860 oass.SolrIndexSearcher.<init> Opening Searcher@1a08211 main
[junit4:junit4] 2> 452551 T1860 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 452551 T1860 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 452556 T1861 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a08211 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 452558 T1860 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 452558 T1860 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50641/r collection:collection1 shard:shard1
[junit4:junit4] 2> 452561 T1860 oasc.ZkController.register We are http://127.0.0.1:50641/r/collection1/ and leader is http://127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 452562 T1860 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50641/r
[junit4:junit4] 2> 452562 T1860 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 452562 T1860 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C950 name=collection1 org.apache.solr.core.SolrCore@e8c4fb url=http://127.0.0.1:50641/r/collection1 node=127.0.0.1:50641_r C950_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, state=down, node_name=127.0.0.1:50641_r, base_url=http://127.0.0.1:50641/r}
[junit4:junit4] 2> 452562 T1862 C950 P50641 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 452563 T1860 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 452563 T1862 C950 P50641 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 452563 T1862 C950 P50641 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 452563 T1862 C950 P50641 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 452564 T1801 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 452564 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 452565 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 452567 T1862 C950 P50641 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 452570 T1837 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 452637 T1801 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 452639 T1801 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:45699
[junit4:junit4] 2> 452640 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 452640 T1801 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 452641 T1801 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371596442103
[junit4:junit4] 2> 452641 T1801 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371596442103/solr.xml
[junit4:junit4] 2> 452641 T1801 oasc.CoreContainer.<init> New CoreContainer 11033838
[junit4:junit4] 2> 452642 T1801 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371596442103/'
[junit4:junit4] 2> 452642 T1801 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371596442103/'
[junit4:junit4] 2> 452686 T1801 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 452686 T1801 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 452687 T1801 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 452687 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 452687 T1801 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 452688 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 452688 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 452688 T1801 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 452689 T1801 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 452689 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 452703 T1801 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 452704 T1801 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54259/solr
[junit4:junit4] 2> 452704 T1801 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 452705 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 452706 T1874 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11a68c9 name:ZooKeeperConnection Watcher:127.0.0.1:54259 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 452707 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 452709 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 452712 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 452713 T1876 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@65010f name:ZooKeeperConnection Watcher:127.0.0.1:54259/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 452714 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 452718 T1801 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 452848 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 452849 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "node_name":"127.0.0.1:50641_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50641/r"}
[junit4:junit4] 2> 452852 T1843 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> 452852 T1830 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> 452852 T1859 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> 452852 T1876 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> 452852 T1823 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> 453571 T1837 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 453571 T1837 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={action=PREPRECOVERY&onlyIfLeader=true&core=collection1&checkLive=true&nodeName=127.0.0.1:50641_r&wt=javabin&state=recovering&version=2&coreNodeName=3} status=0 QTime=1001
[junit4:junit4] 2> 453721 T1801 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45699_r
[junit4:junit4] 2> 453722 T1801 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45699_r
[junit4:junit4] 2> 453724 T1823 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> 453724 T1859 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> 453724 T1876 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> 453724 T1843 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 453724 T1830 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> 453725 T1843 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> 453725 T1859 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 453726 T1823 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 453726 T1876 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 453726 T1830 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 453729 T1877 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 453730 T1877 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 454356 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 454357 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "node_name":"127.0.0.1:45699_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45699/r"}
[junit4:junit4] 2> 454357 T1824 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 454357 T1824 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 454361 T1823 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> 454361 T1830 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> 454361 T1859 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> 454361 T1876 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> 454361 T1843 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> 454734 T1877 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371596442103/collection1
[junit4:junit4] 2> 454734 T1877 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 454735 T1877 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 454735 T1877 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 454736 T1877 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371596442103/collection1/'
[junit4:junit4] 2> 454737 T1877 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1371596442103/collection1/lib/README' to classloader
[junit4:junit4] 2> 454737 T1877 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1371596442103/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 454782 T1877 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 454832 T1877 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 454834 T1877 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 454839 T1877 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 455247 T1877 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 455252 T1877 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 455255 T1877 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 455265 T1877 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 455268 T1877 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 455271 T1877 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 455271 T1877 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 455272 T1877 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 455272 T1877 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 455273 T1877 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 455273 T1877 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 455274 T1877 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 455274 T1877 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371596442103/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/
[junit4:junit4] 2> 455274 T1877 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@48a8dd
[junit4:junit4] 2> 455274 T1877 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 455275 T1877 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3
[junit4:junit4] 2> 455275 T1877 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index/
[junit4:junit4] 2> 455275 T1877 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 455276 T1877 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index
[junit4:junit4] 2> 455280 T1877 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e628e2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 455281 T1877 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 455282 T1877 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 455283 T1877 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 455283 T1877 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 455284 T1877 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 455284 T1877 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 455284 T1877 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 455285 T1877 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 455285 T1877 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 455285 T1877 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 455287 T1877 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 455289 T1877 oass.SolrIndexSearcher.<init> Opening Searcher@11535ab main
[junit4:junit4] 2> 455290 T1877 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 455290 T1877 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 455294 T1878 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@11535ab main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 455295 T1877 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 455295 T1877 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45699/r collection:collection1 shard:shard1
[junit4:junit4] 2> 455298 T1877 oasc.ZkController.register We are http://127.0.0.1:45699/r/collection1/ and leader is http://127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 455298 T1877 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45699/r
[junit4:junit4] 2> 455298 T1877 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 455299 T1877 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C951 name=collection1 org.apache.solr.core.SolrCore@277f02 url=http://127.0.0.1:45699/r/collection1 node=127.0.0.1:45699_r C951_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, state=down, node_name=127.0.0.1:45699_r, base_url=http://127.0.0.1:45699/r}
[junit4:junit4] 2> 455299 T1879 C951 P45699 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 455300 T1879 C951 P45699 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 455300 T1877 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 455300 T1879 C951 P45699 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 455300 T1879 C951 P45699 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 455301 T1801 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 455301 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 455301 T1879 C951 P45699 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 455301 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 455307 T1836 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 455369 T1801 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 455371 T1801 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60000
[junit4:junit4] 2> 455371 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 455372 T1801 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 455372 T1801 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371596444841
[junit4:junit4] 2> 455372 T1801 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371596444841/solr.xml
[junit4:junit4] 2> 455373 T1801 oasc.CoreContainer.<init> New CoreContainer 16118769
[junit4:junit4] 2> 455373 T1801 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371596444841/'
[junit4:junit4] 2> 455373 T1801 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371596444841/'
[junit4:junit4] 2> 455418 T1801 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 455419 T1801 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 455419 T1801 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 455419 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 455420 T1801 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 455420 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 455420 T1801 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 455420 T1801 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 455421 T1801 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 455421 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 455424 T1801 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 455425 T1801 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:54259/solr
[junit4:junit4] 2> 455425 T1801 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 455426 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 455427 T1891 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1221191 name:ZooKeeperConnection Watcher:127.0.0.1:54259 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 455428 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 455429 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 455432 T1801 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 455433 T1893 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f712a0 name:ZooKeeperConnection Watcher:127.0.0.1:54259/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 455433 T1801 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 455436 T1801 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C952 name=collection1 org.apache.solr.core.SolrCore@e8c4fb url=http://127.0.0.1:50641/r/collection1 node=127.0.0.1:50641_r C952_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=recovering, node_name=127.0.0.1:50641_r, base_url=http://127.0.0.1:50641/r}
[junit4:junit4] 2> 455572 T1862 C952 P50641 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:33880/r/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 455572 T1862 C952 P50641 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50641/r START replicas=[http://127.0.0.1:33880/r/collection1/] nUpdates=100
[junit4:junit4] 2> 455573 T1862 C952 P50641 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 455573 T1862 C952 P50641 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 455574 T1862 C952 P50641 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 455574 T1862 C952 P50641 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 455574 T1862 C952 P50641 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 455574 T1862 C952 P50641 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:33880/r/collection1/. core=collection1
[junit4:junit4] 2> 455575 T1862 C952 P50641 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C953 name=collection1 org.apache.solr.core.SolrCore@1f0016a url=http://127.0.0.1:33880/r/collection1 node=127.0.0.1:33880_r C953_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=active, node_name=127.0.0.1:33880_r, base_url=http://127.0.0.1:33880/r, leader=true}
[junit4:junit4] 2> 455578 T1837 C953 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 455580 T1839 C953 P33880 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 455581 T1839 C953 P33880 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 455582 T1839 C953 P33880 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 455589 T1839 C953 P33880 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 455589 T1839 C953 P33880 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 455590 T1839 C953 P33880 oass.SolrIndexSearcher.<init> Opening Searcher@7bbb17 realtime
[junit4:junit4] 2> 455590 T1839 C953 P33880 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 455590 T1839 C953 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={softCommit=false&openSearcher=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 10
[junit4:junit4] 2> 455591 T1862 C952 P50641 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 455591 T1862 C952 P50641 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 455595 T1837 C953 P33880 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 455595 T1837 C953 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=3
[junit4:junit4] 2> 455596 T1862 C952 P50641 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 455596 T1862 C952 P50641 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 455596 T1862 C952 P50641 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 455598 T1839 C953 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/replication params={command=filelist&qt=/replication&generation=2&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 455599 T1862 C952 P50641 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 455600 T1862 C952 P50641 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index.20130618200045134
[junit4:junit4] 2> 455600 T1862 C952 P50641 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index.20130618200045134 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1dc0b8; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 455603 T1838 C953 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/replication params={command=filecontent&checksum=true&qt=/replication&generation=2&wt=filestream&file=segments_2} status=0 QTime=0
[junit4:junit4] 2> 455604 T1862 C952 P50641 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 455609 T1862 C952 P50641 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 455609 T1862 C952 P50641 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 455611 T1862 C952 P50641 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cc4fba; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cc4fba; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 455611 T1862 C952 P50641 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 455612 T1862 C952 P50641 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 455612 T1862 C952 P50641 oass.SolrIndexSearcher.<init> Opening Searcher@ebe0cf main
[junit4:junit4] 2> 455613 T1861 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ebe0cf main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 455613 T1862 C952 P50641 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index.20130618200045134 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index.20130618200045134;done=true>>]
[junit4:junit4] 2> 455613 T1862 C952 P50641 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index.20130618200045134
[junit4:junit4] 2> 455614 T1862 C952 P50641 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index.20130618200045134
[junit4:junit4] 2> 455614 T1862 C952 P50641 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 455614 T1862 C952 P50641 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 455614 T1862 C952 P50641 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 455614 T1862 C952 P50641 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 455616 T1862 C952 P50641 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 455866 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 455867 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "node_name":"127.0.0.1:45699_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45699/r"}
[junit4:junit4] 2> 455870 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "node_name":"127.0.0.1:50641_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50641/r"}
[junit4:junit4] 2> 455889 T1859 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> 455889 T1843 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> 455889 T1823 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> 455889 T1830 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> 455889 T1893 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> 455889 T1876 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> 456307 T1836 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 456308 T1836 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={action=PREPRECOVERY&onlyIfLeader=true&core=collection1&checkLive=true&nodeName=127.0.0.1:45699_r&wt=javabin&state=recovering&version=2&coreNodeName=4} status=0 QTime=1001
[junit4:junit4] 2> 456439 T1801 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60000_r
[junit4:junit4] 2> 456441 T1801 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60000_r
[junit4:junit4] 2> 456444 T1876 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> 456444 T1823 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> 456444 T1830 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 456444 T1843 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> 456445 T1859 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 456445 T1830 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> 456444 T1893 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 456445 T1859 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> 456446 T1893 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> 456447 T1876 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 456447 T1843 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 456447 T1823 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 456451 T1896 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 456451 T1896 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 457396 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 457397 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "node_name":"127.0.0.1:60000_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60000/r"}
[junit4:junit4] 2> 457397 T1824 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 457397 T1824 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 457402 T1823 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> 457402 T1859 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> 457402 T1843 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> 457402 T1876 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> 457402 T1830 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> 457402 T1893 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> 457452 T1896 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371596444841/collection1
[junit4:junit4] 2> 457453 T1896 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 457453 T1896 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 457454 T1896 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 457455 T1896 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371596444841/collection1/'
[junit4:junit4] 2> 457455 T1896 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1371596444841/collection1/lib/README' to classloader
[junit4:junit4] 2> 457456 T1896 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1371596444841/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 457482 T1896 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 457528 T1896 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 457530 T1896 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 457533 T1896 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 457865 T1896 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 457870 T1896 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 457873 T1896 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 457883 T1896 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 457886 T1896 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 457888 T1896 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 457889 T1896 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 457890 T1896 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 457890 T1896 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 457891 T1896 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 457891 T1896 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 457891 T1896 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 457891 T1896 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371596444841/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/
[junit4:junit4] 2> 457892 T1896 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@48a8dd
[junit4:junit4] 2> 457892 T1896 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 457892 T1896 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4
[junit4:junit4] 2> 457893 T1896 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index/
[junit4:junit4] 2> 457893 T1896 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 457893 T1896 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index
[junit4:junit4] 2> 457896 T1896 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b88852; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 457896 T1896 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 457898 T1896 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 457898 T1896 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 457899 T1896 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 457899 T1896 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 457900 T1896 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 457900 T1896 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 457900 T1896 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 457901 T1896 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 457901 T1896 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 457903 T1896 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 457905 T1896 oass.SolrIndexSearcher.<init> Opening Searcher@1f1e214 main
[junit4:junit4] 2> 457906 T1896 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 457906 T1896 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 457910 T1897 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f1e214 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 457912 T1896 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 457912 T1896 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60000/r collection:collection1 shard:shard1
[junit4:junit4] 2> 457914 T1896 oasc.ZkController.register We are http://127.0.0.1:60000/r/collection1/ and leader is http://127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 457914 T1896 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60000/r
[junit4:junit4] 2> 457914 T1896 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 457915 T1896 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C954 name=collection1 org.apache.solr.core.SolrCore@ef02d8 url=http://127.0.0.1:60000/r/collection1 node=127.0.0.1:60000_r C954_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, state=down, node_name=127.0.0.1:60000_r, base_url=http://127.0.0.1:60000/r}
[junit4:junit4] 2> 457915 T1898 C954 P60000 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 457915 T1896 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 457915 T1898 C954 P60000 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 457916 T1898 C954 P60000 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 457916 T1898 C954 P60000 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 457916 T1801 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 457917 T1801 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 457917 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 457917 T1898 C954 P60000 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 457920 T1801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 457921 T1839 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 457921 T1801 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 457921 T1801 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 457922 T1801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C955 name=collection1 org.apache.solr.core.SolrCore@277f02 url=http://127.0.0.1:45699/r/collection1 node=127.0.0.1:45699_r C955_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=recovering, node_name=127.0.0.1:45699_r, base_url=http://127.0.0.1:45699/r}
[junit4:junit4] 2> 458308 T1879 C955 P45699 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:33880/r/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 458309 T1879 C955 P45699 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45699/r START replicas=[http://127.0.0.1:33880/r/collection1/] nUpdates=100
[junit4:junit4] 2> 458309 T1879 C955 P45699 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 458309 T1879 C955 P45699 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 458309 T1879 C955 P45699 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 458309 T1879 C955 P45699 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 458310 T1879 C955 P45699 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 458310 T1879 C955 P45699 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:33880/r/collection1/. core=collection1
[junit4:junit4] 2> 458310 T1879 C955 P45699 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C956 name=collection1 org.apache.solr.core.SolrCore@1f0016a url=http://127.0.0.1:33880/r/collection1 node=127.0.0.1:33880_r C956_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=active, node_name=127.0.0.1:33880_r, base_url=http://127.0.0.1:33880/r, leader=true}
[junit4:junit4] 2> 458311 T1838 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 458313 T1837 C956 P33880 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 458319 T1837 C956 P33880 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 458319 T1837 C956 P33880 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 458319 T1837 C956 P33880 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 458320 T1837 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={softCommit=false&openSearcher=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 7
[junit4:junit4] 2> 458320 T1879 C955 P45699 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 458320 T1879 C955 P45699 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 458322 T1838 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 458323 T1879 C955 P45699 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 458323 T1879 C955 P45699 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 458323 T1879 C955 P45699 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 458325 T1837 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/replication params={command=filelist&qt=/replication&generation=3&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 458325 T1879 C955 P45699 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 458326 T1879 C955 P45699 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index.20130618200047860
[junit4:junit4] 2> 458326 T1879 C955 P45699 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index.20130618200047860 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c6cb07; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 458328 T1836 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/replication params={command=filecontent&checksum=true&qt=/replication&generation=3&wt=filestream&file=segments_3} status=0 QTime=0
[junit4:junit4] 2> 458329 T1879 C955 P45699 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 458332 T1879 C955 P45699 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 458332 T1879 C955 P45699 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 458333 T1879 C955 P45699 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e628e2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e628e2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 458334 T1879 C955 P45699 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 458334 T1879 C955 P45699 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 458334 T1879 C955 P45699 oass.SolrIndexSearcher.<init> Opening Searcher@1199875 main
[junit4:junit4] 2> 458335 T1878 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1199875 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 458336 T1879 C955 P45699 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index.20130618200047860 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index.20130618200047860;done=true>>]
[junit4:junit4] 2> 458336 T1879 C955 P45699 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index.20130618200047860
[junit4:junit4] 2> 458336 T1879 C955 P45699 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index.20130618200047860
[junit4:junit4] 2> 458336 T1879 C955 P45699 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 458337 T1879 C955 P45699 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 458337 T1879 C955 P45699 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 458337 T1879 C955 P45699 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 458338 T1879 C955 P45699 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 458906 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 458907 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "node_name":"127.0.0.1:60000_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60000/r"}
[junit4:junit4] 2> 458910 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "node_name":"127.0.0.1:45699_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45699/r"}
[junit4:junit4] 2> 458912 T1859 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> 458913 T1823 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> 458913 T1830 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> 458913 T1893 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> 458913 T1843 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> 458913 T1876 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> 458921 T1839 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 458922 T1839 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={action=PREPRECOVERY&onlyIfLeader=true&core=collection1&checkLive=true&nodeName=127.0.0.1:60000_r&wt=javabin&state=recovering&version=2&coreNodeName=5} status=0 QTime=1001
[junit4:junit4] 2> 458923 T1801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 459925 T1801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C954_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=recovering, node_name=127.0.0.1:60000_r, base_url=http://127.0.0.1:60000/r}
[junit4:junit4] 2> 460922 T1898 C954 P60000 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:33880/r/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 460923 T1898 C954 P60000 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:60000/r START replicas=[http://127.0.0.1:33880/r/collection1/] nUpdates=100
[junit4:junit4] 2> 460923 T1898 C954 P60000 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 460923 T1898 C954 P60000 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 460923 T1898 C954 P60000 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 460923 T1898 C954 P60000 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 460924 T1898 C954 P60000 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 460924 T1898 C954 P60000 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:33880/r/collection1/. core=collection1
[junit4:junit4] 2> 460924 T1898 C954 P60000 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 460925 T1837 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 460926 T1801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 460928 T1836 C956 P33880 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 460939 T1836 C956 P33880 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 460939 T1836 C956 P33880 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 460940 T1836 C956 P33880 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 460940 T1836 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={softCommit=false&openSearcher=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 13
[junit4:junit4] 2> 460940 T1898 C954 P60000 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 460941 T1898 C954 P60000 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 460942 T1839 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 460943 T1898 C954 P60000 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 460943 T1898 C954 P60000 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 460943 T1898 C954 P60000 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 460945 T1837 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/replication params={command=filelist&qt=/replication&generation=4&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 460945 T1898 C954 P60000 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 460946 T1898 C954 P60000 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index.20130618200050481
[junit4:junit4] 2> 460947 T1898 C954 P60000 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index.20130618200050481 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ea6553; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 460949 T1836 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/replication params={command=filecontent&checksum=true&qt=/replication&generation=4&wt=filestream&file=segments_4} status=0 QTime=0
[junit4:junit4] 2> 460950 T1898 C954 P60000 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 460951 T1898 C954 P60000 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 460951 T1898 C954 P60000 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 460953 T1898 C954 P60000 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b88852; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b88852; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 460954 T1898 C954 P60000 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 460954 T1898 C954 P60000 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 460954 T1898 C954 P60000 oass.SolrIndexSearcher.<init> Opening Searcher@dbaa63 main
[junit4:junit4] 2> 460955 T1897 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@dbaa63 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 460956 T1898 C954 P60000 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index.20130618200050481 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index.20130618200050481;done=true>>]
[junit4:junit4] 2> 460956 T1898 C954 P60000 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index.20130618200050481
[junit4:junit4] 2> 460956 T1898 C954 P60000 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index.20130618200050481
[junit4:junit4] 2> 460956 T1898 C954 P60000 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 460956 T1898 C954 P60000 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 460957 T1898 C954 P60000 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 460957 T1898 C954 P60000 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 460958 T1898 C954 P60000 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 461919 T1824 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 461920 T1824 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "node_name":"127.0.0.1:60000_r",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60000/r"}
[junit4:junit4] 2> 461923 T1876 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> 461924 T1843 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> 461924 T1823 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> 461924 T1893 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> 461924 T1830 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> 461923 T1859 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> 461927 T1801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 461928 T1801 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C957 name=collection1 org.apache.solr.core.SolrCore@19c0d9 url=http://127.0.0.1:40647/r/collection1 node=127.0.0.1:40647_r C957_STATE=coll:control_collection core:collection1 props:{shard=shard1, core=collection1, collection=control_collection, state=active, node_name=127.0.0.1:40647_r, base_url=http://127.0.0.1:40647/r, leader=true}
[junit4:junit4] 2> 461933 T1817 C957 P40647 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 461935 T1817 C957 P40647 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@245e05; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 461936 T1817 C957 P40647 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 461949 T1817 C957 P40647 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@245e05; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@245e05; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 461949 T1817 C957 P40647 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 461950 T1817 C957 P40647 oass.SolrIndexSearcher.<init> Opening Searcher@47ccf9 main
[junit4:junit4] 2> 461950 T1817 C957 P40647 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 461951 T1827 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@47ccf9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 461951 T1817 C957 P40647 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={softCommit=false&commit=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 18
[junit4:junit4] 2> ASYNC NEW_CORE C958 name=collection1 org.apache.solr.core.SolrCore@e8c4fb url=http://127.0.0.1:50641/r/collection1 node=127.0.0.1:50641_r C958_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=active, node_name=127.0.0.1:50641_r, base_url=http://127.0.0.1:50641/r}
[junit4:junit4] 2> 461958 T1855 C958 P50641 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:33880/r/collection1/, StdNode: http://127.0.0.1:50641/r/collection1/, StdNode: http://127.0.0.1:45699/r/collection1/, StdNode: http://127.0.0.1:60000/r/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 461961 T1852 C958 P50641 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 461962 T1836 C956 P33880 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C955_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=active, node_name=127.0.0.1:45699_r, base_url=http://127.0.0.1:45699/r}
[junit4:junit4] 2> 461965 T1871 C955 P45699 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C954_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=active, node_name=127.0.0.1:60000_r, base_url=http://127.0.0.1:60000/r}
[junit4:junit4] 2> 461965 T1889 C954 P60000 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 461979 T1836 C956 P33880 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 461979 T1836 C956 P33880 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 461980 T1836 C956 P33880 oass.SolrIndexSearcher.<init> Opening Searcher@3b51b main
[junit4:junit4] 2> 461980 T1836 C956 P33880 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 461981 T1845 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3b51b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 461981 T1836 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={expungeDeletes=false&softCommit=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 19
[junit4:junit4] 2> 461999 T1852 C958 P50641 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cc4fba; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cc4fba; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 461999 T1852 C958 P50641 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 461999 T1871 C955 P45699 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e628e2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e628e2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 462000 T1871 C955 P45699 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 462000 T1889 C954 P60000 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b88852; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b88852; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 462001 T1871 C955 P45699 oass.SolrIndexSearcher.<init> Opening Searcher@79beb7 main
[junit4:junit4] 2> 462000 T1852 C958 P50641 oass.SolrIndexSearcher.<init> Opening Searcher@1d27a60 main
[junit4:junit4] 2> 462001 T1871 C955 P45699 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 462001 T1889 C954 P60000 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 462002 T1878 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@79beb7 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 462002 T1861 oasc.JmxMonitoredMap.put WARN Failed to register info bean: fieldValueCache javax.management.InstanceNotFoundException: solr/collection1:id=org.apache.solr.search.FastLRUCache,type=fieldValueCache
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getMBean(DefaultMBeanServerInterceptor.java:1095)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean(DefaultMBeanServerInterceptor.java:427)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean(DefaultMBeanServerInterceptor.java:415)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean(JmxMBeanServer.java:537)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:138)
[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:303)
[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.run(FutureTask.java:262)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 462002 T1852 C958 P50641 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 462003 T1861 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d27a60 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 462003 T1889 C954 P60000 oass.SolrIndexSearcher.<init> Opening Searcher@1a68ae2 main
[junit4:junit4] 2> 462003 T1871 C955 P45699 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={expungeDeletes=false&softCommit=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 38
[junit4:junit4] 2> 462004 T1889 C954 P60000 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 462004 T1852 C958 P50641 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={expungeDeletes=false&softCommit=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 43
[junit4:junit4] 2> 462005 T1897 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a68ae2 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 462005 T1889 C954 P60000 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={expungeDeletes=false&softCommit=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 40
[junit4:junit4] 2> 462006 T1855 C958 P50641 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={softCommit=false&commit=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 48
[junit4:junit4] 2> 462007 T1801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 462009 T1839 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/select params={q=*:*&distrib=false&wt=javabin&tests=checkShardConsistency&rows=0&version=2} hits=0 status=0 QTime=1
[junit4:junit4] 2> 462010 T1854 C958 P50641 oasc.SolrCore.execute [collection1] webapp=/r path=/select params={q=*:*&distrib=false&wt=javabin&tests=checkShardConsistency&rows=0&version=2} hits=0 status=0 QTime=0
[junit4:junit4] 2> 462012 T1872 C955 P45699 oasc.SolrCore.execute [collection1] webapp=/r path=/select params={q=*:*&distrib=false&wt=javabin&tests=checkShardConsistency&rows=0&version=2} hits=0 status=0 QTime=1
[junit4:junit4] 2> 462013 T1886 C954 P60000 oasc.SolrCore.execute [collection1] webapp=/r path=/select params={q=*:*&distrib=false&wt=javabin&tests=checkShardConsistency&rows=0&version=2} hits=0 status=0 QTime=0
[junit4:junit4] 2> 464017 T1816 C957 P40647 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438223122878693376)} 0 1
[junit4:junit4] 2> 464028 T1871 C955 P45699 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={update.from=http://127.0.0.1:33880/r/collection1/&_version_=-1438223122883936256&update.distrib=FROMLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438223122883936256)} 0 1
[junit4:junit4] 2> 464028 T1855 C958 P50641 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={update.from=http://127.0.0.1:33880/r/collection1/&_version_=-1438223122883936256&update.distrib=FROMLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438223122883936256)} 0 1
[junit4:junit4] 2> 464028 T1889 C954 P60000 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={update.from=http://127.0.0.1:33880/r/collection1/&_version_=-1438223122883936256&update.distrib=FROMLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438223122883936256)} 0 1
[junit4:junit4] 2> 464029 T1838 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438223122883936256)} 0 9
[junit4:junit4] 2> 464030 T1872 C955 P45699 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 11
[junit4:junit4] 2> 464033 T1817 C957 P40647 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&version=2} {add=[0 (1438223122895470592)]} 0 1
[junit4:junit4] 2> 464041 T1852 C958 P50641 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:33880/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438223122900713472)]} 0 1
[junit4:junit4] 2> 464041 T1869 C955 P45699 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:33880/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438223122900713472)]} 0 1
[junit4:junit4] 2> 464041 T1887 C954 P60000 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:33880/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438223122900713472)]} 0 1
[junit4:junit4] 2> 464042 T1839 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:50641/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1438223122900713472)]} 0 5
[junit4:junit4] 2> 464042 T1854 C958 P50641 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&version=2} {add=[0]} 0 7
[junit4:junit4] 2> 464045 T1818 C957 P40647 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&version=2} {add=[1 (1438223122908053504)]} 0 1
[junit4:junit4] 2> 464050 T1886 C954 P60000 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:33880/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438223122912247808)]} 0 0
[junit4:junit4] 2> 464051 T1870 C955 P45699 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:33880/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438223122912247808)]} 0 1
[junit4:junit4] 2> 464051 T1853 C958 P50641 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:33880/r/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438223122912247808)]} 0 1
[junit4:junit4] 2> 464052 T1836 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:60000/r/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1438223122912247808)]} 0 4
[junit4:junit4] 2> 464052 T1888 C954 P60000 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&version=2} {add=[1]} 0 6
[junit4:junit4] 2> 464055 T1819 C957 P40647 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&version=2} {add=[2 (1438223122918539264)]} 0 1
[junit4:junit4] 2> 464056 T1838 C956 P33880 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:50641/r/collection1/]
[junit4:junit4] 2> 464056 T1838 C956 P33880 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:50641/r/collection1/ against:[http://127.0.0.1:50641/r/collection1/] result:true
[junit4:junit4] 2> 464057 T1838 C956 P33880 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:45699/r/collection1/ against:[http://127.0.0.1:50641/r/collection1/] result:false
[junit4:junit4] 2> 464057 T1838 C956 P33880 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:60000/r/collection1/ against:[http://127.0.0.1:50641/r/collection1/] result:false
[junit4:junit4] 2> 464060 T1871 C955 P45699 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:33880/r/collection1/&update.distrib=FROMLEADER&wt=javabin&test.distrib.skip.servers=http://127.0.0.1:50641/r/collection1/&version=2} {add=[2 (1438223122921684992)]} 0 0
[junit4:junit4] 2> 464060 T1889 C954 P60000 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:33880/r/collection1/&update.distrib=FROMLEADER&wt=javabin&test.distrib.skip.servers=http://127.0.0.1:50641/r/collection1/&version=2} {add=[2 (1438223122921684992)]} 0 0
[junit4:junit4] 2> 464061 T1838 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&test.distrib.skip.servers=http://127.0.0.1:50641/r/collection1/&version=2} {add=[2 (1438223122921684992)]} 0 5
[junit4:junit4] 2> 464063 T1816 C957 P40647 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&version=2} {add=[3 (1438223122927976448)]} 0 0
[junit4:junit4] 2> 464066 T1839 C956 P33880 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:50641/r/collection1/, http://127.0.0.1:45699/r/collection1/]
[junit4:junit4] 2> 464066 T1839 C956 P33880 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:50641/r/collection1/ against:[http://127.0.0.1:50641/r/collection1/, http://127.0.0.1:45699/r/collection1/] result:true
[junit4:junit4] 2> 464066 T1839 C956 P33880 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:45699/r/collection1/ against:[http://127.0.0.1:50641/r/collection1/, http://127.0.0.1:45699/r/collection1/] result:true
[junit4:junit4] 2> 464066 T1839 C956 P33880 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:60000/r/collection1/ against:[http://127.0.0.1:50641/r/collection1/, http://127.0.0.1:45699/r/collection1/] result:false
[junit4:junit4] 2> 464069 T1887 C954 P60000 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={distrib.from=http://127.0.0.1:33880/r/collection1/&update.distrib=FROMLEADER&wt=javabin&test.distrib.skip.servers=http://127.0.0.1:50641/r/collection1/&version=2} {add=[3 (1438223122932170752)]} 0 0
[junit4:junit4] 2> 464070 T1839 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={wt=javabin&test.distrib.skip.servers=http://127.0.0.1:50641/r/collection1/&test.distrib.skip.servers=http://127.0.0.1:45699/r/collection1/&version=2} {add=[3 (1438223122932170752)]} 0 5
[junit4:junit4] 2> 464072 T1817 C957 P40647 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464119 T1817 C957 P40647 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@245e05; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@245e05; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 464119 T1817 C957 P40647 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 464121 T1817 C957 P40647 oass.SolrIndexSearcher.<init> Opening Searcher@175f386 main
[junit4:junit4] 2> 464121 T1817 C957 P40647 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 464122 T1827 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@175f386 main{StandardDirectoryReader(segments_3:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 464122 T1817 C957 P40647 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={softCommit=false&commit=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 50
[junit4:junit4] 2> 464125 T1837 C956 P33880 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:33880/r/collection1/, StdNode: http://127.0.0.1:50641/r/collection1/, StdNode: http://127.0.0.1:45699/r/collection1/, StdNode: http://127.0.0.1:60000/r/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 464126 T1836 C956 P33880 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464127 T1872 C955 P45699 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464127 T1886 C954 P60000 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464127 T1855 C958 P50641 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464149 T1836 C956 P33880 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 464149 T1836 C956 P33880 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 464151 T1836 C956 P33880 oass.SolrIndexSearcher.<init> Opening Searcher@e03094 main
[junit4:junit4] 2> 464151 T1836 C956 P33880 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 464152 T1845 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e03094 main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 464152 T1836 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={expungeDeletes=false&softCommit=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 26
[junit4:junit4] 2> 464179 T1886 C954 P60000 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b88852; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b88852; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 464179 T1886 C954 P60000 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 464179 T1872 C955 P45699 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e628e2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e628e2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 464180 T1872 C955 P45699 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 464179 T1855 C958 P50641 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cc4fba; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cc4fba; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 464181 T1855 C958 P50641 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 464181 T1886 C954 P60000 oass.SolrIndexSearcher.<init> Opening Searcher@5152fe main
[junit4:junit4] 2> 464182 T1886 C954 P60000 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 464182 T1872 C955 P45699 oass.SolrIndexSearcher.<init> Opening Searcher@783c83 main
[junit4:junit4] 2> 464183 T1855 C958 P50641 oass.SolrIndexSearcher.<init> Opening Searcher@38e2d8 main
[junit4:junit4] 2> 464183 T1872 C955 P45699 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 464183 T1897 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5152fe main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 464184 T1861 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@38e2d8 main{StandardDirectoryReader(segments_4:3:nrt _0(5.0):c2)}
[junit4:junit4] 2> 464183 T1878 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@783c83 main{StandardDirectoryReader(segments_5:3:nrt _0(5.0):c3)}
[junit4:junit4] 2> 464183 T1855 C958 P50641 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 464185 T1872 C955 P45699 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={expungeDeletes=false&softCommit=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 58
[junit4:junit4] 2> 464185 T1886 C954 P60000 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={expungeDeletes=false&softCommit=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 58
[junit4:junit4] 2> 464185 T1855 C958 P50641 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={expungeDeletes=false&softCommit=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 58
[junit4:junit4] 2> 464186 T1837 C956 P33880 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={softCommit=false&commit=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 62
[junit4:junit4] 2> 464187 T1801 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 464188 T1801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 464188 T1801 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 464190 T1838 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/select params={q=*:*&distrib=false&wt=javabin&tests=checkShardConsistency&rows=0&version=2} hits=4 status=0 QTime=0
[junit4:junit4] 2> 464193 T1852 C958 P50641 oasc.SolrCore.execute [collection1] webapp=/r path=/select params={q=*:*&distrib=false&wt=javabin&tests=checkShardConsistency&rows=0&version=2} hits=2 status=0 QTime=1
[junit4:junit4] 2> 464195 T1869 C955 P45699 oasc.SolrCore.execute [collection1] webapp=/r path=/select params={q=*:*&distrib=false&wt=javabin&tests=checkShardConsistency&rows=0&version=2} hits=3 status=0 QTime=0
[junit4:junit4] 2> 464197 T1888 C954 P60000 oasc.SolrCore.execute [collection1] webapp=/r path=/select params={q=*:*&distrib=false&wt=javabin&tests=checkShardConsistency&rows=0&version=2} hits=4 status=0 QTime=0
[junit4:junit4] 2> 464199 T1801 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 464204 T1870 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 464204 T1870 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 464208 T1839 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 464208 T1839 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 464208 T1839 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:33880/r START replicas=[http://127.0.0.1:50641/r/collection1/, http://127.0.0.1:45699/r/collection1/, http://127.0.0.1:60000/r/collection1/] nUpdates=100
[junit4:junit4] 2> 464210 T1889 C954 P60000 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 464210 T1872 C955 P45699 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 464210 T1853 C958 P50641 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 464210 T1839 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:33880/r Received 5 versions from 127.0.0.1:60000/r/collection1/
[junit4:junit4] 2> 464211 T1839 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:33880/r Our versions are newer. ourLowThreshold=1438223122883936256 otherHigh=1438223122921684992
[junit4:junit4] 2> 464211 T1839 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:33880/r Received 4 versions from 127.0.0.1:45699/r/collection1/
[junit4:junit4] 2> 464211 T1839 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:33880/r Our versions are newer. ourLowThreshold=1438223122883936256 otherHigh=1438223122921684992
[junit4:junit4] 2> 464212 T1839 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:33880/r Received 3 versions from 127.0.0.1:50641/r/collection1/
[junit4:junit4] 2> 464212 T1839 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:33880/r Our versions are newer. ourLowThreshold=1438223122883936256 otherHigh=1438223122912247808
[junit4:junit4] 2> 464212 T1839 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:33880/r DONE. sync succeeded
[junit4:junit4] 2> 464212 T1839 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 464213 T1839 oasc.SyncStrategy.syncToMe http://127.0.0.1:33880/r/collection1/: try and ask http://127.0.0.1:50641/r/collection1/ to sync
[junit4:junit4] 2> 464213 T1839 oasc.SyncStrategy.syncToMe http://127.0.0.1:33880/r/collection1/: try and ask http://127.0.0.1:45699/r/collection1/ to sync
[junit4:junit4] 2> 464213 T1839 oasc.SyncStrategy.syncToMe http://127.0.0.1:33880/r/collection1/: try and ask http://127.0.0.1:60000/r/collection1/ to sync
[junit4:junit4] 2> 464214 T1852 C958 P50641 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50641/r START replicas=[http://127.0.0.1:33880/r/collection1/] nUpdates=100
[junit4:junit4] 2> 464214 T1869 C955 P45699 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45699/r START replicas=[http://127.0.0.1:33880/r/collection1/] nUpdates=100
[junit4:junit4] 2> 464214 T1887 C954 P60000 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:60000/r START replicas=[http://127.0.0.1:33880/r/collection1/] nUpdates=100
[junit4:junit4] 2> 464215 T1836 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 464216 T1837 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 464216 T1836 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&distrib=false&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 464216 T1887 C954 P60000 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:60000/r Received 5 versions from 127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 464216 T1869 C955 P45699 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:45699/r Received 5 versions from 127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 464217 T1887 C954 P60000 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:60000/r Our versions are newer. ourLowThreshold=1438223122883936256 otherHigh=1438223122921684992
[junit4:junit4] 2> 464217 T1852 C958 P50641 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:50641/r Received 5 versions from 127.0.0.1:33880/r/collection1/
[junit4:junit4] 2> 464217 T1887 C954 P60000 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:60000/r DONE. sync succeeded
[junit4:junit4] 2> 464217 T1869 C955 P45699 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:45699/r Requesting updates from 127.0.0.1:33880/r/collection1/n=1 versions=[1438223122932170752]
[junit4:junit4] 2> 464218 T1887 C954 P60000 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&sync=http://127.0.0.1:33880/r/collection1/&distrib=false&wt=javabin&version=2} status=0 QTime=4
[junit4:junit4] 2> 464218 T1852 C958 P50641 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:50641/r Requesting updates from 127.0.0.1:33880/r/collection1/n=2 versions=[1438223122932170752, 1438223122921684992]
[junit4:junit4] 2> 464219 T1839 oasc.SyncStrategy.syncToMe http://127.0.0.1:33880/r/collection1/: sync completed with http://127.0.0.1:60000/r/collection1/
[junit4:junit4] 2> 464220 T1838 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={qt=/get&distrib=false&wt=javabin&version=2&getUpdates=1438223122932170752} status=0 QTime=0
[junit4:junit4] 2> 464220 T1837 C956 P33880 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={qt=/get&distrib=false&wt=javabin&version=2&getUpdates=1438223122932170752,1438223122921684992} status=0 QTime=0
[junit4:junit4] 2> 464222 T1869 C955 P45699 oasup.LogUpdateProcessor.finish [collection1] {add=[3 (1438223122932170752)]} 0 1
[junit4:junit4] 2> 464223 T1869 C955 P45699 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45699/r DONE. sync succeeded
[junit4:junit4] 2> 464223 T1852 C958 P50641 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438223122921684992), 3 (1438223122932170752)]} 0 2
[junit4:junit4] 2> 464223 T1869 C955 P45699 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&sync=http://127.0.0.1:33880/r/collection1/&distrib=false&wt=javabin&version=2} status=0 QTime=9
[junit4:junit4] 2> 464223 T1852 C958 P50641 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50641/r DONE. sync succeeded
[junit4:junit4] 2> 464224 T1852 C958 P50641 oasc.SolrCore.execute [collection1] webapp=/r path=/get params={getVersions=100&qt=/get&sync=http://127.0.0.1:33880/r/collection1/&distrib=false&wt=javabin&version=2} status=0 QTime=10
[junit4:junit4] 2> 464224 T1839 oasc.SyncStrategy.syncToMe http://127.0.0.1:33880/r/collection1/: sync completed with http://127.0.0.1:45699/r/collection1/
[junit4:junit4] 2> 464224 T1839 oasc.SyncStrategy.syncToMe http://127.0.0.1:33880/r/collection1/: sync completed with http://127.0.0.1:50641/r/collection1/
[junit4:junit4] 2> 464225 T1839 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=17
[junit4:junit4] 2> 464225 T1870 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2} status=0 QTime=22
[junit4:junit4] 2> 464225 T1801 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 464226 T1801 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 464226 T1801 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 464227 T1801 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 464229 T1819 C957 P40647 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464279 T1819 C957 P40647 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@245e05; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@245e05; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 464279 T1819 C957 P40647 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 464280 T1819 C957 P40647 oass.SolrIndexSearcher.<init> Opening Searcher@1ee6f3 main
[junit4:junit4] 2> 464281 T1819 C957 P40647 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 464281 T1827 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ee6f3 main{StandardDirectoryReader(segments_3:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 464282 T1819 C957 P40647 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={softCommit=false&commit=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 53
[junit4:junit4] 2> 464284 T1871 C955 P45699 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:33880/r/collection1/, StdNode: http://127.0.0.1:50641/r/collection1/, StdNode: http://127.0.0.1:45699/r/collection1/, StdNode: http://127.0.0.1:60000/r/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 464285 T1854 C958 P50641 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464286 T1886 C954 P60000 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464286 T1869 C955 P45699 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464292 T1836 C956 P33880 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 464309 T1886 C954 P60000 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b88852; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b88852; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_7,generation=7}
[junit4:junit4] 2> 464309 T1886 C954 P60000 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 464310 T1886 C954 P60000 oass.SolrIndexSearcher.<init> Opening Searcher@23b2be main
[junit4:junit4] 2> 464310 T1886 C954 P60000 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 464311 T1897 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@23b2be main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 464312 T1886 C954 P60000 oasup.LogUpdateProcessor.finish [collection1] webapp=/r path=/update params={expungeDeletes=false&softCommit=false&commit=true&commit_end_point=true&wt=javabin&waitSearcher=true&version=2} {commit=} 0 26
[junit4:junit4] 2> 464319 T1836 C956 P33880 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371596432910/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1cac28e; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTe
[...truncated too long message...]
/solr/collections/collection1/leader_elect/shard1/election/89888943827320842-4-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89888943827320846-2-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89888943827320844-5-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/shards (0)
[junit4:junit4] 1> /solr/clusterstate.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "control_collection":{
[junit4:junit4] 1> "router":"compositeId",
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"1":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:40647_r",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40647/r",
[junit4:junit4] 1> "leader":"true"}}}}},
[junit4:junit4] 1> "collection1":{
[junit4:junit4] 1> "router":"compositeId",
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "2":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:33880_r",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:33880/r"},
[junit4:junit4] 1> "3":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "node_name":"127.0.0.1:50641_r",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:50641/r"},
[junit4:junit4] 1> "4":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:45699_r",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:45699/r",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "5":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:60000_r",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:60000/r"}}}}}}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (4)
[junit4:junit4] 1> /solr/overseer_elect/election/89888943827320844-127.0.0.1:60000_r-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89888943827320842-127.0.0.1:45699_r-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89888943827320835-127.0.0.1:40647_r-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89888943827320846-127.0.0.1:33880_r-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89888943827320835-127.0.0.1:40647_r-n_0000000000"}
[junit4:junit4] 1> /solr/aliases.json (0)
[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=14FA98A28E8105C6 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ja_JP -Dtests.timezone=America/Jujuy -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 98.8s J1 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:33880/r/collection1lastClient and got 266 from http://127.0.0.1:45699/r/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([14FA98A28E8105C6:951C16BAF9DE65FA]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4] > at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 542128 T1801 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 98762 T1800 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 542233 T1876 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 542233 T1876 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> 542233 T1876 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 543324 T1893 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 543325 T1893 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 543325 T1893 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=DummyCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=DUMMY, chunkSize=136), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=DUMMY, chunkSize=136)), sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=ja_JP, timezone=America/Jujuy
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=3,free=81841976,total=301989888
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestCollationField, ChaosMonkeySafeLeaderTest, DistanceFunctionTest, TestDFRSimilarityFactory, CopyFieldTest, DebugComponentTest, SuggesterWFSTTest, UpdateParamsTest, OutputWriterTest, TestManagedSchema, TestLuceneMatchVersion, FileUtilsTest, TestIndexSearcher, TestSolrJ, IndexBasedSpellCheckerTest, NumericFieldsTest, TimeZoneUtilsTest, SolrCmdDistributorTest, CachingDirectoryFactoryTest, SampleTest, HardAutoCommitTest, TestSchemaVersionResource, TestUpdate, URLClassifyProcessorTest, StandardRequestHandlerTest, TestAtomicUpdateErrorCases, IndexReaderFactoryTest, TestSolrXml, TestBM25SimilarityFactory, BadCopyFieldTest, TestUtils, TestFieldResource, TestSuggestSpellingConverter, TestHashPartitioner, EchoParamsTest, TestLMJelinekMercerSimilarityFactory, MultiTermTest, TestDistributedGrouping, PathHierarchyTokenizerFactoryTest, CurrencyFieldXmlFileTest, TestPartialUpdateDeduplication, BadIndexSchemaTest, NoCacheHeaderTest, DisMaxRequestHandlerTest, TestMergePolicyConfig, FullSolrCloudDistribCmdsTest, TestClassNameShortening, TestRTGBase, SortByFunctionTest, ZkNodePropsTest, TestStressReorder, TestReloadAndDeleteDocs, TestJmxMonitoredMap, TestDistributedSearch, RequestHandlersTest, TestCodecSupport, StatsComponentTest, ShardRoutingCustomTest, DirectUpdateHandlerTest, SolrTestCaseJ4Test, RequiredFieldsTest, TestComponentsName, UniqFieldsUpdateProcessorFactoryTest, TestShardHandlerFactory, JSONWriterTest, TestNumberUtils, TestCloudManagedSchemaAddField, TestRandomFaceting, TestCSVLoader, HighlighterConfigTest, TestUniqueKeyFieldResource, BasicDistributedZk2Test, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest, SyncSliceTest]
[junit4:junit4] Completed on J1 in 100.04s, 1 test, 1 failure <<< FAILURES!
[...truncated 499 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:887: There were test failures: 297 suites, 1252 tests, 1 failure, 16 ignored (7 assumptions)
Total time: 36 minutes 57 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.8.0-ea-b93 -server -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure