You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/06/25 11:55:42 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1737 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1737/
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:19794/ud/d/collection1lastClient and got 257 from http://127.0.0.1:18619/ud/d/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:19794/ud/d/collection1lastClient and got 257 from http://127.0.0.1:18619/ud/d/collection1
at __randomizedtesting.SeedInfo.seed([9D102214822078A5:1CF6AC0CF57F1899]: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:616)
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:679)
Build Log:
[...truncated 9171 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 1137302 T2583 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /ud/d
[junit4:junit4] 2> 1137307 T2583 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-SyncSliceTest-1372153487861
[junit4:junit4] 2> 1137308 T2583 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1137309 T2584 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1137410 T2583 oasc.ZkTestServer.run start zk server on port:19787
[junit4:junit4] 2> 1137410 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1137415 T2590 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52e022a8 name:ZooKeeperConnection Watcher:127.0.0.1:19787 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1137415 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1137416 T2583 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1137428 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1137431 T2592 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@809e57e name:ZooKeeperConnection Watcher:127.0.0.1:19787/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1137431 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1137431 T2583 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1137442 T2583 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1137444 T2583 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1137446 T2583 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1137449 T2583 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1137450 T2583 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1137465 T2583 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1137465 T2583 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1137569 T2583 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1137570 T2583 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1137572 T2583 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1137573 T2583 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1137576 T2583 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1137576 T2583 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1137588 T2583 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1137589 T2583 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1137591 T2583 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1137592 T2583 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1137595 T2583 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1137595 T2583 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1137603 T2583 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1137603 T2583 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1137863 T2583 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1137868 T2583 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19790
[junit4:junit4] 2> 1137869 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1137869 T2583 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1137870 T2583 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372153488160
[junit4:junit4] 2> 1137870 T2583 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372153488160/solr.xml
[junit4:junit4] 2> 1137870 T2583 oasc.CoreContainer.<init> New CoreContainer 8650795
[junit4:junit4] 2> 1137871 T2583 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372153488160/'
[junit4:junit4] 2> 1137872 T2583 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372153488160/'
[junit4:junit4] 2> 1137978 T2583 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1137979 T2583 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1137979 T2583 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1137980 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1137980 T2583 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1137981 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1137981 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1137982 T2583 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1137982 T2583 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1137983 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1138000 T2583 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1138001 T2583 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19787/solr
[junit4:junit4] 2> 1138001 T2583 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1138002 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1138010 T2603 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3851436d name:ZooKeeperConnection Watcher:127.0.0.1:19787 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1138011 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1138025 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1138038 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1138040 T2605 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3f3f23da name:ZooKeeperConnection Watcher:127.0.0.1:19787/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1138040 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1138043 T2583 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1138052 T2583 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1138055 T2583 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1138057 T2583 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19790_ud%2Fd
[junit4:junit4] 2> 1138065 T2583 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19790_ud%2Fd
[junit4:junit4] 2> 1138068 T2583 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1138084 T2583 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1138087 T2583 oasc.Overseer.start Overseer (id=89925450980917251-127.0.0.1:19790_ud%2Fd-n_0000000000) starting
[junit4:junit4] 2> 1138099 T2583 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1138110 T2607 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1138111 T2583 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1138113 T2583 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1138124 T2583 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1138127 T2606 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1138131 T2608 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1138131 T2608 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1139630 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1139631 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:19790_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19790/ud/d"}
[junit4:junit4] 2> 1139631 T2606 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1139632 T2606 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1139648 T2605 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> 1140134 T2608 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372153488160/collection1
[junit4:junit4] 2> 1140134 T2608 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1140135 T2608 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1140135 T2608 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1140137 T2608 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372153488160/collection1/'
[junit4:junit4] 2> 1140138 T2608 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1372153488160/collection1/lib/README' to classloader
[junit4:junit4] 2> 1140139 T2608 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1372153488160/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1140187 T2608 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1140245 T2608 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1140346 T2608 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1140353 T2608 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1140948 T2608 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1140949 T2608 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1140950 T2608 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1140962 T2608 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1140966 T2608 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1140979 T2608 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1140983 T2608 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1140987 T2608 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1140988 T2608 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1140989 T2608 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1140989 T2608 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1140990 T2608 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1140990 T2608 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1140990 T2608 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1140990 T2608 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372153488160/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/
[junit4:junit4] 2> 1140991 T2608 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26c59ad5
[junit4:junit4] 2> 1140991 T2608 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1140993 T2608 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data
[junit4:junit4] 2> 1140993 T2608 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index/
[junit4:junit4] 2> 1140994 T2608 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1140995 T2608 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index
[junit4:junit4] 2> 1141001 T2608 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1141002 T2608 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1141004 T2608 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1141005 T2608 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1141005 T2608 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1141006 T2608 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1141006 T2608 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1141006 T2608 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1141007 T2608 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1141007 T2608 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1141008 T2608 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1141017 T2608 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1141026 T2608 oass.SolrIndexSearcher.<init> Opening Searcher@2dd354ce main
[junit4:junit4] 2> 1141028 T2608 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1141028 T2608 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1141031 T2609 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2dd354ce main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1141032 T2608 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1141032 T2608 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19790/ud/d collection:control_collection shard:shard1
[junit4:junit4] 2> 1141033 T2608 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1141049 T2608 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1141060 T2608 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1141060 T2608 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1141060 T2608 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:19790/ud/d/collection1/
[junit4:junit4] 2> 1141060 T2608 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1141061 T2608 oasc.SyncStrategy.syncToMe http://127.0.0.1:19790/ud/d/collection1/ has no replicas
[junit4:junit4] 2> 1141061 T2608 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:19790/ud/d/collection1/
[junit4:junit4] 2> 1141061 T2608 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1141152 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1141167 T2605 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> 1141177 T2608 oasc.ZkController.register We are http://127.0.0.1:19790/ud/d/collection1/ and leader is http://127.0.0.1:19790/ud/d/collection1/
[junit4:junit4] 2> 1141177 T2608 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19790/ud/d
[junit4:junit4] 2> 1141177 T2608 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1141177 T2608 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1141177 T2608 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1141179 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1141180 T2583 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1141181 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1141181 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1141199 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1141200 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1141206 T2612 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d8c1103 name:ZooKeeperConnection Watcher:127.0.0.1:19787/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1141207 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1141208 T2583 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1141210 T2583 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1141472 T2583 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1141475 T2583 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19794
[junit4:junit4] 2> 1141476 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1141476 T2583 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1141477 T2583 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372153491764
[junit4:junit4] 2> 1141477 T2583 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372153491764/solr.xml
[junit4:junit4] 2> 1141478 T2583 oasc.CoreContainer.<init> New CoreContainer 1084251087
[junit4:junit4] 2> 1141478 T2583 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372153491764/'
[junit4:junit4] 2> 1141479 T2583 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372153491764/'
[junit4:junit4] 2> 1141586 T2583 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1141587 T2583 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1141587 T2583 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1141588 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1141588 T2583 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1141588 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1141589 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1141589 T2583 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1141590 T2583 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1141590 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1141608 T2583 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1141608 T2583 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19787/solr
[junit4:junit4] 2> 1141609 T2583 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1141610 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1141612 T2623 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@634d8934 name:ZooKeeperConnection Watcher:127.0.0.1:19787 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1141613 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1141626 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1141638 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1141640 T2625 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@74751ac8 name:ZooKeeperConnection Watcher:127.0.0.1:19787/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1141641 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1141646 T2583 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1142649 T2583 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19794_ud%2Fd
[junit4:junit4] 2> 1142651 T2583 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19794_ud%2Fd
[junit4:junit4] 2> 1142654 T2605 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1142654 T2625 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1142654 T2612 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1142654 T2605 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> 1142667 T2626 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1142668 T2626 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1142672 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1142673 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:19790_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19790/ud/d"}
[junit4:junit4] 2> 1142681 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:19794_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19794/ud/d"}
[junit4:junit4] 2> 1142682 T2606 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 1142682 T2606 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1142694 T2612 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> 1142694 T2605 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> 1142694 T2625 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> 1143670 T2626 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372153491764/collection1
[junit4:junit4] 2> 1143670 T2626 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1143671 T2626 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1143671 T2626 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1143672 T2626 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372153491764/collection1/'
[junit4:junit4] 2> 1143674 T2626 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1372153491764/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1143674 T2626 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1372153491764/collection1/lib/README' to classloader
[junit4:junit4] 2> 1143724 T2626 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1143782 T2626 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1143883 T2626 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1143890 T2626 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1144491 T2626 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1144492 T2626 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1144493 T2626 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1144505 T2626 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1144509 T2626 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1144522 T2626 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1144527 T2626 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1144531 T2626 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1144532 T2626 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1144532 T2626 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1144532 T2626 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1144533 T2626 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1144533 T2626 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1144534 T2626 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1144534 T2626 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372153491764/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/
[junit4:junit4] 2> 1144534 T2626 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26c59ad5
[junit4:junit4] 2> 1144535 T2626 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1144536 T2626 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1
[junit4:junit4] 2> 1144537 T2626 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index/
[junit4:junit4] 2> 1144537 T2626 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1144538 T2626 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index
[junit4:junit4] 2> 1144571 T2626 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1144571 T2626 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1144573 T2626 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1144574 T2626 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1144574 T2626 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1144575 T2626 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1144576 T2626 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1144576 T2626 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1144576 T2626 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1144577 T2626 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1144577 T2626 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1144586 T2626 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1144596 T2626 oass.SolrIndexSearcher.<init> Opening Searcher@4626b3e8 main
[junit4:junit4] 2> 1144597 T2626 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1144597 T2626 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1144601 T2627 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4626b3e8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1144603 T2626 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1144604 T2626 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19794/ud/d collection:collection1 shard:shard1
[junit4:junit4] 2> 1144604 T2626 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1144622 T2626 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1144624 T2626 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1144624 T2626 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1144625 T2626 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1144625 T2626 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1144625 T2626 oasc.SyncStrategy.syncToMe http://127.0.0.1:19794/ud/d/collection1/ has no replicas
[junit4:junit4] 2> 1144625 T2626 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1144626 T2626 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1145701 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1145728 T2612 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> 1145728 T2625 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> 1145728 T2605 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> 1145753 T2626 oasc.ZkController.register We are http://127.0.0.1:19794/ud/d/collection1/ and leader is http://127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1145753 T2626 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19794/ud/d
[junit4:junit4] 2> 1145753 T2626 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1145753 T2626 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1145753 T2626 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1145755 T2626 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1145757 T2583 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1145758 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1145758 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1146032 T2583 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1146035 T2583 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12000
[junit4:junit4] 2> 1146036 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1146036 T2583 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1146037 T2583 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372153496329
[junit4:junit4] 2> 1146037 T2583 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372153496329/solr.xml
[junit4:junit4] 2> 1146038 T2583 oasc.CoreContainer.<init> New CoreContainer 1500899900
[junit4:junit4] 2> 1146038 T2583 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372153496329/'
[junit4:junit4] 2> 1146039 T2583 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372153496329/'
[junit4:junit4] 2> 1146146 T2583 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1146146 T2583 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1146147 T2583 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1146147 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1146148 T2583 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1146148 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1146149 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1146149 T2583 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1146150 T2583 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1146150 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1146168 T2583 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1146168 T2583 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19787/solr
[junit4:junit4] 2> 1146169 T2583 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1146170 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1146173 T2639 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8ff9219 name:ZooKeeperConnection Watcher:127.0.0.1:19787 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1146174 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1146183 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1146196 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1146198 T2641 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5898d7a6 name:ZooKeeperConnection Watcher:127.0.0.1:19787/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1146198 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1146209 T2583 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1147212 T2583 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12000_ud%2Fd
[junit4:junit4] 2> 1147218 T2583 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12000_ud%2Fd
[junit4:junit4] 2> 1147221 T2625 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> 1147222 T2612 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1147222 T2641 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1147222 T2605 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1147222 T2612 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> 1147222 T2605 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> 1147223 T2625 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1147229 T2642 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1147229 T2642 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1147238 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1147239 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:19794_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19794/ud/d"}
[junit4:junit4] 2> 1147242 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12000_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12000/ud/d"}
[junit4:junit4] 2> 1147243 T2606 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 1147243 T2606 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1147253 T2612 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> 1147253 T2605 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> 1147253 T2641 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> 1147253 T2625 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> 1148231 T2642 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372153496329/collection1
[junit4:junit4] 2> 1148231 T2642 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1148232 T2642 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1148232 T2642 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1148233 T2642 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372153496329/collection1/'
[junit4:junit4] 2> 1148235 T2642 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1372153496329/collection1/lib/README' to classloader
[junit4:junit4] 2> 1148235 T2642 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1372153496329/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1148284 T2642 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1148341 T2642 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1148442 T2642 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1148449 T2642 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1149040 T2642 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1149041 T2642 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1149041 T2642 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1149049 T2642 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1149052 T2642 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1149063 T2642 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1149066 T2642 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1149069 T2642 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1149070 T2642 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1149070 T2642 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1149070 T2642 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1149071 T2642 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1149071 T2642 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1149071 T2642 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1149072 T2642 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372153496329/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/
[junit4:junit4] 2> 1149072 T2642 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26c59ad5
[junit4:junit4] 2> 1149072 T2642 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1149073 T2642 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2
[junit4:junit4] 2> 1149073 T2642 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index/
[junit4:junit4] 2> 1149074 T2642 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1149075 T2642 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index
[junit4:junit4] 2> 1149079 T2642 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1149079 T2642 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1149081 T2642 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1149081 T2642 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1149081 T2642 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1149082 T2642 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1149082 T2642 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1149082 T2642 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1149082 T2642 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1149083 T2642 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1149083 T2642 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1149089 T2642 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1149096 T2642 oass.SolrIndexSearcher.<init> Opening Searcher@73f7798c main
[junit4:junit4] 2> 1149097 T2642 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1149097 T2642 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1149100 T2643 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@73f7798c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1149101 T2642 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1149101 T2642 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12000/ud/d collection:collection1 shard:shard1
[junit4:junit4] 2> 1149104 T2642 oasc.ZkController.register We are http://127.0.0.1:12000/ud/d/collection1/ and leader is http://127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1149104 T2642 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12000/ud/d
[junit4:junit4] 2> 1149104 T2642 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1149105 T2642 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C806 name=collection1 org.apache.solr.core.SolrCore@1a007be3 url=http://127.0.0.1:12000/ud/d/collection1 node=127.0.0.1:12000_ud%2Fd C806_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:12000_ud%2Fd, base_url=http://127.0.0.1:12000/ud/d}
[junit4:junit4] 2> 1149105 T2644 C806 P12000 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1149105 T2642 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1149105 T2644 C806 P12000 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1149106 T2644 C806 P12000 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1149106 T2644 C806 P12000 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1149106 T2583 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1149107 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1149107 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1149107 T2644 C806 P12000 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1149123 T2615 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1149293 T2583 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1149296 T2583 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:18619
[junit4:junit4] 2> 1149296 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1149296 T2583 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1149297 T2583 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372153499675
[junit4:junit4] 2> 1149297 T2583 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372153499675/solr.xml
[junit4:junit4] 2> 1149297 T2583 oasc.CoreContainer.<init> New CoreContainer 1663281900
[junit4:junit4] 2> 1149298 T2583 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372153499675/'
[junit4:junit4] 2> 1149298 T2583 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372153499675/'
[junit4:junit4] 2> 1149368 T2583 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1149369 T2583 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1149369 T2583 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1149370 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1149370 T2583 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1149370 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1149370 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1149371 T2583 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1149371 T2583 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1149371 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1149382 T2583 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1149382 T2583 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19787/solr
[junit4:junit4] 2> 1149382 T2583 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1149383 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1149386 T2656 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@179fc2d2 name:ZooKeeperConnection Watcher:127.0.0.1:19787 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1149386 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1149401 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1149412 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1149414 T2658 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@57b23615 name:ZooKeeperConnection Watcher:127.0.0.1:19787/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1149414 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1149423 T2583 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1150267 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1150268 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12000_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12000/ud/d"}
[junit4:junit4] 2> 1150287 T2612 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> 1150288 T2641 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> 1150287 T2605 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> 1150287 T2658 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> 1150287 T2625 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> 1150426 T2583 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:18619_ud%2Fd
[junit4:junit4] 2> 1150433 T2583 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:18619_ud%2Fd
[junit4:junit4] 2> 1150438 T2625 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> 1150438 T2612 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1150439 T2641 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1150438 T2605 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1150438 T2658 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1150439 T2605 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> 1150439 T2641 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> 1150439 T2612 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> 1150440 T2625 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1150439 T2658 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> 1150451 T2659 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1150451 T2659 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1151126 T2615 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1151126 T2615 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=3&state=recovering&nodeName=127.0.0.1:12000_ud%252Fd&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1151792 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1151793 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:18619_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18619/ud/d"}
[junit4:junit4] 2> 1151793 T2606 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 1151793 T2606 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1151818 T2605 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> 1151818 T2658 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> 1151818 T2641 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> 1151818 T2612 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> 1151818 T2625 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> 1152455 T2659 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372153499675/collection1
[junit4:junit4] 2> 1152455 T2659 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1152456 T2659 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1152456 T2659 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1152458 T2659 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372153499675/collection1/'
[junit4:junit4] 2> 1152459 T2659 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1372153499675/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1152460 T2659 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1372153499675/collection1/lib/README' to classloader
[junit4:junit4] 2> 1152516 T2659 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1152580 T2659 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1152682 T2659 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1152690 T2659 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C807 name=collection1 org.apache.solr.core.SolrCore@1a007be3 url=http://127.0.0.1:12000/ud/d/collection1 node=127.0.0.1:12000_ud%2Fd C807_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:12000_ud%2Fd, base_url=http://127.0.0.1:12000/ud/d}
[junit4:junit4] 2> 1153128 T2644 C807 P12000 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:19794/ud/d/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1153128 T2644 C807 P12000 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:12000/ud/d START replicas=[http://127.0.0.1:19794/ud/d/collection1/] nUpdates=100
[junit4:junit4] 2> 1153129 T2644 C807 P12000 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1153129 T2644 C807 P12000 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1153130 T2644 C807 P12000 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1153130 T2644 C807 P12000 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1153130 T2644 C807 P12000 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1153130 T2644 C807 P12000 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:19794/ud/d/collection1/. core=collection1
[junit4:junit4] 2> 1153130 T2644 C807 P12000 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C808 name=collection1 org.apache.solr.core.SolrCore@2d4a00ff url=http://127.0.0.1:19794/ud/d/collection1 node=127.0.0.1:19794_ud%2Fd C808_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19794_ud%2Fd, base_url=http://127.0.0.1:19794/ud/d, leader=true}
[junit4:junit4] 2> 1153138 T2616 C808 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1153143 T2617 C808 P19794 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1153149 T2617 C808 P19794 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1153149 T2617 C808 P19794 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1153155 T2617 C808 P19794 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 1153155 T2617 C808 P19794 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1153158 T2617 C808 P19794 oass.SolrIndexSearcher.<init> Opening Searcher@551b7b80 realtime
[junit4:junit4] 2> 1153159 T2617 C808 P19794 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1153159 T2617 C808 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 1153160 T2644 C807 P12000 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1153161 T2644 C807 P12000 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1153163 T2618 C808 P19794 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1153164 T2618 C808 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1153165 T2644 C807 P12000 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1153165 T2644 C807 P12000 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1153165 T2644 C807 P12000 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1153168 T2618 C808 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 1153169 T2644 C807 P12000 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1153171 T2644 C807 P12000 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index.20130625144503722
[junit4:junit4] 2> 1153172 T2644 C807 P12000 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index.20130625144503722 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7b322fd6 fullCopy=false
[junit4:junit4] 2> 1153176 T2618 C808 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1153178 T2644 C807 P12000 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1153181 T2644 C807 P12000 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1153182 T2644 C807 P12000 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1153188 T2644 C807 P12000 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 1153189 T2644 C807 P12000 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1153189 T2644 C807 P12000 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1153191 T2644 C807 P12000 oass.SolrIndexSearcher.<init> Opening Searcher@1748df76 main
[junit4:junit4] 2> 1153192 T2643 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1748df76 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1153192 T2644 C807 P12000 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index.20130625144503722 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index.20130625144503722;done=true>>]
[junit4:junit4] 2> 1153193 T2644 C807 P12000 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index.20130625144503722
[junit4:junit4] 2> 1153193 T2644 C807 P12000 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index.20130625144503722
[junit4:junit4] 2> 1153194 T2644 C807 P12000 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1153195 T2644 C807 P12000 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1153195 T2644 C807 P12000 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1153195 T2644 C807 P12000 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1153197 T2644 C807 P12000 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1153337 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1153338 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12000_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12000/ud/d"}
[junit4:junit4] 2> 1153353 T2641 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> 1153353 T2625 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> 1153353 T2658 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> 1153353 T2605 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> 1153353 T2612 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> 1153399 T2659 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1153400 T2659 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1153401 T2659 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1153415 T2659 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1153420 T2659 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1153434 T2659 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1153448 T2659 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1153453 T2659 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1153454 T2659 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1153454 T2659 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1153455 T2659 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1153456 T2659 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1153456 T2659 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1153456 T2659 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1153456 T2659 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372153499675/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/
[junit4:junit4] 2> 1153457 T2659 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26c59ad5
[junit4:junit4] 2> 1153457 T2659 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1153458 T2659 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3
[junit4:junit4] 2> 1153459 T2659 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index/
[junit4:junit4] 2> 1153460 T2659 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1153461 T2659 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index
[junit4:junit4] 2> 1153576 T2659 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1153577 T2659 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1153580 T2659 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1153581 T2659 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1153581 T2659 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1153582 T2659 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1153582 T2659 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1153583 T2659 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1153587 T2659 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1153588 T2659 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1153589 T2659 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1153603 T2659 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1153615 T2659 oass.SolrIndexSearcher.<init> Opening Searcher@741a7d52 main
[junit4:junit4] 2> 1153616 T2659 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1153617 T2659 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1153622 T2662 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@741a7d52 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1153625 T2659 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1153625 T2659 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:18619/ud/d collection:collection1 shard:shard1
[junit4:junit4] 2> 1153628 T2659 oasc.ZkController.register We are http://127.0.0.1:18619/ud/d/collection1/ and leader is http://127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1153629 T2659 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:18619/ud/d
[junit4:junit4] 2> 1153629 T2659 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1153629 T2659 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C809 name=collection1 org.apache.solr.core.SolrCore@dcfc13e url=http://127.0.0.1:18619/ud/d/collection1 node=127.0.0.1:18619_ud%2Fd C809_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:18619_ud%2Fd, base_url=http://127.0.0.1:18619/ud/d}
[junit4:junit4] 2> 1153630 T2663 C809 P18619 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1153630 T2663 C809 P18619 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1153630 T2659 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1153631 T2663 C809 P18619 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1153631 T2663 C809 P18619 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1153632 T2583 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1153632 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1153633 T2663 C809 P18619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1153633 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1153663 T2619 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1153960 T2583 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1153963 T2583 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:18951
[junit4:junit4] 2> 1153964 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1153965 T2583 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1153965 T2583 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372153504214
[junit4:junit4] 2> 1153966 T2583 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372153504214/solr.xml
[junit4:junit4] 2> 1153966 T2583 oasc.CoreContainer.<init> New CoreContainer 1329735173
[junit4:junit4] 2> 1153967 T2583 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372153504214/'
[junit4:junit4] 2> 1153968 T2583 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372153504214/'
[junit4:junit4] 2> 1154096 T2583 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1154097 T2583 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1154097 T2583 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1154097 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1154098 T2583 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1154098 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1154099 T2583 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1154099 T2583 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1154100 T2583 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1154100 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1154120 T2583 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1154121 T2583 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:19787/solr
[junit4:junit4] 2> 1154121 T2583 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1154122 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1154130 T2675 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3c7dd88c name:ZooKeeperConnection Watcher:127.0.0.1:19787 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1154131 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1154150 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1154171 T2583 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1154200 T2677 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2fc55091 name:ZooKeeperConnection Watcher:127.0.0.1:19787/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1154200 T2583 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1154207 T2583 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1154858 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1154859 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:18619_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18619/ud/d"}
[junit4:junit4] 2> 1154897 T2612 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> 1154897 T2625 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> 1154897 T2677 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> 1154897 T2641 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> 1154897 T2605 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> 1154899 T2658 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> 1155211 T2583 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:18951_ud%2Fd
[junit4:junit4] 2> 1155213 T2583 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:18951_ud%2Fd
[junit4:junit4] 2> 1155216 T2625 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> 1155216 T2612 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1155217 T2658 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1155217 T2605 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1155217 T2658 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> 1155217 T2677 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1155217 T2612 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> 1155216 T2641 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1155218 T2677 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> 1155217 T2605 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> 1155218 T2641 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> 1155224 T2625 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1155231 T2678 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1155231 T2678 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1155665 T2619 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1155665 T2619 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:18619_ud%252Fd&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 2> 1156403 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1156404 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:18951_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18951/ud/d"}
[junit4:junit4] 2> 1156405 T2606 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 1156405 T2606 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1156444 T2612 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> 1156444 T2658 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> 1156444 T2625 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> 1156444 T2677 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> 1156444 T2641 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> 1156444 T2605 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> 1157235 T2678 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372153504214/collection1
[junit4:junit4] 2> 1157236 T2678 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1157238 T2678 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1157238 T2678 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1157240 T2678 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372153504214/collection1/'
[junit4:junit4] 2> 1157242 T2678 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1372153504214/collection1/lib/README' to classloader
[junit4:junit4] 2> 1157243 T2678 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1372153504214/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1157302 T2678 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1157364 T2678 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1157465 T2678 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1157473 T2678 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C810 name=collection1 org.apache.solr.core.SolrCore@dcfc13e url=http://127.0.0.1:18619/ud/d/collection1 node=127.0.0.1:18619_ud%2Fd C810_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:18619_ud%2Fd, base_url=http://127.0.0.1:18619/ud/d}
[junit4:junit4] 2> 1157667 T2663 C810 P18619 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:19794/ud/d/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1157667 T2663 C810 P18619 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18619/ud/d START replicas=[http://127.0.0.1:19794/ud/d/collection1/] nUpdates=100
[junit4:junit4] 2> 1157668 T2663 C810 P18619 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1157668 T2663 C810 P18619 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1157668 T2663 C810 P18619 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1157668 T2663 C810 P18619 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1157669 T2663 C810 P18619 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1157669 T2663 C810 P18619 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:19794/ud/d/collection1/. core=collection1
[junit4:junit4] 2> 1157669 T2663 C810 P18619 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C811 name=collection1 org.apache.solr.core.SolrCore@2d4a00ff url=http://127.0.0.1:19794/ud/d/collection1 node=127.0.0.1:19794_ud%2Fd C811_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19794_ud%2Fd, base_url=http://127.0.0.1:19794/ud/d, leader=true}
[junit4:junit4] 2> 1157671 T2616 C811 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1157682 T2620 C811 P19794 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1157692 T2620 C811 P19794 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 1157693 T2620 C811 P19794 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1157695 T2620 C811 P19794 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1157695 T2620 C811 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> 1157696 T2663 C810 P18619 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1157697 T2663 C810 P18619 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1157699 T2618 C811 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 1157701 T2663 C810 P18619 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 1157701 T2663 C810 P18619 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1157701 T2663 C810 P18619 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1157706 T2618 C811 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=2
[junit4:junit4] 2> 1157707 T2663 C810 P18619 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1157710 T2663 C810 P18619 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index.20130625144508261
[junit4:junit4] 2> 1157712 T2663 C810 P18619 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index.20130625144508261 lockFactory=org.apache.lucene.store.NativeFSLockFactory@53fe2496 fullCopy=false
[junit4:junit4] 2> 1157718 T2618 C811 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=1
[junit4:junit4] 2> 1157720 T2663 C810 P18619 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1157724 T2663 C810 P18619 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1157724 T2663 C810 P18619 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1157729 T2663 C810 P18619 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 1157730 T2663 C810 P18619 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1157730 T2663 C810 P18619 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1157732 T2663 C810 P18619 oass.SolrIndexSearcher.<init> Opening Searcher@31fcfe8b main
[junit4:junit4] 2> 1157733 T2662 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@31fcfe8b main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 1157734 T2663 C810 P18619 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index.20130625144508261 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index.20130625144508261;done=true>>]
[junit4:junit4] 2> 1157734 T2663 C810 P18619 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index.20130625144508261
[junit4:junit4] 2> 1157734 T2663 C810 P18619 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index.20130625144508261
[junit4:junit4] 2> 1157737 T2663 C810 P18619 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1157737 T2663 C810 P18619 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1157737 T2663 C810 P18619 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1157737 T2663 C810 P18619 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1157740 T2663 C810 P18619 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1157949 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1157950 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:18619_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18619/ud/d"}
[junit4:junit4] 2> 1157964 T2658 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> 1157964 T2641 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> 1157964 T2605 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> 1157964 T2677 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> 1157964 T2612 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> 1157964 T2625 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> 1158202 T2678 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1158203 T2678 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 1158204 T2678 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1158217 T2678 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1158222 T2678 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1158236 T2678 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1158251 T2678 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1158256 T2678 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1158257 T2678 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1158257 T2678 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1158258 T2678 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1158259 T2678 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1158259 T2678 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 1158259 T2678 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1158260 T2678 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372153504214/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/
[junit4:junit4] 2> 1158260 T2678 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@26c59ad5
[junit4:junit4] 2> 1158260 T2678 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 1158262 T2678 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4
[junit4:junit4] 2> 1158262 T2678 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index/
[junit4:junit4] 2> 1158263 T2678 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1158264 T2678 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index
[junit4:junit4] 2> 1158271 T2678 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1158272 T2678 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1158274 T2678 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1158275 T2678 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1158275 T2678 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1158276 T2678 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1158277 T2678 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1158277 T2678 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1158280 T2678 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1158281 T2678 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1158282 T2678 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1158293 T2678 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1158304 T2678 oass.SolrIndexSearcher.<init> Opening Searcher@46fa2706 main
[junit4:junit4] 2> 1158305 T2678 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1158306 T2678 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1158310 T2681 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@46fa2706 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1158312 T2678 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1158312 T2678 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:18951/ud/d collection:collection1 shard:shard1
[junit4:junit4] 2> 1158316 T2678 oasc.ZkController.register We are http://127.0.0.1:18951/ud/d/collection1/ and leader is http://127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1158316 T2678 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:18951/ud/d
[junit4:junit4] 2> 1158316 T2678 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1158317 T2678 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C812 name=collection1 org.apache.solr.core.SolrCore@1e7939b0 url=http://127.0.0.1:18951/ud/d/collection1 node=127.0.0.1:18951_ud%2Fd C812_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:18951_ud%2Fd, base_url=http://127.0.0.1:18951/ud/d}
[junit4:junit4] 2> 1158317 T2682 C812 P18951 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1158317 T2682 C812 P18951 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1158317 T2678 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1158318 T2682 C812 P18951 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1158318 T2682 C812 P18951 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1158319 T2583 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1158319 T2583 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1158320 T2682 C812 P18951 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1158320 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1158347 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1158347 T2621 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1158349 T2583 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1158349 T2583 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1158350 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1159351 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1159469 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1159470 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:18951_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18951/ud/d"}
[junit4:junit4] 2> 1159517 T2677 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> 1159517 T2612 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> 1159517 T2625 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> 1159517 T2605 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> 1159517 T2641 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> 1159517 T2658 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> 1160350 T2621 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1160350 T2621 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:18951_ud%252Fd&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1160353 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1161355 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C812_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:18951_ud%2Fd, base_url=http://127.0.0.1:18951/ud/d}
[junit4:junit4] 2> 1162352 T2682 C812 P18951 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:19794/ud/d/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1162352 T2682 C812 P18951 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18951/ud/d START replicas=[http://127.0.0.1:19794/ud/d/collection1/] nUpdates=100
[junit4:junit4] 2> 1162353 T2682 C812 P18951 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1162353 T2682 C812 P18951 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1162353 T2682 C812 P18951 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1162353 T2682 C812 P18951 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1162353 T2682 C812 P18951 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1162353 T2682 C812 P18951 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:19794/ud/d/collection1/. core=collection1
[junit4:junit4] 2> 1162354 T2682 C812 P18951 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C813 name=collection1 org.apache.solr.core.SolrCore@2d4a00ff url=http://127.0.0.1:19794/ud/d/collection1 node=127.0.0.1:19794_ud%2Fd C813_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19794_ud%2Fd, base_url=http://127.0.0.1:19794/ud/d, leader=true}
[junit4:junit4] 2> 1162355 T2616 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1162357 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1162364 T2615 C813 P19794 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1162405 T2615 C813 P19794 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 1162406 T2615 C813 P19794 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 1162407 T2615 C813 P19794 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1162407 T2615 C813 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 43
[junit4:junit4] 2> 1162409 T2682 C812 P18951 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1162409 T2682 C812 P18951 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1162411 T2618 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 1162412 T2682 C812 P18951 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 1162412 T2682 C812 P18951 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1162412 T2682 C812 P18951 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1162416 T2618 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 1162417 T2682 C812 P18951 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1162419 T2682 C812 P18951 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index.20130625144512970
[junit4:junit4] 2> 1162420 T2682 C812 P18951 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index.20130625144512970 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ff62bac fullCopy=false
[junit4:junit4] 2> 1162424 T2618 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 1162426 T2682 C812 P18951 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1162429 T2682 C812 P18951 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1162429 T2682 C812 P18951 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1162434 T2682 C812 P18951 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 1162434 T2682 C812 P18951 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 1162434 T2682 C812 P18951 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1162436 T2682 C812 P18951 oass.SolrIndexSearcher.<init> Opening Searcher@85d59a0 main
[junit4:junit4] 2> 1162437 T2681 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@85d59a0 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 1162438 T2682 C812 P18951 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index.20130625144512970 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index.20130625144512970;done=true>>]
[junit4:junit4] 2> 1162438 T2682 C812 P18951 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index.20130625144512970
[junit4:junit4] 2> 1162438 T2682 C812 P18951 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index.20130625144512970
[junit4:junit4] 2> 1162439 T2682 C812 P18951 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1162439 T2682 C812 P18951 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1162440 T2682 C812 P18951 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1162440 T2682 C812 P18951 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1162441 T2682 C812 P18951 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1162524 T2606 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1162525 T2606 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:18951_ud%2Fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18951/ud/d"}
[junit4:junit4] 2> 1162538 T2625 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> 1162539 T2677 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> 1162538 T2605 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> 1162538 T2641 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> 1162538 T2612 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> 1162538 T2658 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> 1163359 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1163360 T2583 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C814 name=collection1 org.apache.solr.core.SolrCore@73280d3a url=http://127.0.0.1:19790/ud/d/collection1 node=127.0.0.1:19790_ud%2Fd C814_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:19790_ud%2Fd, base_url=http://127.0.0.1:19790/ud/d, leader=true}
[junit4:junit4] 2> 1163373 T2595 C814 P19790 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1163379 T2595 C814 P19790 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 1163379 T2595 C814 P19790 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1163383 T2595 C814 P19790 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 1163384 T2595 C814 P19790 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1163386 T2595 C814 P19790 oass.SolrIndexSearcher.<init> Opening Searcher@22d52347 main
[junit4:junit4] 2> 1163386 T2595 C814 P19790 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1163387 T2609 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@22d52347 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1163389 T2595 C814 P19790 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> ASYNC NEW_CORE C815 name=collection1 org.apache.solr.core.SolrCore@1a007be3 url=http://127.0.0.1:12000/ud/d/collection1 node=127.0.0.1:12000_ud%2Fd C815_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:12000_ud%2Fd, base_url=http://127.0.0.1:12000/ud/d}
[junit4:junit4] 2> 1163411 T2631 C815 P12000 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:19794/ud/d/collection1/, StdNode: http://127.0.0.1:12000/ud/d/collection1/, StdNode: http://127.0.0.1:18619/ud/d/collection1/, StdNode: http://127.0.0.1:18951/ud/d/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1163415 T2617 C813 P19794 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1163415 T2632 C815 P12000 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C812_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18951_ud%2Fd, base_url=http://127.0.0.1:18951/ud/d}
[junit4:junit4] 2> 1163430 T2667 C812 P18951 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1163430 T2617 C813 P19794 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> ASYNC NEW_CORE C816 name=collection1 org.apache.solr.core.SolrCore@dcfc13e url=http://127.0.0.1:18619/ud/d/collection1 node=127.0.0.1:18619_ud%2Fd C816_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18619_ud%2Fd, base_url=http://127.0.0.1:18619/ud/d}
[junit4:junit4] 2> 1163431 T2648 C816 P18619 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1163431 T2632 C815 P12000 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 1163432 T2617 C813 P19794 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 1163433 T2632 C815 P12000 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1163436 T2617 C813 P19794 oass.SolrIndexSearcher.<init> Opening Searcher@2d9cca46 main
[junit4:junit4] 2> 1163436 T2632 C815 P12000 oass.SolrIndexSearcher.<init> Opening Searcher@72f23851 main
[junit4:junit4] 2> 1163437 T2617 C813 P19794 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1163437 T2632 C815 P12000 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1163438 T2627 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d9cca46 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1163438 T2643 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@72f23851 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1163438 T2617 C813 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4] 2> 1163439 T2632 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 1163441 T2667 C812 P18951 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 1163442 T2667 C812 P18951 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 1163443 T2648 C816 P18619 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 1163443 T2648 C816 P18619 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 1163444 T2667 C812 P18951 oass.SolrIndexSearcher.<init> Opening Searcher@499e072f main
[junit4:junit4] 2> 1163444 T2667 C812 P18951 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1163445 T2681 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@499e072f main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 1163445 T2648 C816 P18619 oass.SolrIndexSearcher.<init> Opening Searcher@165e603f main
[junit4:junit4] 2> 1163445 T2667 C812 P18951 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 15
[junit4:junit4] 2> 1163446 T2648 C816 P18619 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1163447 T2662 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@165e603f main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 1163447 T2648 C816 P18619 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 17
[junit4:junit4] 2> 1163448 T2631 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 37
[junit4:junit4] 2> 1163449 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1163451 T2619 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1163453 T2633 C815 P12000 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1163455 T2649 C816 P18619 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1163457 T2668 C812 P18951 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 1165463 T2595 C814 P19790 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438807245207896064)} 0 3
[junit4:junit4] 2> 1165475 T2651 C816 P18619 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={update.distrib=FROMLEADER&_version_=-1438807245215236096&update.from=http://127.0.0.1:19794/ud/d/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438807245215236096)} 0 2
[junit4:junit4] 2> 1165476 T2669 C812 P18951 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={update.distrib=FROMLEADER&_version_=-1438807245215236096&update.from=http://127.0.0.1:19794/ud/d/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438807245215236096)} 0 3
[junit4:junit4] 2> 1165476 T2634 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={update.distrib=FROMLEADER&_version_=-1438807245215236096&update.from=http://127.0.0.1:19794/ud/d/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438807245215236096)} 0 3
[junit4:junit4] 2> 1165477 T2620 C813 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438807245215236096)} 0 9
[junit4:junit4] 2> 1165478 T2650 C816 P18619 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 13
[junit4:junit4] 2> 1165483 T2595 C814 P19790 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={wt=javabin&version=2} {add=[0 (1438807245227819008)]} 0 3
[junit4:junit4] 2> 1165496 T2634 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438807245234110464)]} 0 4
[junit4:junit4] 2> 1165496 T2651 C816 P18619 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438807245234110464)]} 0 4
[junit4:junit4] 2> 1165496 T2669 C812 P18951 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438807245234110464)]} 0 4
[junit4:junit4] 2> 1165497 T2621 C813 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={wt=javabin&version=2} {add=[0 (1438807245234110464)]} 0 11
[junit4:junit4] 2> 1165501 T2595 C814 P19790 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={wt=javabin&version=2} {add=[1 (1438807245248790528)]} 0 1
[junit4:junit4] 2> 1165509 T2634 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438807245254033408)]} 0 1
[junit4:junit4] 2> 1165509 T2651 C816 P18619 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438807245254033408)]} 0 1
[junit4:junit4] 2> 1165509 T2669 C812 P18951 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438807245254033408)]} 0 1
[junit4:junit4] 2> 1165510 T2617 C813 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:12000/ud/d/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1438807245254033408)]} 0 5
[junit4:junit4] 2> 1165511 T2631 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={wt=javabin&version=2} {add=[1]} 0 8
[junit4:junit4] 2> 1165515 T2595 C814 P19790 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={wt=javabin&version=2} {add=[2 (1438807245263470592)]} 0 1
[junit4:junit4] 2> 1165519 T2615 C813 P19794 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:12000/ud/d/collection1/]
[junit4:junit4] 2> 1165519 T2615 C813 P19794 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:12000/ud/d/collection1/ against:[http://127.0.0.1:12000/ud/d/collection1/] result:true
[junit4:junit4] 2> 1165520 T2615 C813 P19794 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18619/ud/d/collection1/ against:[http://127.0.0.1:12000/ud/d/collection1/] result:false
[junit4:junit4] 2> 1165520 T2615 C813 P19794 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18951/ud/d/collection1/ against:[http://127.0.0.1:12000/ud/d/collection1/] result:false
[junit4:junit4] 2> 1165524 T2651 C816 P18619 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:12000/ud/d/collection1/&wt=javabin&version=2} {add=[2 (1438807245269762048)]} 0 1
[junit4:junit4] 2> 1165524 T2669 C812 P18951 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:12000/ud/d/collection1/&wt=javabin&version=2} {add=[2 (1438807245269762048)]} 0 1
[junit4:junit4] 2> 1165525 T2615 C813 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:18951/ud/d/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:12000/ud/d/collection1/&wt=javabin&version=2} {add=[2 (1438807245269762048)]} 0 7
[junit4:junit4] 2> 1165526 T2670 C812 P18951 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={test.distrib.skip.servers=http://127.0.0.1:12000/ud/d/collection1/&wt=javabin&version=2} {add=[2]} 0 9
[junit4:junit4] 2> 1165529 T2595 C814 P19790 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={wt=javabin&version=2} {add=[3 (1438807245278150656)]} 0 1
[junit4:junit4] 2> 1165535 T2617 C813 P19794 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:12000/ud/d/collection1/]
[junit4:junit4] 2> 1165536 T2617 C813 P19794 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:12000/ud/d/collection1/ against:[http://127.0.0.1:12000/ud/d/collection1/] result:true
[junit4:junit4] 2> 1165536 T2617 C813 P19794 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18619/ud/d/collection1/ against:[http://127.0.0.1:12000/ud/d/collection1/] result:false
[junit4:junit4] 2> 1165537 T2617 C813 P19794 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:18951/ud/d/collection1/ against:[http://127.0.0.1:12000/ud/d/collection1/] result:false
[junit4:junit4] 2> 1165541 T2669 C812 P18951 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:12000/ud/d/collection1/&wt=javabin&version=2} {add=[3 (1438807245287587840)]} 0 1
[junit4:junit4] 2> 1165541 T2651 C816 P18619 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:19794/ud/d/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:12000/ud/d/collection1/&wt=javabin&version=2} {add=[3 (1438807245287587840)]} 0 1
[junit4:junit4] 2> 1165542 T2617 C813 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={distrib.from=http://127.0.0.1:12000/ud/d/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:12000/ud/d/collection1/&wt=javabin&version=2} {add=[3 (1438807245287587840)]} 0 7
[junit4:junit4] 2> 1165543 T2631 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={test.distrib.skip.servers=http://127.0.0.1:12000/ud/d/collection1/&test.distrib.skip.servers=http://127.0.0.1:18619/ud/d/collection1/&wt=javabin&version=2} {add=[3]} 0 11
[junit4:junit4] 2> 1165545 T2595 C814 P19790 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165637 T2595 C814 P19790 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 1165637 T2595 C814 P19790 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1165642 T2595 C814 P19790 oass.SolrIndexSearcher.<init> Opening Searcher@3822f963 main
[junit4:junit4] 2> 1165643 T2595 C814 P19790 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1165643 T2609 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3822f963 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 1165644 T2595 C814 P19790 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 99
[junit4:junit4] 2> 1165647 T2631 C815 P12000 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:19794/ud/d/collection1/, StdNode: http://127.0.0.1:12000/ud/d/collection1/, StdNode: http://127.0.0.1:18619/ud/d/collection1/, StdNode: http://127.0.0.1:18951/ud/d/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1165650 T2617 C813 P19794 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165650 T2632 C815 P12000 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165650 T2667 C812 P18951 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165650 T2648 C816 P18619 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165747 T2667 C812 P18951 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> 1165747 T2617 C813 P19794 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> 1165748 T2667 C812 P18951 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 1165748 T2617 C813 P19794 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 1165753 T2667 C812 P18951 oass.SolrIndexSearcher.<init> Opening Searcher@636fee1a main
[junit4:junit4] 2> 1165753 T2617 C813 P19794 oass.SolrIndexSearcher.<init> Opening Searcher@3d92eeeb main
[junit4:junit4] 2> 1165754 T2632 C815 P12000 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty2/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 1165754 T2667 C812 P18951 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1165755 T2627 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d92eeeb main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 1165755 T2681 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@636fee1a main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 1165755 T2632 C815 P12000 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 1165755 T2617 C813 P19794 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1165754 T2648 C816 P18619 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 1165757 T2617 C813 P19794 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 107
[junit4:junit4] 2> 1165757 T2667 C812 P18951 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 107
[junit4:junit4] 2> 1165758 T2648 C816 P18619 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 1165761 T2632 C815 P12000 oass.SolrIndexSearcher.<init> Opening Searcher@7c6ce4da main
[junit4:junit4] 2> 1165763 T2632 C815 P12000 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1165764 T2643 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7c6ce4da main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):c2)}
[junit4:junit4] 2> 1165765 T2632 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 115
[junit4:junit4] 2> 1165767 T2648 C816 P18619 oass.SolrIndexSearcher.<init> Opening Searcher@782dbf39 main
[junit4:junit4] 2> 1165768 T2648 C816 P18619 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1165769 T2662 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@782dbf39 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 1165769 T2648 C816 P18619 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 119
[junit4:junit4] 2> 1165770 T2631 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 123
[junit4:junit4] 2> 1165771 T2583 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 1165772 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1165773 T2583 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 1165776 T2619 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 1165779 T2633 C815 P12000 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=0
[junit4:junit4] 2> 1165782 T2649 C816 P18619 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 1165785 T2668 C812 P18951 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 1165786 T2583 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1165807 T2652 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 1165808 T2652 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1165820 T2695 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 1165821 T2695 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1165821 T2695 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:19794/ud/d START replicas=[http://127.0.0.1:12000/ud/d/collection1/, http://127.0.0.1:18619/ud/d/collection1/, http://127.0.0.1:18951/ud/d/collection1/] nUpdates=100
[junit4:junit4] 2> 1165823 T2635 C815 P12000 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1165824 T2653 C816 P18619 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1165824 T2695 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:19794/ud/d Received 3 versions from 127.0.0.1:12000/ud/d/collection1/
[junit4:junit4] 2> 1165824 T2671 C812 P18951 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1165824 T2695 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:19794/ud/d Our versions are newer. ourLowThreshold=1438807245215236096 otherHigh=1438807245254033408
[junit4:junit4] 2> 1165825 T2695 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:19794/ud/d Received 5 versions from 127.0.0.1:18619/ud/d/collection1/
[junit4:junit4] 2> 1165826 T2695 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:19794/ud/d Our versions are newer. ourLowThreshold=1438807245215236096 otherHigh=1438807245269762048
[junit4:junit4] 2> 1165826 T2695 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:19794/ud/d Received 5 versions from 127.0.0.1:18951/ud/d/collection1/
[junit4:junit4] 2> 1165826 T2695 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:19794/ud/d Our versions are newer. ourLowThreshold=1438807245215236096 otherHigh=1438807245269762048
[junit4:junit4] 2> 1165827 T2695 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:19794/ud/d DONE. sync succeeded
[junit4:junit4] 2> 1165827 T2695 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1165827 T2695 oasc.SyncStrategy.syncToMe http://127.0.0.1:19794/ud/d/collection1/: try and ask http://127.0.0.1:12000/ud/d/collection1/ to sync
[junit4:junit4] 2> 1165828 T2695 oasc.SyncStrategy.syncToMe http://127.0.0.1:19794/ud/d/collection1/: try and ask http://127.0.0.1:18619/ud/d/collection1/ to sync
[junit4:junit4] 2> 1165828 T2695 oasc.SyncStrategy.syncToMe http://127.0.0.1:19794/ud/d/collection1/: try and ask http://127.0.0.1:18951/ud/d/collection1/ to sync
[junit4:junit4] 2> 1165829 T2636 C815 P12000 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:12000/ud/d START replicas=[http://127.0.0.1:19794/ud/d/collection1/] nUpdates=100
[junit4:junit4] 2> 1165829 T2654 C816 P18619 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18619/ud/d START replicas=[http://127.0.0.1:19794/ud/d/collection1/] nUpdates=100
[junit4:junit4] 2> 1165830 T2672 C812 P18951 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18951/ud/d START replicas=[http://127.0.0.1:19794/ud/d/collection1/] nUpdates=100
[junit4:junit4] 2> 1165831 T2705 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1165832 T2706 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1165832 T2654 C816 P18619 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:18619/ud/d Received 5 versions from 127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1165832 T2672 C812 P18951 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:18951/ud/d Received 5 versions from 127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1165832 T2616 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1165833 T2672 C812 P18951 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:18951/ud/d Our versions are newer. ourLowThreshold=1438807245215236096 otherHigh=1438807245269762048
[junit4:junit4] 2> 1165833 T2654 C816 P18619 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:18619/ud/d Our versions are newer. ourLowThreshold=1438807245215236096 otherHigh=1438807245269762048
[junit4:junit4] 2> 1165834 T2672 C812 P18951 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18951/ud/d DONE. sync succeeded
[junit4:junit4] 2> 1165834 T2636 C815 P12000 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:12000/ud/d Received 5 versions from 127.0.0.1:19794/ud/d/collection1/
[junit4:junit4] 2> 1165834 T2672 C812 P18951 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={sync=http://127.0.0.1:19794/ud/d/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=4
[junit4:junit4] 2> 1165834 T2654 C816 P18619 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:18619/ud/d DONE. sync succeeded
[junit4:junit4] 2> 1165835 T2636 C815 P12000 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:12000/ud/d Requesting updates from 127.0.0.1:19794/ud/d/collection1/n=2 versions=[1438807245287587840, 1438807245269762048]
[junit4:junit4] 2> 1165836 T2695 oasc.SyncStrategy.syncToMe http://127.0.0.1:19794/ud/d/collection1/: sync completed with http://127.0.0.1:18951/ud/d/collection1/
[junit4:junit4] 2> 1165836 T2654 C816 P18619 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={sync=http://127.0.0.1:19794/ud/d/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=7
[junit4:junit4] 2> 1165837 T2695 oasc.SyncStrategy.syncToMe http://127.0.0.1:19794/ud/d/collection1/: sync completed with http://127.0.0.1:18619/ud/d/collection1/
[junit4:junit4] 2> 1165838 T2616 C813 P19794 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={distrib=false&getUpdates=1438807245287587840,1438807245269762048&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1165844 T2636 C815 P12000 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438807245269762048), 3 (1438807245287587840)]} 0 5
[junit4:junit4] 2> 1165845 T2636 C815 P12000 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:12000/ud/d DONE. sync succeeded
[junit4:junit4] 2> 1165845 T2636 C815 P12000 oasc.SolrCore.execute [collection1] webapp=/ud/d path=/get params={sync=http://127.0.0.1:19794/ud/d/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=16
[junit4:junit4] 2> 1165846 T2695 oasc.SyncStrategy.syncToMe http://127.0.0.1:19794/ud/d/collection1/: sync completed with http://127.0.0.1:12000/ud/d/collection1/
[junit4:junit4] 2> 1165846 T2695 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={shard=shard1&action=REQUESTSYNCSHARD&core=collection1&collection=collection1&wt=javabin&version=2} status=0 QTime=26
[junit4:junit4] 2> 1165847 T2652 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2} status=0 QTime=40
[junit4:junit4] 2> 1165848 T2583 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1165848 T2583 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1165849 T2583 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1165850 T2583 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 1165852 T2595 C814 P19790 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165861 T2595 C814 P19790 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/control/data/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 1165861 T2595 C814 P19790 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 1165863 T2595 C814 P19790 oass.SolrIndexSearcher.<init> Opening Searcher@1de6ff5a main
[junit4:junit4] 2> 1165864 T2595 C814 P19790 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1165865 T2609 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1de6ff5a main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 1165865 T2595 C814 P19790 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 13
[junit4:junit4] 2> 1165868 T2670 C812 P18951 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:19794/ud/d/collection1/, StdNode: http://127.0.0.1:12000/ud/d/collection1/, StdNode: http://127.0.0.1:18619/ud/d/collection1/, StdNode: http://127.0.0.1:18951/ud/d/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1165871 T2637 C815 P12000 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165871 T2710 C816 P18619 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165871 T2673 C812 P18951 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165871 T2615 C813 P19794 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1165889 T2673 C812 P18951 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty4/index,segFN=segments_7,generation=7}
[junit4:junit4] 2> 1165889 T2710 C816 P18619 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty3/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> 1165890 T2673 C812 P18951 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 1165890 T2710 C816 P18619 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 1165893 T2673 C812 P18951 oass.SolrIndexSearcher.<init> Opening Searcher@5051d760 main
[junit4:junit4] 2> 1165893 T2673 C812 P18951 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1165893 T2710 C816 P18619 oass.SolrIndexSearcher.<init> Opening Searcher@3ca82a1c main
[junit4:junit4] 2> 1165894 T2681 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5051d760 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 1165894 T2710 C816 P18619 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1165895 T2673 C812 P18951 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 1165895 T2662 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ca82a1c main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 1165895 T2615 C813 P19794 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> commit{dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1372153487860/jetty1/index,segFN=segments_7,generation=7}
[junit4:junit4] 2> 1165896 T2710 C816 P18619 oasup.LogUpdateProcessor.finish [collection1] webapp=/ud/d path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 25
[junit4:junit4] 2> 1165896 T2615 C813 P19794 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 1165899 T2615 C813 P19794 oass.SolrIndexSearcher.<init> Opening S
[...truncated too long message...]
as":{"1":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "node_name":"127.0.0.1:19790_ud%2Fd",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:19790/ud/d",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"}}
[junit4:junit4] 1> /solr/aliases.json (0)
[junit4:junit4] 1> /solr/live_nodes (4)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:18619_ud%2Fd (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:18951_ud%2Fd (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:19794_ud%2Fd (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:19790_ud%2Fd (0)
[junit4:junit4] 1> /solr/overseer (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/overseer/queue (0)
[junit4:junit4] 1> /solr/overseer/queue-work (0)
[junit4:junit4] 1> /solr/overseer/collection-queue-work (0)
[junit4:junit4] 1> /solr/collections (2)
[junit4:junit4] 1> /solr/collections/collection1 (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/collection1/shards (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election (3)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89925450980917258-4-n_0000000005 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89925450980917260-5-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89925450980917262-2-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/collection1/leaders (1)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:18951_ud%2Fd",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:18951/ud/d"}
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89925450980917251-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> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:19790_ud%2Fd",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:19790/ud/d"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (4)
[junit4:junit4] 1> /solr/overseer_elect/election/89925450980917262-127.0.0.1:19794_ud%2Fd-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89925450980917258-127.0.0.1:18619_ud%2Fd-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89925450980917251-127.0.0.1:19790_ud%2Fd-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89925450980917260-127.0.0.1:18951_ud%2Fd-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89925450980917251-127.0.0.1:19790_ud%2Fd-n_0000000000"}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=9D102214822078A5 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=vi -Dtests.timezone=Etc/GMT-5 -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 511s J1 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:19794/ud/d/collection1lastClient and got 257 from http://127.0.0.1:18619/ud/d/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([9D102214822078A5:1CF6AC0CF57F1899]: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:679)
[junit4:junit4] 2> 1648216 T2583 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 510919 T2582 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 1648915 T2677 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1648915 T2677 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> 1648915 T2677 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=Lucene41(blocksize=128), text=PostingsFormat(name=MockSep), _version_=Lucene41(blocksize=128), rnd_b=Pulsing41(freqCutoff=17 minBlockSize=4 maxBlockSize=13), intDefault=Lucene41(blocksize=128), id=Pulsing41(freqCutoff=17 minBlockSize=4 maxBlockSize=13), timestamp=Lucene41(blocksize=128), a_t=PostingsFormat(name=SimpleText), range_facet_sl=Pulsing41(freqCutoff=17 minBlockSize=4 maxBlockSize=13), range_facet_si=PostingsFormat(name=SimpleText), other_tl1=Lucene41(blocksize=128), multiDefault=Lucene41(blocksize=128), a_si=Lucene41(blocksize=128)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=vi, timezone=Etc/GMT-5
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=1,free=219231216,total=452329472
[junit4:junit4] 2> NOTE: All tests run in this JVM: [FieldAnalysisRequestHandlerTest, XmlUpdateRequestHandlerTest, SolrPluginUtilsTest, ChaosMonkeySafeLeaderTest, TestDFRSimilarityFactory, TestSolrQueryParserResource, DirectSolrSpellCheckerTest, BasicDistributedZk2Test, DefaultValueUpdateProcessorTest, CurrencyFieldXmlFileTest, PathHierarchyTokenizerFactoryTest, PingRequestHandlerTest, UniqFieldsUpdateProcessorFactoryTest, TestLuceneMatchVersion, FullSolrCloudDistribCmdsTest, TestRecovery, CollectionsAPIDistributedZkTest, TestCSVLoader, JSONWriterTest, SampleTest, ConvertedLegacyTest, TestReload, TestMaxScoreQueryParser, TestOmitPositions, NotRequiredUniqueKeyTest, TestLazyCores, SolrCoreCheckLockOnStartupTest, TestUniqueKeyFieldResource, TestCoreDiscovery, TestUpdate, TestUtils, BasicZkTest, CurrencyFieldOpenExchangeTest, XsltUpdateRequestHandlerTest, TestPropInject, StandardRequestHandlerTest, TestSchemaNameResource, FileUtilsTest, NoCacheHeaderTest, TestShardHandlerFactory, IndexBasedSpellCheckerTest, ShardRoutingCustomTest, TestFiltering, SolrCmdDistributorTest, TestDynamicFieldCollectionResource, ZkSolrClientTest, UpdateParamsTest, CopyFieldTest, TestRTGBase, TestFastOutputStream, TestMultiCoreConfBootstrap, TestSolrQueryParserDefaultOperatorResource, DirectUpdateHandlerTest, SuggesterWFSTTest, CoreContainerCoreInitFailuresTest, TestWordDelimiterFilterFactory, TermVectorComponentDistributedTest, TestAnalyzedSuggestions, RequestHandlersTest, TestJmxIntegration, TestRandomFaceting, OutputWriterTest, DebugComponentTest, ZkNodePropsTest, HighlighterTest, TestBM25SimilarityFactory, DateMathParserTest, TestIndexSearcher, MultiTermTest, TestFieldTypeCollectionResource, SyncSliceTest]
[junit4:junit4] Completed on J1 in 511.70s, 1 test, 1 failure <<< FAILURES!
[...truncated 409 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:392: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:372: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1246: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 52 minutes 19 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure