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/24 01:21:21 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.8.0-ea-b93) - Build #
6207 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6207/
Java: 32bit/jdk1.8.0-ea-b93 -server -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:56091/collection1lastClient and got 252 from http://127.0.0.1:38345/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:56091/collection1lastClient and got 252 from http://127.0.0.1:38345/collection1
at __randomizedtesting.SeedInfo.seed([27A493963144C4B9:A6421D8E461BA485]: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 9760 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 455201 T1464 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 455205 T1464 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1372029042573
[junit4:junit4] 2> 455206 T1464 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 455206 T1465 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 455306 T1464 oasc.ZkTestServer.run start zk server on port:58654
[junit4:junit4] 2> 455307 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 455331 T1471 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@eb4096 name:ZooKeeperConnection Watcher:127.0.0.1:58654 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 455331 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 455331 T1464 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 455335 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 455337 T1473 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ca0fb name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 455337 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 455338 T1464 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 455340 T1464 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 455343 T1464 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 455345 T1464 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 455347 T1464 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 455347 T1464 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 455351 T1464 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 455352 T1464 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 455355 T1464 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 455355 T1464 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 455357 T1464 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 455357 T1464 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 455359 T1464 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 455359 T1464 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 455361 T1464 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 455362 T1464 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 455364 T1464 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 455364 T1464 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 455366 T1464 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 455367 T1464 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 455368 T1464 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 455369 T1464 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 455455 T1464 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 455470 T1464 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54800
[junit4:junit4] 2> 455470 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 455471 T1464 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 455471 T1464 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372029042739
[junit4:junit4] 2> 455471 T1464 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372029042739/solr.xml
[junit4:junit4] 2> 455471 T1464 oasc.CoreContainer.<init> New CoreContainer 29891262
[junit4:junit4] 2> 455472 T1464 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372029042739/'
[junit4:junit4] 2> 455472 T1464 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372029042739/'
[junit4:junit4] 2> 455521 T1464 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 455522 T1464 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 455522 T1464 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 455522 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 455522 T1464 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 455523 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 455523 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 455523 T1464 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 455524 T1464 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 455524 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 455527 T1464 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 455527 T1464 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58654/solr
[junit4:junit4] 2> 455527 T1464 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 455528 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 455529 T1484 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18445d5 name:ZooKeeperConnection Watcher:127.0.0.1:58654 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 455530 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 455531 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 455534 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 455535 T1486 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18d9d32 name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 455535 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 455536 T1464 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 455538 T1464 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 455542 T1464 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 455544 T1464 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54800_
[junit4:junit4] 2> 455545 T1464 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54800_
[junit4:junit4] 2> 455547 T1464 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 455551 T1464 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 455553 T1464 oasc.Overseer.start Overseer (id=89917295334260739-127.0.0.1:54800_-n_0000000000) starting
[junit4:junit4] 2> 455556 T1464 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 455560 T1488 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 455561 T1464 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 455564 T1464 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 455567 T1464 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 455571 T1487 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 455577 T1489 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 455577 T1489 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 457074 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 457074 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54800",
[junit4:junit4] 2> "node_name":"127.0.0.1:54800_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 457074 T1487 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 457075 T1487 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 457077 T1486 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> 457579 T1489 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372029042739/collection1
[junit4:junit4] 2> 457579 T1489 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 457580 T1489 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 457580 T1489 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 457581 T1489 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372029042739/collection1/'
[junit4:junit4] 2> 457582 T1489 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372029042739/collection1/lib/README' to classloader
[junit4:junit4] 2> 457582 T1489 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372029042739/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 457616 T1489 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 457660 T1489 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 457661 T1489 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 457664 T1489 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 458044 T1489 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 458045 T1489 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 458045 T1489 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 458051 T1489 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 458053 T1489 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 458062 T1489 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 458065 T1489 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 458067 T1489 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 458068 T1489 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 458068 T1489 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 458068 T1489 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 458069 T1489 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 458069 T1489 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 458069 T1489 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 458069 T1489 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372029042739/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/
[junit4:junit4] 2> 458070 T1489 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1e60620
[junit4:junit4] 2> 458070 T1489 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 458070 T1489 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data
[junit4:junit4] 2> 458071 T1489 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index/
[junit4:junit4] 2> 458071 T1489 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 458071 T1489 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index
[junit4:junit4] 2> 458074 T1489 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@9df93a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 458074 T1489 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 458076 T1489 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 458076 T1489 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 458077 T1489 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 458077 T1489 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 458077 T1489 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 458078 T1489 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 458078 T1489 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 458078 T1489 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 458078 T1489 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 458080 T1489 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 458083 T1489 oass.SolrIndexSearcher.<init> Opening Searcher@1febf69 main
[junit4:junit4] 2> 458083 T1489 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 458084 T1489 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 458087 T1490 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1febf69 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 458088 T1489 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 458088 T1489 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54800 collection:control_collection shard:shard1
[junit4:junit4] 2> 458089 T1489 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 458099 T1489 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 458100 T1489 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 458101 T1489 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 458101 T1489 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54800/collection1/
[junit4:junit4] 2> 458101 T1489 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 458101 T1489 oasc.SyncStrategy.syncToMe http://127.0.0.1:54800/collection1/ has no replicas
[junit4:junit4] 2> 458101 T1489 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54800/collection1/
[junit4:junit4] 2> 458102 T1489 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 458581 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 458587 T1486 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> 458607 T1489 oasc.ZkController.register We are http://127.0.0.1:54800/collection1/ and leader is http://127.0.0.1:54800/collection1/
[junit4:junit4] 2> 458607 T1489 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54800
[junit4:junit4] 2> 458607 T1489 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 458607 T1489 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 458607 T1489 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 458608 T1489 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 458609 T1464 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 458610 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 458610 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 458613 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 458614 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 458616 T1493 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17575bc name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 458616 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 458617 T1464 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 458619 T1464 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 458689 T1464 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 458690 T1464 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56091
[junit4:junit4] 2> 458691 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 458691 T1464 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 458692 T1464 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372029045987
[junit4:junit4] 2> 458692 T1464 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372029045987/solr.xml
[junit4:junit4] 2> 458692 T1464 oasc.CoreContainer.<init> New CoreContainer 25495429
[junit4:junit4] 2> 458692 T1464 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372029045987/'
[junit4:junit4] 2> 458693 T1464 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372029045987/'
[junit4:junit4] 2> 458740 T1464 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 458740 T1464 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 458740 T1464 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 458741 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 458741 T1464 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 458741 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 458742 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 458742 T1464 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 458742 T1464 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 458742 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 458746 T1464 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 458747 T1464 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58654/solr
[junit4:junit4] 2> 458747 T1464 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 458748 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 458750 T1504 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1cabf8c name:ZooKeeperConnection Watcher:127.0.0.1:58654 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 458750 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 458752 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 458755 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 458756 T1506 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@abacaa name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 458756 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 458760 T1464 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 459762 T1464 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56091_
[junit4:junit4] 2> 459764 T1464 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56091_
[junit4:junit4] 2> 459767 T1486 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 459767 T1493 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 459767 T1486 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> 459767 T1506 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 459771 T1507 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 459771 T1507 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 460093 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 460094 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54800",
[junit4:junit4] 2> "node_name":"127.0.0.1:54800_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 460098 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56091",
[junit4:junit4] 2> "node_name":"127.0.0.1:56091_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 460098 T1487 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 460099 T1487 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 460103 T1506 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> 460103 T1486 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> 460103 T1493 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> 460772 T1507 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372029045987/collection1
[junit4:junit4] 2> 460773 T1507 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 460774 T1507 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 460774 T1507 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 460775 T1507 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372029045987/collection1/'
[junit4:junit4] 2> 460775 T1507 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372029045987/collection1/lib/README' to classloader
[junit4:junit4] 2> 460776 T1507 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372029045987/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 460798 T1507 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 460835 T1507 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 460836 T1507 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 460839 T1507 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 461148 T1507 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 461149 T1507 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 461149 T1507 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 461154 T1507 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 461156 T1507 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 461167 T1507 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 461170 T1507 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 461172 T1507 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 461173 T1507 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 461173 T1507 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 461173 T1507 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 461174 T1507 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 461174 T1507 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 461174 T1507 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 461175 T1507 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372029045987/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/
[junit4:junit4] 2> 461175 T1507 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1e60620
[junit4:junit4] 2> 461175 T1507 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 461175 T1507 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1
[junit4:junit4] 2> 461176 T1507 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index/
[junit4:junit4] 2> 461176 T1507 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 461176 T1507 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index
[junit4:junit4] 2> 461179 T1507 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 461179 T1507 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 461181 T1507 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 461181 T1507 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 461181 T1507 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 461182 T1507 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 461182 T1507 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 461182 T1507 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 461183 T1507 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 461183 T1507 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 461183 T1507 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 461185 T1507 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 461194 T1507 oass.SolrIndexSearcher.<init> Opening Searcher@268191 main
[junit4:junit4] 2> 461195 T1507 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 461195 T1507 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 461199 T1508 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@268191 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 461201 T1507 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 461202 T1507 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56091 collection:collection1 shard:shard1
[junit4:junit4] 2> 461202 T1507 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 461208 T1507 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 461210 T1507 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 461210 T1507 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 461210 T1507 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:56091/collection1/
[junit4:junit4] 2> 461210 T1507 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 461211 T1507 oasc.SyncStrategy.syncToMe http://127.0.0.1:56091/collection1/ has no replicas
[junit4:junit4] 2> 461211 T1507 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:56091/collection1/
[junit4:junit4] 2> 461211 T1507 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 461610 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 461615 T1486 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> 461615 T1493 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> 461615 T1506 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> 461617 T1507 oasc.ZkController.register We are http://127.0.0.1:56091/collection1/ and leader is http://127.0.0.1:56091/collection1/
[junit4:junit4] 2> 461617 T1507 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56091
[junit4:junit4] 2> 461617 T1507 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 461617 T1507 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 461617 T1507 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 461619 T1507 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 461619 T1464 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 461620 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 461620 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 461687 T1464 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 461688 T1464 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47814
[junit4:junit4] 2> 461689 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 461690 T1464 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 461690 T1464 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372029048991
[junit4:junit4] 2> 461690 T1464 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372029048991/solr.xml
[junit4:junit4] 2> 461690 T1464 oasc.CoreContainer.<init> New CoreContainer 25241099
[junit4:junit4] 2> 461691 T1464 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372029048991/'
[junit4:junit4] 2> 461691 T1464 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372029048991/'
[junit4:junit4] 2> 461727 T1464 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 461728 T1464 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 461728 T1464 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 461728 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 461729 T1464 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 461729 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 461729 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 461730 T1464 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 461730 T1464 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 461730 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 461733 T1464 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 461733 T1464 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58654/solr
[junit4:junit4] 2> 461734 T1464 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 461734 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 461736 T1520 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16bd808 name:ZooKeeperConnection Watcher:127.0.0.1:58654 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 461736 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 461737 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 461740 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 461741 T1522 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1de779d name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 461742 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 461744 T1464 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 462747 T1464 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47814_
[junit4:junit4] 2> 462748 T1464 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47814_
[junit4:junit4] 2> 462749 T1493 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> 462749 T1506 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> 462749 T1486 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> 462751 T1522 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 462751 T1493 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 462751 T1486 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 462752 T1506 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 462755 T1523 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 462755 T1523 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 463119 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 463119 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56091",
[junit4:junit4] 2> "node_name":"127.0.0.1:56091_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 463122 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47814",
[junit4:junit4] 2> "node_name":"127.0.0.1:47814_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 463122 T1487 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 463122 T1487 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 463124 T1486 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> 463124 T1522 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> 463124 T1493 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> 463124 T1506 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> 463756 T1523 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372029048991/collection1
[junit4:junit4] 2> 463757 T1523 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 463757 T1523 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 463758 T1523 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 463759 T1523 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372029048991/collection1/'
[junit4:junit4] 2> 463759 T1523 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372029048991/collection1/lib/README' to classloader
[junit4:junit4] 2> 463759 T1523 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372029048991/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 463795 T1523 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 463825 T1523 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 463826 T1523 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 463829 T1523 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 464152 T1523 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 464152 T1523 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 464153 T1523 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 464158 T1523 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 464160 T1523 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 464170 T1523 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 464172 T1523 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 464174 T1523 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 464175 T1523 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 464175 T1523 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 464175 T1523 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 464176 T1523 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 464176 T1523 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 464176 T1523 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 464176 T1523 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372029048991/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/
[junit4:junit4] 2> 464176 T1523 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1e60620
[junit4:junit4] 2> 464177 T1523 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 464177 T1523 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2
[junit4:junit4] 2> 464177 T1523 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index/
[junit4:junit4] 2> 464178 T1523 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 464178 T1523 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index
[junit4:junit4] 2> 464181 T1523 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25d94f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 464182 T1523 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 464183 T1523 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 464183 T1523 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 464184 T1523 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 464184 T1523 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 464185 T1523 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 464185 T1523 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 464185 T1523 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 464185 T1523 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 464186 T1523 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 464187 T1523 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 464189 T1523 oass.SolrIndexSearcher.<init> Opening Searcher@189836e main
[junit4:junit4] 2> 464190 T1523 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 464190 T1523 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 464193 T1524 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@189836e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 464195 T1523 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 464195 T1523 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47814 collection:collection1 shard:shard1
[junit4:junit4] 2> 464197 T1523 oasc.ZkController.register We are http://127.0.0.1:47814/collection1/ and leader is http://127.0.0.1:56091/collection1/
[junit4:junit4] 2> 464197 T1523 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47814
[junit4:junit4] 2> 464197 T1523 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 464197 T1523 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2425 name=collection1 org.apache.solr.core.SolrCore@1a8243c url=http://127.0.0.1:47814/collection1 node=127.0.0.1:47814_ C2425_STATE=coll:collection1 core:collection1 props:{collection=collection1, base_url=http://127.0.0.1:47814, node_name=127.0.0.1:47814_, state=down, core=collection1}
[junit4:junit4] 2> 464198 T1525 C2425 P47814 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 464198 T1525 C2425 P47814 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 464198 T1523 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 464198 T1525 C2425 P47814 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 464198 T1525 C2425 P47814 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 464199 T1464 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 464199 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 464199 T1525 C2425 P47814 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 464199 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 464204 T1500 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 464269 T1464 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 464271 T1464 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38345
[junit4:junit4] 2> 464272 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 464272 T1464 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 464272 T1464 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372029051571
[junit4:junit4] 2> 464273 T1464 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372029051571/solr.xml
[junit4:junit4] 2> 464273 T1464 oasc.CoreContainer.<init> New CoreContainer 7061179
[junit4:junit4] 2> 464273 T1464 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372029051571/'
[junit4:junit4] 2> 464273 T1464 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372029051571/'
[junit4:junit4] 2> 464321 T1464 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 464321 T1464 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 464321 T1464 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 464322 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 464322 T1464 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 464322 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 464322 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 464323 T1464 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 464323 T1464 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 464323 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 464326 T1464 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 464326 T1464 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58654/solr
[junit4:junit4] 2> 464327 T1464 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 464327 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 464329 T1537 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f365b name:ZooKeeperConnection Watcher:127.0.0.1:58654 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 464329 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 464331 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 464333 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 464334 T1539 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@165cd2d name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 464334 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 464337 T1464 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 464629 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 464630 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47814",
[junit4:junit4] 2> "node_name":"127.0.0.1:47814_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 464636 T1522 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> 464636 T1493 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> 464636 T1539 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> 464636 T1506 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> 464636 T1486 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> 465205 T1500 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 465205 T1500 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={checkLive=true&onlyIfLeader=true&action=PREPRECOVERY&version=2&wt=javabin&state=recovering&nodeName=127.0.0.1:47814_&coreNodeName=3&core=collection1} status=0 QTime=1001
[junit4:junit4] 2> 465340 T1464 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38345_
[junit4:junit4] 2> 465341 T1464 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38345_
[junit4:junit4] 2> 465343 T1539 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> 465343 T1486 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 465343 T1522 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 465343 T1486 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> 465344 T1506 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 465343 T1522 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> 465344 T1506 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> 465344 T1493 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 465344 T1493 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> 465345 T1539 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 465351 T1540 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 465351 T1540 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 466143 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 466144 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38345",
[junit4:junit4] 2> "node_name":"127.0.0.1:38345_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 466144 T1487 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 466144 T1487 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 466147 T1486 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> 466147 T1493 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> 466147 T1506 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> 466148 T1522 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> 466148 T1539 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> 466352 T1540 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372029051571/collection1
[junit4:junit4] 2> 466352 T1540 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 466353 T1540 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 466353 T1540 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 466354 T1540 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372029051571/collection1/'
[junit4:junit4] 2> 466355 T1540 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372029051571/collection1/lib/README' to classloader
[junit4:junit4] 2> 466355 T1540 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372029051571/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 466378 T1540 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 466414 T1540 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 466415 T1540 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 466418 T1540 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 466744 T1540 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 466745 T1540 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 466745 T1540 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 466751 T1540 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 466754 T1540 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 466765 T1540 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 466767 T1540 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 466769 T1540 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 466770 T1540 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 466770 T1540 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 466770 T1540 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 466771 T1540 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 466771 T1540 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 466771 T1540 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 466772 T1540 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372029051571/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/
[junit4:junit4] 2> 466772 T1540 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1e60620
[junit4:junit4] 2> 466772 T1540 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 466772 T1540 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3
[junit4:junit4] 2> 466773 T1540 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index/
[junit4:junit4] 2> 466773 T1540 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 466773 T1540 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index
[junit4:junit4] 2> 466776 T1540 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cb245; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 466776 T1540 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 466778 T1540 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 466778 T1540 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 466778 T1540 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 466779 T1540 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 466779 T1540 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 466779 T1540 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 466779 T1540 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 466780 T1540 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 466780 T1540 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 466781 T1540 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 466784 T1540 oass.SolrIndexSearcher.<init> Opening Searcher@1f5aad9 main
[junit4:junit4] 2> 466784 T1540 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 466785 T1540 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 466788 T1541 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f5aad9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 466789 T1540 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 466790 T1540 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38345 collection:collection1 shard:shard1
[junit4:junit4] 2> 466792 T1540 oasc.ZkController.register We are http://127.0.0.1:38345/collection1/ and leader is http://127.0.0.1:56091/collection1/
[junit4:junit4] 2> 466793 T1540 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38345
[junit4:junit4] 2> 466793 T1540 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 466793 T1540 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2426 name=collection1 org.apache.solr.core.SolrCore@18ae2f3 url=http://127.0.0.1:38345/collection1 node=127.0.0.1:38345_ C2426_STATE=coll:collection1 core:collection1 props:{collection=collection1, base_url=http://127.0.0.1:38345, node_name=127.0.0.1:38345_, state=down, core=collection1}
[junit4:junit4] 2> 466793 T1542 C2426 P38345 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 466794 T1542 C2426 P38345 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 466794 T1540 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 466794 T1542 C2426 P38345 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 466794 T1542 C2426 P38345 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 466795 T1464 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 466795 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 466795 T1542 C2426 P38345 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 466795 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 466799 T1499 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 466878 T1464 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 466880 T1464 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39247
[junit4:junit4] 2> 466880 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 466880 T1464 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 466881 T1464 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372029054166
[junit4:junit4] 2> 466881 T1464 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372029054166/solr.xml
[junit4:junit4] 2> 466881 T1464 oasc.CoreContainer.<init> New CoreContainer 5905738
[junit4:junit4] 2> 466882 T1464 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372029054166/'
[junit4:junit4] 2> 466882 T1464 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372029054166/'
[junit4:junit4] 2> 466933 T1464 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 466934 T1464 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 466934 T1464 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 466934 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 466935 T1464 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 466935 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 466935 T1464 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 466936 T1464 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 466936 T1464 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 466936 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 466939 T1464 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 466939 T1464 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58654/solr
[junit4:junit4] 2> 466940 T1464 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 466940 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 466942 T1554 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ad6a28 name:ZooKeeperConnection Watcher:127.0.0.1:58654 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 466942 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 466943 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 466946 T1464 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 466947 T1556 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b80873 name:ZooKeeperConnection Watcher:127.0.0.1:58654/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 466947 T1464 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 466950 T1464 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C2427 name=collection1 org.apache.solr.core.SolrCore@1a8243c url=http://127.0.0.1:47814/collection1 node=127.0.0.1:47814_ C2427_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:47814, node_name=127.0.0.1:47814_, state=recovering, core=collection1}
[junit4:junit4] 2> 467206 T1525 C2427 P47814 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:56091/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 467206 T1525 C2427 P47814 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:47814 START replicas=[http://127.0.0.1:56091/collection1/] nUpdates=100
[junit4:junit4] 2> 467206 T1525 C2427 P47814 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 467207 T1525 C2427 P47814 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 467207 T1525 C2427 P47814 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 467207 T1525 C2427 P47814 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 467207 T1525 C2427 P47814 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 467207 T1525 C2427 P47814 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:56091/collection1/. core=collection1
[junit4:junit4] 2> 467207 T1525 C2427 P47814 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2428 name=collection1 org.apache.solr.core.SolrCore@12248f url=http://127.0.0.1:56091/collection1 node=127.0.0.1:56091_ C2428_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:56091, node_name=127.0.0.1:56091_, state=active, core=collection1, leader=true}
[junit4:junit4] 2> 467212 T1502 C2428 P56091 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&version=2&wt=javabin&qt=/get} status=0 QTime=1
[junit4:junit4] 2> 467216 T1500 C2428 P56091 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 467218 T1500 C2428 P56091 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 467219 T1500 C2428 P56091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 467230 T1500 C2428 P56091 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 467231 T1500 C2428 P56091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 467231 T1500 C2428 P56091 oass.SolrIndexSearcher.<init> Opening Searcher@6d6399 realtime
[junit4:junit4] 2> 467231 T1500 C2428 P56091 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 467232 T1500 C2428 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={openSearcher=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 467233 T1525 C2427 P47814 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 467233 T1525 C2427 P47814 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 467250 T1502 C2428 P56091 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 467250 T1502 C2428 P56091 oasc.SolrCore.execute [collection1] webapp= path=/replication params={version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=16
[junit4:junit4] 2> 467251 T1525 C2427 P47814 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 467251 T1525 C2427 P47814 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 467252 T1525 C2427 P47814 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 467254 T1500 C2428 P56091 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=2&version=2&wt=javabin&qt=/replication&command=filelist} status=0 QTime=0
[junit4:junit4] 2> 467255 T1525 C2427 P47814 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 467256 T1525 C2427 P47814 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index.20130623171054623
[junit4:junit4] 2> 467257 T1525 C2427 P47814 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index.20130623171054623 lockFactory=org.apache.lucene.store.NativeFSLockFactory@159afb3; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 467260 T1501 C2428 P56091 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=2&checksum=true&wt=filestream&qt=/replication&file=segments_2&command=filecontent} status=0 QTime=0
[junit4:junit4] 2> 467261 T1525 C2427 P47814 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 467271 T1525 C2427 P47814 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 467272 T1525 C2427 P47814 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 467274 T1525 C2427 P47814 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25d94f; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25d94f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 467274 T1525 C2427 P47814 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 467274 T1525 C2427 P47814 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 467275 T1525 C2427 P47814 oass.SolrIndexSearcher.<init> Opening Searcher@1db5a8 main
[junit4:junit4] 2> 467276 T1524 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1db5a8 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 467276 T1525 C2427 P47814 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index.20130623171054623 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index.20130623171054623;done=true>>]
[junit4:junit4] 2> 467276 T1525 C2427 P47814 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index.20130623171054623
[junit4:junit4] 2> 467276 T1525 C2427 P47814 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index.20130623171054623
[junit4:junit4] 2> 467277 T1525 C2427 P47814 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 467277 T1525 C2427 P47814 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 467277 T1525 C2427 P47814 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 467277 T1525 C2427 P47814 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 467279 T1525 C2427 P47814 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 467652 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 467653 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38345",
[junit4:junit4] 2> "node_name":"127.0.0.1:38345_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 467656 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47814",
[junit4:junit4] 2> "node_name":"127.0.0.1:47814_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 467670 T1493 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> 467670 T1539 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> 467670 T1506 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> 467670 T1556 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> 467671 T1486 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> 467670 T1522 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> 467799 T1499 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 467800 T1499 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={checkLive=true&onlyIfLeader=true&action=PREPRECOVERY&version=2&wt=javabin&state=recovering&nodeName=127.0.0.1:38345_&coreNodeName=4&core=collection1} status=0 QTime=1001
[junit4:junit4] 2> 467953 T1464 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39247_
[junit4:junit4] 2> 467954 T1464 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39247_
[junit4:junit4] 2> 467957 T1556 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> 467957 T1506 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> 467958 T1486 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 467958 T1539 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 467959 T1539 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> 467959 T1493 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 467959 T1522 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 467960 T1522 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> 467959 T1486 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> 467960 T1493 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> 467961 T1506 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 467961 T1556 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 467969 T1559 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 467969 T1559 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 469179 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 469180 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39247",
[junit4:junit4] 2> "node_name":"127.0.0.1:39247_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 469180 T1487 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 469181 T1487 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 469185 T1506 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> 469185 T1486 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> 469185 T1556 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> 469185 T1493 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> 469185 T1522 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> 469185 T1539 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> ASYNC NEW_CORE C2429 name=collection1 org.apache.solr.core.SolrCore@18ae2f3 url=http://127.0.0.1:38345/collection1 node=127.0.0.1:38345_ C2429_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:38345, node_name=127.0.0.1:38345_, state=recovering, core=collection1}
[junit4:junit4] 2> 469800 T1542 C2429 P38345 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:56091/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 469801 T1542 C2429 P38345 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38345 START replicas=[http://127.0.0.1:56091/collection1/] nUpdates=100
[junit4:junit4] 2> 469801 T1542 C2429 P38345 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 469802 T1542 C2429 P38345 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 469802 T1542 C2429 P38345 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 469802 T1542 C2429 P38345 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 469802 T1542 C2429 P38345 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 469802 T1542 C2429 P38345 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:56091/collection1/. core=collection1
[junit4:junit4] 2> 469802 T1542 C2429 P38345 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 469803 T1500 C2428 P56091 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&version=2&wt=javabin&qt=/get} status=0 QTime=0
[junit4:junit4] 2> 469806 T1501 C2428 P56091 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 469820 T1501 C2428 P56091 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 469821 T1501 C2428 P56091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 469821 T1501 C2428 P56091 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 469821 T1501 C2428 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={openSearcher=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 15
[junit4:junit4] 2> 469822 T1542 C2429 P38345 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 469822 T1542 C2429 P38345 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 469824 T1499 C2428 P56091 oasc.SolrCore.execute [collection1] webapp= path=/replication params={version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=0
[junit4:junit4] 2> 469824 T1542 C2429 P38345 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 469825 T1542 C2429 P38345 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 469825 T1542 C2429 P38345 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 469827 T1500 C2428 P56091 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=3&version=2&wt=javabin&qt=/replication&command=filelist} status=0 QTime=1
[junit4:junit4] 2> 469827 T1542 C2429 P38345 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 469828 T1542 C2429 P38345 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index.20130623171057195
[junit4:junit4] 2> 469828 T1542 C2429 P38345 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index.20130623171057195 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17cf02e; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 469830 T1501 C2428 P56091 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=3&checksum=true&wt=filestream&qt=/replication&file=segments_3&command=filecontent} status=0 QTime=0
[junit4:junit4] 2> 469831 T1542 C2429 P38345 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 469833 T1542 C2429 P38345 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 469833 T1542 C2429 P38345 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 469835 T1542 C2429 P38345 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cb245; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cb245; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 469835 T1542 C2429 P38345 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 469835 T1542 C2429 P38345 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 469836 T1542 C2429 P38345 oass.SolrIndexSearcher.<init> Opening Searcher@19cce63 main
[junit4:junit4] 2> 469837 T1541 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19cce63 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 469837 T1542 C2429 P38345 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index.20130623171057195 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index.20130623171057195;done=true>>]
[junit4:junit4] 2> 469837 T1542 C2429 P38345 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index.20130623171057195
[junit4:junit4] 2> 469837 T1542 C2429 P38345 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index.20130623171057195
[junit4:junit4] 2> 469838 T1542 C2429 P38345 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 469838 T1542 C2429 P38345 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 469838 T1542 C2429 P38345 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 469838 T1542 C2429 P38345 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 469839 T1542 C2429 P38345 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 469971 T1559 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372029054166/collection1
[junit4:junit4] 2> 469971 T1559 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 469972 T1559 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 469972 T1559 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 469974 T1559 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372029054166/collection1/'
[junit4:junit4] 2> 469974 T1559 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372029054166/collection1/lib/README' to classloader
[junit4:junit4] 2> 469975 T1559 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372029054166/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 470006 T1559 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 470046 T1559 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 470048 T1559 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 470052 T1559 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 470391 T1559 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 470392 T1559 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 470392 T1559 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 470397 T1559 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 470399 T1559 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 470410 T1559 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 470412 T1559 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 470415 T1559 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 470416 T1559 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 470416 T1559 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 470416 T1559 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 470417 T1559 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 470417 T1559 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 470417 T1559 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 470417 T1559 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372029054166/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/
[junit4:junit4] 2> 470417 T1559 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1e60620
[junit4:junit4] 2> 470418 T1559 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 470418 T1559 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4
[junit4:junit4] 2> 470418 T1559 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index/
[junit4:junit4] 2> 470419 T1559 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 470419 T1559 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index
[junit4:junit4] 2> 470442 T1559 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@801632; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 470442 T1559 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 470444 T1559 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 470444 T1559 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 470444 T1559 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 470445 T1559 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 470445 T1559 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 470445 T1559 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 470447 T1559 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 470447 T1559 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 470447 T1559 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 470449 T1559 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 470451 T1559 oass.SolrIndexSearcher.<init> Opening Searcher@12b6243 main
[junit4:junit4] 2> 470452 T1559 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 470452 T1559 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 470455 T1562 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@12b6243 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 470457 T1559 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 470457 T1559 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39247 collection:collection1 shard:shard1
[junit4:junit4] 2> 470460 T1559 oasc.ZkController.register We are http://127.0.0.1:39247/collection1/ and leader is http://127.0.0.1:56091/collection1/
[junit4:junit4] 2> 470460 T1559 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39247
[junit4:junit4] 2> 470460 T1559 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 470460 T1559 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2430 name=collection1 org.apache.solr.core.SolrCore@1aa70e url=http://127.0.0.1:39247/collection1 node=127.0.0.1:39247_ C2430_STATE=coll:collection1 core:collection1 props:{collection=collection1, base_url=http://127.0.0.1:39247, node_name=127.0.0.1:39247_, state=down, core=collection1}
[junit4:junit4] 2> 470461 T1563 C2430 P39247 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 470461 T1559 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 470461 T1563 C2430 P39247 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 470462 T1563 C2430 P39247 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 470462 T1563 C2430 P39247 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 470462 T1464 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 470462 T1464 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 470463 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 470463 T1563 C2430 P39247 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 470467 T1500 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 470467 T1464 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 470468 T1464 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 470469 T1464 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 470469 T1464 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 470689 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 470690 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38345",
[junit4:junit4] 2> "node_name":"127.0.0.1:38345_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 470693 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39247",
[junit4:junit4] 2> "node_name":"127.0.0.1:39247_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 470695 T1556 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> 470695 T1539 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> 470695 T1522 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> 470695 T1486 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> 470695 T1493 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> 470695 T1506 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> 471467 T1500 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 471468 T1500 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={checkLive=true&onlyIfLeader=true&action=PREPRECOVERY&version=2&wt=javabin&state=recovering&nodeName=127.0.0.1:39247_&coreNodeName=5&core=collection1} status=0 QTime=1001
[junit4:junit4] 2> 471471 T1464 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 472472 T1464 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C2430_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:39247, node_name=127.0.0.1:39247_, state=recovering, core=collection1}
[junit4:junit4] 2> 473468 T1563 C2430 P39247 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:56091/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 473469 T1563 C2430 P39247 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:39247 START replicas=[http://127.0.0.1:56091/collection1/] nUpdates=100
[junit4:junit4] 2> 473469 T1563 C2430 P39247 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 473469 T1563 C2430 P39247 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 473469 T1563 C2430 P39247 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 473470 T1563 C2430 P39247 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 473470 T1563 C2430 P39247 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 473470 T1563 C2430 P39247 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:56091/collection1/. core=collection1
[junit4:junit4] 2> 473470 T1563 C2430 P39247 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2431 name=collection1 org.apache.solr.core.SolrCore@12248f url=http://127.0.0.1:56091/collection1 node=127.0.0.1:56091_ C2431_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:56091, node_name=127.0.0.1:56091_, state=active, core=collection1, leader=true}
[junit4:junit4] 2> 473471 T1501 C2431 P56091 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&version=2&wt=javabin&qt=/get} status=0 QTime=0
[junit4:junit4] 2> 473473 T1502 C2431 P56091 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 473474 T1464 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 473480 T1502 C2431 P56091 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 473481 T1502 C2431 P56091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 473481 T1502 C2431 P56091 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 473481 T1502 C2431 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={openSearcher=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 473482 T1563 C2430 P39247 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 473482 T1563 C2430 P39247 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 473484 T1501 C2431 P56091 oasc.SolrCore.execute [collection1] webapp= path=/replication params={version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=0
[junit4:junit4] 2> 473484 T1563 C2430 P39247 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 473485 T1563 C2430 P39247 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 473485 T1563 C2430 P39247 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 473487 T1500 C2431 P56091 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=4&version=2&wt=javabin&qt=/replication&command=filelist} status=0 QTime=1
[junit4:junit4] 2> 473487 T1563 C2430 P39247 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 473488 T1563 C2430 P39247 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index.20130623171100855
[junit4:junit4] 2> 473488 T1563 C2430 P39247 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index.20130623171100855 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3c3324; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 473491 T1502 C2431 P56091 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=4&checksum=true&wt=filestream&qt=/replication&file=segments_4&command=filecontent} status=0 QTime=0
[junit4:junit4] 2> 473492 T1563 C2430 P39247 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 473503 T1563 C2430 P39247 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 473503 T1563 C2430 P39247 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 473504 T1563 C2430 P39247 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@801632; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@801632; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 473505 T1563 C2430 P39247 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 473505 T1563 C2430 P39247 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 473505 T1563 C2430 P39247 oass.SolrIndexSearcher.<init> Opening Searcher@d38720 main
[junit4:junit4] 2> 473506 T1562 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d38720 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 473507 T1563 C2430 P39247 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index.20130623171100855 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index.20130623171100855;done=true>>]
[junit4:junit4] 2> 473507 T1563 C2430 P39247 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index.20130623171100855
[junit4:junit4] 2> 473507 T1563 C2430 P39247 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index.20130623171100855
[junit4:junit4] 2> 473507 T1563 C2430 P39247 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 473507 T1563 C2430 P39247 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 473508 T1563 C2430 P39247 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 473508 T1563 C2430 P39247 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 473509 T1563 C2430 P39247 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 473702 T1487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 473703 T1487 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39247",
[junit4:junit4] 2> "node_name":"127.0.0.1:39247_",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 473724 T1539 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> 473724 T1556 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> 473724 T1493 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> 473724 T1506 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> 473724 T1522 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> 473724 T1486 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> 474476 T1464 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 474477 T1464 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C2432 name=collection1 org.apache.solr.core.SolrCore@12f6ccf url=http://127.0.0.1:54800/collection1 node=127.0.0.1:54800_ C2432_STATE=coll:control_collection core:collection1 props:{collection=control_collection, shard=shard1, base_url=http://127.0.0.1:54800, node_name=127.0.0.1:54800_, state=active, core=collection1, leader=true}
[junit4:junit4] 2> 474490 T1482 C2432 P54800 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 474494 T1482 C2432 P54800 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@9df93a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 474494 T1482 C2432 P54800 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 474500 T1482 C2432 P54800 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@9df93a; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@9df93a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 474501 T1482 C2432 P54800 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 474501 T1482 C2432 P54800 oass.SolrIndexSearcher.<init> Opening Searcher@512fab main
[junit4:junit4] 2> 474501 T1482 C2432 P54800 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 474502 T1490 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@512fab main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 474503 T1482 C2432 P54800 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> C2430_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:39247, node_name=127.0.0.1:39247_, state=active, core=collection1}
[junit4:junit4] 2> 474510 T1550 C2430 P39247 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:56091/collection1/, StdNode: http://127.0.0.1:47814/collection1/, StdNode: http://127.0.0.1:38345/collection1/, StdNode: http://127.0.0.1:39247/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 474512 T1502 C2431 P56091 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 474512 T1552 C2430 P39247 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2433 name=collection1 org.apache.solr.core.SolrCore@1a8243c url=http://127.0.0.1:47814/collection1 node=127.0.0.1:47814_ C2433_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:47814, node_name=127.0.0.1:47814_, state=active, core=collection1}
[junit4:junit4] 2> 474517 T1515 C2433 P47814 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2434 name=collection1 org.apache.solr.core.SolrCore@18ae2f3 url=http://127.0.0.1:38345/collection1 node=127.0.0.1:38345_ C2434_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:38345, node_name=127.0.0.1:38345_, state=active, core=collection1}
[junit4:junit4] 2> 474517 T1535 C2434 P38345 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 474540 T1552 C2430 P39247 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@801632; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@801632; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 474540 T1502 C2431 P56091 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 474542 T1502 C2431 P56091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 474541 T1552 C2430 P39247 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 474543 T1502 C2431 P56091 oass.SolrIndexSearcher.<init> Opening Searcher@71b0db main
[junit4:junit4] 2> 474544 T1552 C2430 P39247 oass.SolrIndexSearcher.<init> Opening Searcher@161a578 main
[junit4:junit4] 2> 474544 T1502 C2431 P56091 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 474545 T1552 C2430 P39247 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 474546 T1562 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@161a578 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 474545 T1508 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71b0db main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 474546 T1552 C2430 P39247 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 34
[junit4:junit4] 2> 474546 T1502 C2431 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 34
[junit4:junit4] 2> 474560 T1535 C2434 P38345 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cb245; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cb245; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 474561 T1535 C2434 P38345 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 474560 T1515 C2433 P47814 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25d94f; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25d94f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 474561 T1535 C2434 P38345 oass.SolrIndexSearcher.<init> Opening Searcher@407d97 main
[junit4:junit4] 2> 474561 T1515 C2433 P47814 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 474562 T1535 C2434 P38345 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 474562 T1541 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@407d97 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 474562 T1515 C2433 P47814 oass.SolrIndexSearcher.<init> Opening Searcher@67e652 main
[junit4:junit4] 2> 474563 T1535 C2434 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 46
[junit4:junit4] 2> 474563 T1515 C2433 P47814 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 474563 T1524 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@67e652 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 474564 T1515 C2433 P47814 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 47
[junit4:junit4] 2> 474564 T1550 C2430 P39247 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 55
[junit4:junit4] 2> 474565 T1464 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 474567 T1501 C2431 P56091 oasc.SolrCore.execute [collection1] webapp= path=/select params={rows=0&distrib=false&tests=checkShardConsistency&q=*:*&version=2&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 2> 474568 T1517 C2433 P47814 oasc.SolrCore.execute [collection1] webapp= path=/select params={rows=0&distrib=false&tests=checkShardConsistency&q=*:*&version=2&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 2> 474570 T1534 C2434 P38345 oasc.SolrCore.execute [collection1] webapp= path=/select params={rows=0&distrib=false&tests=checkShardConsistency&q=*:*&version=2&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 2> 474571 T1549 C2430 P39247 oasc.SolrCore.execute [collection1] webapp= path=/select params={rows=0&distrib=false&tests=checkShardConsistency&q=*:*&version=2&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 2> 476575 T1481 C2432 P54800 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1438676747750998016)} 0 2
[junit4:junit4] 2> ASYNC NEW_CORE C2435 name=collection1 org.apache.solr.core.SolrCore@1aa70e url=http://127.0.0.1:39247/collection1 node=127.0.0.1:39247_ C2435_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:39247, node_name=127.0.0.1:39247_, state=active, core=collection1}
[junit4:junit4] 2> 476589 T1550 C2435 P39247 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.from=http://127.0.0.1:56091/collection1/&version=2&wt=javabin&_version_=-1438676747754143744&update.distrib=FROMLEADER} {deleteByQuery=*:* (-1438676747754143744)} 0 10
[junit4:junit4] 2> ASYNC NEW_CORE C2436 name=collection1 org.apache.solr.core.SolrCore@18ae2f3 url=http://127.0.0.1:38345/collection1 node=127.0.0.1:38345_ C2436_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:38345, node_name=127.0.0.1:38345_, state=active, core=collection1}
[junit4:junit4] 2> 476589 T1534 C2436 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.from=http://127.0.0.1:56091/collection1/&version=2&wt=javabin&_version_=-1438676747754143744&update.distrib=FROMLEADER} {deleteByQuery=*:* (-1438676747754143744)} 0 10
[junit4:junit4] 2> ASYNC NEW_CORE C2437 name=collection1 org.apache.solr.core.SolrCore@1a8243c url=http://127.0.0.1:47814/collection1 node=127.0.0.1:47814_ C2437_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:47814, node_name=127.0.0.1:47814_, state=active, core=collection1}
[junit4:junit4] 2> 476589 T1516 C2437 P47814 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.from=http://127.0.0.1:56091/collection1/&version=2&wt=javabin&_version_=-1438676747754143744&update.distrib=FROMLEADER} {deleteByQuery=*:* (-1438676747754143744)} 0 10
[junit4:junit4] 2> ASYNC NEW_CORE C2438 name=collection1 org.apache.solr.core.SolrCore@12248f url=http://127.0.0.1:56091/collection1 node=127.0.0.1:56091_ C2438_STATE=coll:collection1 core:collection1 props:{collection=collection1, shard=shard1, base_url=http://127.0.0.1:56091, node_name=127.0.0.1:56091_, state=active, core=collection1, leader=true}
[junit4:junit4] 2> 476590 T1499 C2438 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1438676747754143744)} 0 14
[junit4:junit4] 2> ASYNC NEW_CORE C2439 name=collection1 org.apache.solr.core.SolrCore@12f6ccf url=http://127.0.0.1:54800/collection1 node=127.0.0.1:54800_ C2439_STATE=coll:control_collection core:collection1 props:{collection=control_collection, shard=shard1, base_url=http://127.0.0.1:54800, node_name=127.0.0.1:54800_, state=active, core=collection1, leader=true}
[junit4:junit4] 2> 476594 T1482 C2439 P54800 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0 (1438676747771969536)]} 0 1
[junit4:junit4] 2> 476602 T1551 C2435 P39247 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[0 (1438676747777212416)]} 0 1
[junit4:junit4] 2> 476602 T1517 C2437 P47814 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[0 (1438676747777212416)]} 0 1
[junit4:junit4] 2> 476602 T1532 C2436 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[0 (1438676747777212416)]} 0 1
[junit4:junit4] 2> 476603 T1501 C2438 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&distrib.from=http://127.0.0.1:39247/collection1/&update.distrib=TOLEADER} {add=[0 (1438676747777212416)]} 0 5
[junit4:junit4] 2> 476603 T1549 C2435 P39247 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0]} 0 7
[junit4:junit4] 2> 476606 T1479 C2439 P54800 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1 (1438676747784552448)]} 0 1
[junit4:junit4] 2> 476611 T1552 C2435 P39247 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[1 (1438676747787698176)]} 0 1
[junit4:junit4] 2> 476611 T1533 C2436 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[1 (1438676747787698176)]} 0 1
[junit4:junit4] 2> 476611 T1518 C2437 P47814 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[1 (1438676747787698176)]} 0 1
[junit4:junit4] 2> 476612 T1500 C2438 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1 (1438676747787698176)]} 0 4
[junit4:junit4] 2> 476614 T1480 C2439 P54800 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[2 (1438676747793989632)]} 0 1
[junit4:junit4] 2> 476617 T1502 C2438 P56091 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:47814/collection1/]
[junit4:junit4] 2> 476617 T1502 C2438 P56091 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:47814/collection1/ against:[http://127.0.0.1:47814/collection1/] result:true
[junit4:junit4] 2> 476618 T1502 C2438 P56091 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:38345/collection1/ against:[http://127.0.0.1:47814/collection1/] result:false
[junit4:junit4] 2> 476618 T1502 C2438 P56091 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:39247/collection1/ against:[http://127.0.0.1:47814/collection1/] result:false
[junit4:junit4] 2> 476621 T1534 C2436 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:47814/collection1/&version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[2 (1438676747798183936)]} 0 1
[junit4:junit4] 2> 476621 T1550 C2435 P39247 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:47814/collection1/&version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[2 (1438676747798183936)]} 0 0
[junit4:junit4] 2> 476622 T1502 C2438 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:47814/collection1/&version=2&wt=javabin&distrib.from=http://127.0.0.1:38345/collection1/&update.distrib=TOLEADER} {add=[2 (1438676747798183936)]} 0 5
[junit4:junit4] 2> 476622 T1535 C2436 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:47814/collection1/&version=2&wt=javabin} {add=[2]} 0 7
[junit4:junit4] 2> 476625 T1481 C2439 P54800 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[3 (1438676747804475392)]} 0 1
[junit4:junit4] 2> 476629 T1499 C2438 P56091 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:47814/collection1/]
[junit4:junit4] 2> 476629 T1499 C2438 P56091 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:47814/collection1/ against:[http://127.0.0.1:47814/collection1/] result:true
[junit4:junit4] 2> 476630 T1499 C2438 P56091 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:38345/collection1/ against:[http://127.0.0.1:47814/collection1/] result:false
[junit4:junit4] 2> 476630 T1499 C2438 P56091 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:39247/collection1/ against:[http://127.0.0.1:47814/collection1/] result:false
[junit4:junit4] 2> 476636 T1551 C2435 P39247 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:47814/collection1/&version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[3 (1438676747811815424)]} 0 2
[junit4:junit4] 2> 476636 T1533 C2436 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:47814/collection1/&version=2&wt=javabin&distrib.from=http://127.0.0.1:56091/collection1/&update.distrib=FROMLEADER} {add=[3 (1438676747811815424)]} 0 2
[junit4:junit4] 2> 476639 T1499 C2438 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:47814/collection1/&version=2&wt=javabin&distrib.from=http://127.0.0.1:38345/collection1/&update.distrib=TOLEADER} {add=[3 (1438676747811815424)]} 0 11
[junit4:junit4] 2> 476640 T1532 C2436 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:47814/collection1/&test.distrib.skip.servers=http://127.0.0.1:38345/collection1/&version=2&wt=javabin} {add=[3]} 0 13
[junit4:junit4] 2> 476643 T1482 C2439 P54800 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476680 T1482 C2439 P54800 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@9df93a; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@9df93a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 476681 T1482 C2439 P54800 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 476683 T1482 C2439 P54800 oass.SolrIndexSearcher.<init> Opening Searcher@36e1c2 main
[junit4:junit4] 2> 476683 T1482 C2439 P54800 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 476684 T1490 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@36e1c2 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 476684 T1482 C2439 P54800 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 41
[junit4:junit4] 2> 476686 T1534 C2436 P38345 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:56091/collection1/, StdNode: http://127.0.0.1:47814/collection1/, StdNode: http://127.0.0.1:38345/collection1/, StdNode: http://127.0.0.1:39247/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 476688 T1535 C2436 P38345 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476688 T1501 C2438 P56091 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476688 T1516 C2437 P47814 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476689 T1552 C2435 P39247 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476730 T1535 C2436 P38345 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cb245; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cb245; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 476731 T1535 C2436 P38345 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 476732 T1552 C2435 P39247 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@801632; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@801632; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 476732 T1552 C2435 P39247 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 476732 T1501 C2438 P56091 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 476732 T1516 C2437 P47814 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25d94f; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@25d94f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 476733 T1501 C2438 P56091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 476733 T1535 C2436 P38345 oass.SolrIndexSearcher.<init> Opening Searcher@18ffef1 main
[junit4:junit4] 2> 476733 T1516 C2437 P47814 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 476734 T1552 C2435 P39247 oass.SolrIndexSearcher.<init> Opening Searcher@1629e81 main
[junit4:junit4] 2> 476734 T1541 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@18ffef1 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 476734 T1552 C2435 P39247 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 476734 T1535 C2436 P38345 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 476735 T1501 C2438 P56091 oass.SolrIndexSearcher.<init> Opening Searcher@18fc5a5 main
[junit4:junit4] 2> 476735 T1562 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1629e81 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 476735 T1501 C2438 P56091 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 476735 T1535 C2436 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 47
[junit4:junit4] 2> 476736 T1516 C2437 P47814 oass.SolrIndexSearcher.<init> Opening Searcher@192ea3a main
[junit4:junit4] 2> 476736 T1508 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@18fc5a5 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 476736 T1552 C2435 P39247 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 47
[junit4:junit4] 2> 476737 T1501 C2438 P56091 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 49
[junit4:junit4] 2> 476737 T1516 C2437 P47814 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 476737 T1524 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@192ea3a main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):c2)}
[junit4:junit4] 2> 476738 T1516 C2437 P47814 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit_end_point=true&version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 50
[junit4:junit4] 2> 476739 T1534 C2436 P38345 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 53
[junit4:junit4] 2> 476739 T1464 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 476740 T1464 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 476740 T1464 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 476742 T1500 C2438 P56091 oasc.SolrCore.execute [collection1] webapp= path=/select params={rows=0&distrib=false&tests=checkShardConsistency&q=*:*&version=2&wt=javabin} hits=4 status=0 QTime=0
[junit4:junit4] 2> 476745 T1517 C2437 P47814 oasc.SolrCore.execute [collection1] webapp= path=/select params={rows=0&distrib=false&tests=checkShardConsistency&q=*:*&version=2&wt=javabin} hits=2 status=0 QTime=1
[junit4:junit4] 2> 476747 T1533 C2436 P38345 oasc.SolrCore.execute [collection1] webapp= path=/select params={rows=0&distrib=false&tests=checkShardConsistency&q=*:*&version=2&wt=javabin} hits=4 status=0 QTime=1
[junit4:junit4] 2> 476749 T1550 C2435 P39247 oasc.SolrCore.execute [collection1] webapp= path=/select params={rows=0&distrib=false&tests=checkShardConsistency&q=*:*&version=2&wt=javabin} hits=4 status=0 QTime=1
[junit4:junit4] 2> 476751 T1464 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 476756 T1532 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : action=SYNCSHARD&collection=collection1&shard=shard1&version=2&wt=javabin
[junit4:junit4] 2> 476756 T1532 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 476759 T1502 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 476760 T1502 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:56091/collection1/
[junit4:junit4] 2> 476760 T1502 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56091 START replicas=[http://127.0.0.1:47814/collection1/, http://127.0.0.1:38345/collection1/, http://127.0.0.1:39247/collection1/] nUpdates=100
[junit4:junit4] 2> 476761 T1551 C2435 P39247 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&version=2&wt=javabin&qt=/get} status=0 QTime=0
[junit4:junit4] 2> 476762 T1518 C2437 P47814 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&version=2&wt=javabin&qt=/get} status=0 QTime=1
[junit4:junit4] 2> 476761 T1535 C2436 P38345 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&version=2&wt=javabin&qt=/get} status=0 QTime=0
[junit4:junit4] 2> 476762 T1502 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56091 Received 5 versions from 127.0.0.1:39247/collection1/
[junit4:junit4] 2> 476763 T1502 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56091 Our versions are newer. ourLowThreshold=1438676747754143744 otherHigh=1438676747798183936
[junit4:junit4] 2> 476763 T1502 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56091 Received 3 versions from 127.0.0.1:47814/collection1/
[junit4:junit4] 2> 476763 T1502 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56091 Our versions are newer. ourLowThreshold=1438676747754143744 otherHigh=1438676747787698176
[junit4:junit4] 2> 476763 T1502 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56091 Received 5 versions from 127.0.0.1:38345/collection1/
[junit4:junit4] 2> 476764 T1502 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56091 Our versions are newer. ourLowThreshold=1438676747754143744 otherHigh=1438676747798183936
[junit4:junit4] 2> 476764 T1502 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56091 DONE. sync succeeded
[junit4:junit4] 2> 476764 T1502 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 476764 T1502 oasc.SyncStrategy.syncToMe http://127.0.0.1:56091/collection1/: try and ask http://127.0.0.1:47814/collection1/ to sync
[junit4:junit4] 2> 476765 T1502 oasc.SyncStrategy.syncToMe http://127.0.0.1:56091/collection1/: try and ask http://127.0.0.1:38345/collection1/ to sync
[junit4:junit4] 2> 476765 T1502 oasc.SyncStrategy.syncToMe http://127.0.0.1:56091/collection1/: try and ask http://127.0.0.1:39247/collection1/ to sync
[junit4:junit4] 2> 476766 T1515 C2437 P47814 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:47814 START replicas=[http://127.0.0.1:56091/collection1/] nUpdates=100
[junit4:junit4] 2> 476766 T1534 C2436 P38345 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38345 START replicas=[http://127.0.0.1:56091/collection1/] nUpdates=100
[junit4:junit4] 2> 476767 T1552 C2435 P39247 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:39247 START replicas=[http://127.0.0.1:56091/collection1/] nUpdates=100
[junit4:junit4] 2> 476768 T1499 C2438 P56091 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&version=2&wt=javabin&qt=/get} status=0 QTime=1
[junit4:junit4] 2> 476768 T1501 C2438 P56091 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&version=2&wt=javabin&qt=/get} status=0 QTime=0
[junit4:junit4] 2> 476768 T1534 C2436 P38345 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38345 Received 5 versions from 127.0.0.1:56091/collection1/
[junit4:junit4] 2> 476768 T1552 C2435 P39247 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:39247 Received 5 versions from 127.0.0.1:56091/collection1/
[junit4:junit4] 2> 476768 T1500 C2438 P56091 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&version=2&wt=javabin&qt=/get} status=0 QTime=0
[junit4:junit4] 2> 476769 T1552 C2435 P39247 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:39247 Our versions are newer. ourLowThreshold=1438676747754143744 otherHigh=1438676747798183936
[junit4:junit4] 2> 476769 T1515 C2437 P47814 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:47814 Received 5 versions from 127.0.0.1:56091/collection1/
[junit4:junit4] 2> 476768 T1534 C2436 P38345 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38345 Our versions are newer. ourLowThreshold=1438676747754143744 otherHigh=1438676747798183936
[junit4:junit4] 2> 476770 T1534 C2436 P38345 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38345 DONE. sync succeeded
[junit4:junit4] 2> 476769 T1515 C2437 P47814 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:47814 Requesting updates from 127.0.0.1:56091/collection1/n=2 versions=[1438676747811815424, 1438676747798183936]
[junit4:junit4] 2> 476769 T1552 C2435 P39247 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:39247 DONE. sync succeeded
[junit4:junit4] 2> 476770 T1534 C2436 P38345 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&sync=http://127.0.0.1:56091/collection1/&version=2&wt=javabin&qt=/get} status=0 QTime=4
[junit4:junit4] 2> 476770 T1552 C2435 P39247 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&sync=http://127.0.0.1:56091/collection1/&version=2&wt=javabin&qt=/get} status=0 QTime=4
[junit4:junit4] 2> 476771 T1502 oasc.SyncStrategy.syncToMe http://127.0.0.1:56091/collection1/: sync completed with http://127.0.0.1:38345/collection1/
[junit4:junit4] 2> 476771 T1502 oasc.SyncStrategy.syncToMe http://127.0.0.1:56091/collection1/: sync completed with http://127.0.0.1:39247/collection1/
[junit4:junit4] 2> 476772 T1499 C2438 P56091 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&version=2&wt=javabin&qt=/get&getUpdates=1438676747811815424,1438676747798183936} status=0 QTime=0
[junit4:junit4] 2> 476775 T1515 C2437 P47814 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438676747798183936), 3 (1438676747811815424)]} 0 2
[junit4:junit4] 2> 476775 T1515 C2437 P47814 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:47814 DONE. sync succeeded
[junit4:junit4] 2> 476776 T1515 C2437 P47814 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&sync=http://127.0.0.1:56091/collection1/&version=2&wt=javabin&qt=/get} status=0 QTime=10
[junit4:junit4] 2> 476776 T1502 oasc.SyncStrategy.syncToMe http://127.0.0.1:56091/collection1/: sync completed with http://127.0.0.1:47814/collection1/
[junit4:junit4] 2> 476777 T1502 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={action=REQUESTSYNCSHARD&collection=collection1&shard=shard1&version=2&wt=javabin&core=collection1} status=0 QTime=18
[junit4:junit4] 2> 476777 T1532 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={action=SYNCSHARD&collection=collection1&shard=shard1&version=2&wt=javabin} status=0 QTime=23
[junit4:junit4] 2> 476777 T1464 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 476778 T1464 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 476778 T1464 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 476779 T1464 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 476781 T1479 C2439 P54800 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476830 T1479 C2439 P54800 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@9df93a; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@9df93a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 476831 T1479 C2439 P54800 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 476832 T1479 C2439 P54800 oass.SolrIndexSearcher.<init> Opening Searcher@3394b6 main
[junit4:junit4] 2> 476832 T1479 C2439 P54800 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 476833 T1490 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3394b6 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 476833 T1479 C2439 P54800 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&commit=true&wt=javabin&waitSearcher=true&softCommit=false} {commit=} 0 52
[junit4:junit4] 2> 476835 T1501 C2438 P56091 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:56091/collection1/, StdNode: http://127.0.0.1:47814/collection1/, StdNode: http://127.0.0.1:38345/collection1/, StdNode: http://127.0.0.1:39247/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 476837 T1500 C2438 P56091 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476838 T1533 C2436 P38345 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476838 T1550 C2435 P39247 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476838 T1516 C2437 P47814 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 476860 T1500 C2438 P56091 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; 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-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372029042573/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@146b7e0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_7,generation=7}
[junit4:junit4] 2> 476861 T1500 C2438 P56091 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 476861 T1500 C2438 P56091 oass.SolrIndexSearcher.<init> Opening Searcher@17f96ed main
[junit4:junit4] 2> 476862 T1500 C2438 P56091 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 476862 T1508 oasc.SolrCore.reg
[...truncated too long message...]
] 1> "base_url":"http://127.0.0.1:47814",
[junit4:junit4] 1> "node_name":"127.0.0.1:47814_",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "core":"collection1"},
[junit4:junit4] 1> "4":{
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38345",
[junit4:junit4] 1> "node_name":"127.0.0.1:38345_",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "5":{
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39247",
[junit4:junit4] 1> "node_name":"127.0.0.1:39247_",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1"}}}}},
[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> "collection":"control_collection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54800",
[junit4:junit4] 1> "node_name":"127.0.0.1:54800_",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"}}}}}}
[junit4:junit4] 1> /solr/collections (2)
[junit4:junit4] 1> /solr/collections/collection1 (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/collection1/leader_elect (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election (3)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89917295334260748-5-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89917295334260750-2-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89917295334260746-4-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/collection1/leaders (1)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38345",
[junit4:junit4] 1> "node_name":"127.0.0.1:38345_",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> /solr/collections/collection1/shards (0)
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89917295334260739-1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:54800",
[junit4:junit4] 1> "node_name":"127.0.0.1:54800_",
[junit4:junit4] 1> "core":"collection1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (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=27A493963144C4B9 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=fi -Dtests.timezone=America/Managua -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 99.3s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:56091/collection1lastClient and got 252 from http://127.0.0.1:38345/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([27A493963144C4B9:A6421D8E461BA485]: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> 554454 T1464 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 99255 T1463 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 555636 T1556 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 555637 T1556 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> 555637 T1556 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {rnd_b=Lucene41(blocksize=128), other_tl1=PostingsFormat(name=MockRandom), id=Lucene41(blocksize=128), intDefault=PostingsFormat(name=MockRandom), a_t=PostingsFormat(name=Memory doPackFST= false), timestamp=PostingsFormat(name=Memory doPackFST= false), range_facet_si=PostingsFormat(name=Memory doPackFST= false), text=Pulsing41(freqCutoff=1 minBlockSize=60 maxBlockSize=216), range_facet_sl=Lucene41(blocksize=128), range_facet_l=PostingsFormat(name=Memory doPackFST= false), multiDefault=PostingsFormat(name=Memory doPackFST= false), a_si=PostingsFormat(name=MockRandom), _version_=PostingsFormat(name=MockRandom)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=fi, timezone=America/Managua
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=2,free=42154240,total=155668480
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestUniqueKeyFieldResource, LoggingHandlerTest, TestPluginEnable, TestTrie, DirectSolrConnectionTest, ScriptEngineTest, TestWriterPerf, TestJoin, SoftAutoCommitTest, TestSweetSpotSimilarityFactory, ResourceLoaderTest, PluginInfoTest, BinaryUpdateRequestHandlerTest, IndexSchemaTest, PrimitiveFieldTypeTest, SolrTestCaseJ4Test, TestManagedSchemaFieldResource, DocumentBuilderTest, RAMDirectoryFactoryTest, QueryElevationComponentTest, TestFieldTypeCollectionResource, TestSchemaNameResource, TestFastLRUCache, PreAnalyzedFieldTest, SuggesterTest, TestRemoteStreaming, TestSolrQueryParser, ResponseLogComponentTest, BadComponentTest, SimpleFacetsTest, TestFieldResource, SolrCoreTest, MinimalSchemaTest, ReturnFieldsTest, FileBasedSpellCheckerTest, LegacyHTMLStripCharFilterTest, CSVRequestHandlerTest, TestConfig, SchemaVersionSpecificBehaviorTest, TestPerFieldSimilarity, AnalysisAfterCoreReloadTest, TestXIncludeConfig, TestSolrQueryParserResource, SystemInfoHandlerTest, TestFaceting, TestQueryUtils, TestFieldTypeResource, TestLFUCache, SynonymTokenizerTest, BasicFunctionalityTest, RecoveryZkTest, TestFuzzyAnalyzedSuggestions, TestValueSourceCache, TestFastWriter, TestPseudoReturnFields, MBeansHandlerTest, TestCloudManagedSchemaAddField, TestCharFilters, MoreLikeThisHandlerTest, PrimUtilsTest, ClusterStateUpdateTest, TermsComponentTest, TestPropInjectDefaults, CacheHeaderTest, DistributedQueryElevationComponentTest, SliceStateTest, TestFunctionQuery, DistributedSpellCheckComponentTest, TestQuerySenderListener, QueryEqualityTest, UnloadDistributedZkTest, BasicDistributedZkTest, CollectionsAPIDistributedZkTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 100.54s, 1 test, 1 failure <<< FAILURES!
[...truncated 457 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:392: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:372: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1246: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 16 ignored (7 assumptions)
Total time: 38 minutes 28 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.8.0-ea-b93 -server -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure