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/30 16:08:10 UTC
[JENKINS] Lucene-Solr-NightlyTests-trunk - Build # 306 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-trunk/306/
2 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.BasicDistributedZkTest
Error Message:
1 thread leaked from SUITE scope at org.apache.solr.cloud.BasicDistributedZkTest: 1) Thread[id=2512, name=recoveryCmdExecutor-1007-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest] at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391) at java.net.Socket.connect(Socket.java:579) at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127) at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180) at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294) at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645) at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180) at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:722)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.BasicDistributedZkTest:
1) Thread[id=2512, name=recoveryCmdExecutor-1007-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391)
at java.net.Socket.connect(Socket.java:579)
at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:722)
at __randomizedtesting.SeedInfo.seed([32DFD129DBAC725]:0)
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.BasicDistributedZkTest
Error Message:
There are still zombie threads that couldn't be terminated: 1) Thread[id=2512, name=recoveryCmdExecutor-1007-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest] at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391) at java.net.Socket.connect(Socket.java:579) at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127) at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180) at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294) at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645) at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180) at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:722)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
1) Thread[id=2512, name=recoveryCmdExecutor-1007-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391)
at java.net.Socket.connect(Socket.java:579)
at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:722)
at __randomizedtesting.SeedInfo.seed([32DFD129DBAC725]:0)
Build Log:
[...truncated 9558 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4] 2> 597199 T2029 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /_/
[junit4:junit4] 2> 597204 T2029 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZkTest-1372600986377
[junit4:junit4] 2> 597206 T2029 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 597207 T2030 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 597307 T2029 oasc.ZkTestServer.run start zk server on port:58978
[junit4:junit4] 2> 597308 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 597312 T2036 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7ef7b1c9 name:ZooKeeperConnection Watcher:127.0.0.1:58978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 597313 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 597313 T2029 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 597331 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 597333 T2038 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@137bcd84 name:ZooKeeperConnection Watcher:127.0.0.1:58978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 597333 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 597333 T2029 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 597337 T2029 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 597347 T2029 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 597349 T2029 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 597357 T2029 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 597358 T2029 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 597371 T2029 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 597372 T2029 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 597475 T2029 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 597476 T2029 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 597479 T2029 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 597480 T2029 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 597483 T2029 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 597484 T2029 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 597492 T2029 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 597493 T2029 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 597496 T2029 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 597497 T2029 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 597500 T2029 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 597501 T2029 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 597504 T2029 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 597504 T2029 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 597826 T2029 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 597831 T2029 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:44628
[junit4:junit4] 2> 597831 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 597832 T2029 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 597832 T2029 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372600986687
[junit4:junit4] 2> 597833 T2029 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372600986687/solr.xml
[junit4:junit4] 2> 597833 T2029 oasc.CoreContainer.<init> New CoreContainer 1666776894
[junit4:junit4] 2> 597834 T2029 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372600986687/'
[junit4:junit4] 2> 597834 T2029 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372600986687/'
[junit4:junit4] 2> 597994 T2029 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 597995 T2029 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 597995 T2029 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 597996 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 597996 T2029 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 597997 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 597997 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 597998 T2029 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 597998 T2029 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 597999 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 598019 T2029 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 598020 T2029 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58978/solr
[junit4:junit4] 2> 598020 T2029 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 598021 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 598024 T2049 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48a468ad name:ZooKeeperConnection Watcher:127.0.0.1:58978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 598025 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 598027 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 598040 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 598042 T2051 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1aa694ed name:ZooKeeperConnection Watcher:127.0.0.1:58978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 598042 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 598044 T2029 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 598054 T2029 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 598058 T2029 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 598065 T2029 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44628__
[junit4:junit4] 2> 598067 T2029 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44628__
[junit4:junit4] 2> 598070 T2029 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 598089 T2029 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 598092 T2029 oasc.Overseer.start Overseer (id=89954778243792899-127.0.0.1:44628__-n_0000000000) starting
[junit4:junit4] 2> 598103 T2029 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 598114 T2053 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 598115 T2029 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 598117 T2029 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 598119 T2029 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 598122 T2052 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 598126 T2054 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 598126 T2054 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 598127 T2054 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 599625 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 599626 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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:44628__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44628/_"}
[junit4:junit4] 2> 599627 T2052 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 599627 T2052 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 599655 T2051 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> 600130 T2054 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 600130 T2054 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372600986687/collection1
[junit4:junit4] 2> 600130 T2054 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 600131 T2054 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 600131 T2054 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 600133 T2054 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372600986687/collection1/'
[junit4:junit4] 2> 600135 T2054 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372600986687/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 600136 T2054 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372600986687/collection1/lib/README' to classloader
[junit4:junit4] 2> 600193 T2054 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 600273 T2054 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 600374 T2054 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 600382 T2054 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 601058 T2054 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 601071 T2054 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 601075 T2054 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 601088 T2054 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 601093 T2054 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 601097 T2054 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 601097 T2054 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 601098 T2054 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 601098 T2054 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 601099 T2054 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 601099 T2054 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 601099 T2054 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 601099 T2054 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1372600986687/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/control/data/
[junit4:junit4] 2> 601099 T2054 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3a6f5db5
[junit4:junit4] 2> 601100 T2054 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/control/data
[junit4:junit4] 2> 601100 T2054 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/control/data/index/
[junit4:junit4] 2> 601101 T2054 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 601101 T2054 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/control/data/index
[junit4:junit4] 2> 601105 T2054 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 601106 T2054 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 601108 T2054 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 601108 T2054 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 601109 T2054 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 601109 T2054 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 601109 T2054 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 601109 T2054 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 601110 T2054 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 601110 T2054 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 601110 T2054 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 601127 T2054 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 601135 T2054 oass.SolrIndexSearcher.<init> Opening Searcher@775b2b07 main
[junit4:junit4] 2> 601136 T2054 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 601136 T2054 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 601139 T2055 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@775b2b07 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 601139 T2054 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 601140 T2054 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44628/_ collection:control_collection shard:shard1
[junit4:junit4] 2> 601140 T2054 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 601174 T2054 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 601178 T2054 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 601178 T2054 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 601178 T2054 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:44628/_/collection1/
[junit4:junit4] 2> 601178 T2054 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 601178 T2054 oasc.SyncStrategy.syncToMe http://127.0.0.1:44628/_/collection1/ has no replicas
[junit4:junit4] 2> 601179 T2054 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:44628/_/collection1/ shard1
[junit4:junit4] 2> 601179 T2054 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 602662 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 602683 T2051 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> 602730 T2054 oasc.ZkController.register We are http://127.0.0.1:44628/_/collection1/ and leader is http://127.0.0.1:44628/_/collection1/
[junit4:junit4] 2> 602730 T2054 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44628/_
[junit4:junit4] 2> 602730 T2054 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 602730 T2054 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 602731 T2054 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 602733 T2054 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 602734 T2029 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 602734 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 602735 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 602752 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 602753 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 602756 T2058 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@199b4eff name:ZooKeeperConnection Watcher:127.0.0.1:58978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 602756 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 602757 T2029 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 602759 T2029 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 603059 T2029 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 603062 T2029 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:39343
[junit4:junit4] 2> 603063 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 603064 T2029 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 603064 T2029 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372600991932
[junit4:junit4] 2> 603065 T2029 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372600991932/solr.xml
[junit4:junit4] 2> 603065 T2029 oasc.CoreContainer.<init> New CoreContainer 1529373263
[junit4:junit4] 2> 603066 T2029 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372600991932/'
[junit4:junit4] 2> 603066 T2029 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372600991932/'
[junit4:junit4] 2> 603199 T2029 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 603200 T2029 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 603200 T2029 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 603201 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 603201 T2029 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 603202 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 603202 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 603203 T2029 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 603203 T2029 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 603204 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 603219 T2029 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 603220 T2029 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58978/solr
[junit4:junit4] 2> 603221 T2029 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 603222 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 603225 T2069 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3098b2e2 name:ZooKeeperConnection Watcher:127.0.0.1:58978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 603225 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 603227 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 603238 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 603240 T2071 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f56441b name:ZooKeeperConnection Watcher:127.0.0.1:58978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 603240 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 603244 T2029 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 604189 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 604190 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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:44628__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44628/_"}
[junit4:junit4] 2> 604206 T2071 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> 604206 T2058 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> 604206 T2051 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> 604247 T2029 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39343__
[junit4:junit4] 2> 604249 T2029 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39343__
[junit4:junit4] 2> 604259 T2058 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 604259 T2071 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 604259 T2058 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> 604259 T2051 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 604259 T2071 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> 604260 T2051 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> 604265 T2072 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 604265 T2072 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 604266 T2072 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 605711 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 605712 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "numShards":"2",
[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:39343__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39343/_"}
[junit4:junit4] 2> 605713 T2052 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 605713 T2052 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 605755 T2058 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> 605756 T2071 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> 605755 T2051 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> 606268 T2072 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 606268 T2072 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372600991932/collection1
[junit4:junit4] 2> 606268 T2072 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 606269 T2072 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 606269 T2072 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 606271 T2072 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372600991932/collection1/'
[junit4:junit4] 2> 606272 T2072 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372600991932/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 606273 T2072 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372600991932/collection1/lib/README' to classloader
[junit4:junit4] 2> 606324 T2072 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 606390 T2072 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 606491 T2072 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 606497 T2072 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 607132 T2072 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 607144 T2072 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 607148 T2072 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 607163 T2072 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 607167 T2072 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 607172 T2072 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 607173 T2072 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 607173 T2072 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 607174 T2072 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 607174 T2072 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 607175 T2072 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 607175 T2072 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 607175 T2072 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1372600991932/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty1/
[junit4:junit4] 2> 607176 T2072 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3a6f5db5
[junit4:junit4] 2> 607177 T2072 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty1
[junit4:junit4] 2> 607177 T2072 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty1/index/
[junit4:junit4] 2> 607177 T2072 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 607178 T2072 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty1/index
[junit4:junit4] 2> 607182 T2072 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 607182 T2072 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 607185 T2072 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 607186 T2072 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 607186 T2072 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 607187 T2072 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 607188 T2072 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 607188 T2072 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 607188 T2072 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 607189 T2072 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 607189 T2072 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 607207 T2072 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 607215 T2072 oass.SolrIndexSearcher.<init> Opening Searcher@4700fb61 main
[junit4:junit4] 2> 607217 T2072 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 607217 T2072 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 607221 T2073 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4700fb61 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 607223 T2072 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 607224 T2072 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39343/_ collection:collection1 shard:shard1
[junit4:junit4] 2> 607225 T2072 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 607241 T2072 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 607252 T2072 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 607252 T2072 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 607253 T2072 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39343/_/collection1/
[junit4:junit4] 2> 607253 T2072 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 607253 T2072 oasc.SyncStrategy.syncToMe http://127.0.0.1:39343/_/collection1/ has no replicas
[junit4:junit4] 2> 607253 T2072 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39343/_/collection1/ shard1
[junit4:junit4] 2> 607254 T2072 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 607269 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 607286 T2051 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> 607286 T2071 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> 607286 T2058 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> 607319 T2072 oasc.ZkController.register We are http://127.0.0.1:39343/_/collection1/ and leader is http://127.0.0.1:39343/_/collection1/
[junit4:junit4] 2> 607319 T2072 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39343/_
[junit4:junit4] 2> 607319 T2072 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 607320 T2072 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 607320 T2072 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 607322 T2072 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 607323 T2029 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 607323 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 607324 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 607523 T2029 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 607525 T2029 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:22984
[junit4:junit4] 2> 607526 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 607526 T2029 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 607526 T2029 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372600996507
[junit4:junit4] 2> 607527 T2029 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372600996507/solr.xml
[junit4:junit4] 2> 607527 T2029 oasc.CoreContainer.<init> New CoreContainer 1370829670
[junit4:junit4] 2> 607527 T2029 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372600996507/'
[junit4:junit4] 2> 607528 T2029 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372600996507/'
[junit4:junit4] 2> 607615 T2029 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 607616 T2029 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 607616 T2029 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 607616 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 607617 T2029 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 607617 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 607617 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 607617 T2029 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 607618 T2029 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 607618 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 607630 T2029 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 607631 T2029 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58978/solr
[junit4:junit4] 2> 607631 T2029 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 607632 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 607635 T2085 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@308837f name:ZooKeeperConnection Watcher:127.0.0.1:58978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 607636 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 607650 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 607662 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 607665 T2087 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@783546d2 name:ZooKeeperConnection Watcher:127.0.0.1:58978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 607665 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 607674 T2029 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 608676 T2029 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:22984__
[junit4:junit4] 2> 608686 T2029 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:22984__
[junit4:junit4] 2> 608702 T2058 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 608702 T2087 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 608702 T2071 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 608702 T2051 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 608702 T2071 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> 608702 T2058 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> 608703 T2051 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> 608709 T2088 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 608709 T2088 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 608711 T2088 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 608791 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 608792 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "numShards":"2",
[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:39343__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:39343/_"}
[junit4:junit4] 2> 608796 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[junit4:junit4] 2> "numShards":"2",
[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:22984__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:22984/_"}
[junit4:junit4] 2> 608796 T2052 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 608796 T2052 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 608812 T2058 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> 608812 T2071 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> 608812 T2087 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> 608812 T2051 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> 609712 T2088 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 609712 T2088 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372600996507/collection1
[junit4:junit4] 2> 609712 T2088 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 609713 T2088 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 609713 T2088 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 609715 T2088 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372600996507/collection1/'
[junit4:junit4] 2> 609717 T2088 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372600996507/collection1/lib/README' to classloader
[junit4:junit4] 2> 609717 T2088 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372600996507/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 609773 T2088 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 609837 T2088 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 609939 T2088 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 609945 T2088 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 610579 T2088 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 610588 T2088 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 610590 T2088 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 610602 T2088 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 610606 T2088 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 610609 T2088 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 610610 T2088 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 610610 T2088 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 610611 T2088 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 610611 T2088 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 610611 T2088 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 610612 T2088 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 610612 T2088 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1372600996507/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty2/
[junit4:junit4] 2> 610612 T2088 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3a6f5db5
[junit4:junit4] 2> 610613 T2088 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty2
[junit4:junit4] 2> 610613 T2088 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty2/index/
[junit4:junit4] 2> 610613 T2088 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 610614 T2088 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty2/index
[junit4:junit4] 2> 610616 T2088 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b78cae9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@56f299df),segFN=segments_1,generation=1}
[junit4:junit4] 2> 610617 T2088 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 610619 T2088 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 610619 T2088 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 610620 T2088 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 610620 T2088 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 610620 T2088 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 610621 T2088 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 610621 T2088 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 610621 T2088 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 610622 T2088 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 610635 T2088 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 610640 T2088 oass.SolrIndexSearcher.<init> Opening Searcher@b8152b6 main
[junit4:junit4] 2> 610641 T2088 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 610641 T2088 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 610644 T2089 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b8152b6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 610645 T2088 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 610645 T2088 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:22984/_ collection:collection1 shard:shard2
[junit4:junit4] 2> 610646 T2088 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 610674 T2088 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4:junit4] 2> 610685 T2088 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 610685 T2088 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 610685 T2088 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:22984/_/collection1/
[junit4:junit4] 2> 610685 T2088 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 610686 T2088 oasc.SyncStrategy.syncToMe http://127.0.0.1:22984/_/collection1/ has no replicas
[junit4:junit4] 2> 610686 T2088 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:22984/_/collection1/ shard2
[junit4:junit4] 2> 610686 T2088 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 611820 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 611848 T2051 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> 611848 T2058 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> 611848 T2071 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> 611848 T2087 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> 611870 T2088 oasc.ZkController.register We are http://127.0.0.1:22984/_/collection1/ and leader is http://127.0.0.1:22984/_/collection1/
[junit4:junit4] 2> 611870 T2088 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:22984/_
[junit4:junit4] 2> 611870 T2088 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 611870 T2088 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 611870 T2088 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 611872 T2088 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 611873 T2029 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 611873 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 611874 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 612093 T2029 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 612096 T2029 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:56504
[junit4:junit4] 2> 612097 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 612098 T2029 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 612098 T2029 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372601001059
[junit4:junit4] 2> 612099 T2029 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372601001059/solr.xml
[junit4:junit4] 2> 612099 T2029 oasc.CoreContainer.<init> New CoreContainer 114599400
[junit4:junit4] 2> 612100 T2029 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372601001059/'
[junit4:junit4] 2> 612100 T2029 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372601001059/'
[junit4:junit4] 2> 612253 T2029 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 612253 T2029 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 612254 T2029 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 612254 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 612255 T2029 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 612255 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 612256 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 612256 T2029 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 612257 T2029 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 612257 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 612276 T2029 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 612276 T2029 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58978/solr
[junit4:junit4] 2> 612277 T2029 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 612278 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 612281 T2101 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5b56889f name:ZooKeeperConnection Watcher:127.0.0.1:58978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 612281 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 612294 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 612304 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 612306 T2103 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6c30c677 name:ZooKeeperConnection Watcher:127.0.0.1:58978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 612306 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 612311 T2029 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 613314 T2029 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56504__
[junit4:junit4] 2> 613319 T2029 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56504__
[junit4:junit4] 2> 613331 T2087 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613331 T2103 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613331 T2071 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613331 T2051 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613331 T2058 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 613332 T2051 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> 613332 T2071 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> 613331 T2087 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> 613332 T2058 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> 613339 T2104 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 613339 T2104 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 613341 T2104 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 613353 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 613354 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[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:22984__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:22984/_"}
[junit4:junit4] 2> 613358 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[junit4:junit4] 2> "numShards":"2",
[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:56504__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56504/_"}
[junit4:junit4] 2> 613358 T2052 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 613359 T2052 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 613371 T2103 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> 613371 T2058 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> 613371 T2071 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> 613371 T2087 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> 613371 T2051 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> 614342 T2104 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 614342 T2104 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372601001059/collection1
[junit4:junit4] 2> 614342 T2104 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 614343 T2104 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 614343 T2104 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 614345 T2104 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372601001059/collection1/'
[junit4:junit4] 2> 614346 T2104 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372601001059/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 614347 T2104 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372601001059/collection1/lib/README' to classloader
[junit4:junit4] 2> 614396 T2104 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 614454 T2104 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 614556 T2104 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 614561 T2104 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 615120 T2104 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 615128 T2104 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 615131 T2104 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 615143 T2104 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 615147 T2104 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 615150 T2104 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 615151 T2104 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 615151 T2104 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 615152 T2104 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 615152 T2104 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 615153 T2104 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 615153 T2104 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 615153 T2104 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1372601001059/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty3/
[junit4:junit4] 2> 615153 T2104 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3a6f5db5
[junit4:junit4] 2> 615154 T2104 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty3
[junit4:junit4] 2> 615154 T2104 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty3/index/
[junit4:junit4] 2> 615154 T2104 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 615155 T2104 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty3/index
[junit4:junit4] 2> 615157 T2104 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_1,generation=1}
[junit4:junit4] 2> 615157 T2104 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 615159 T2104 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 615160 T2104 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 615160 T2104 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 615160 T2104 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 615161 T2104 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 615161 T2104 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 615161 T2104 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 615162 T2104 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 615162 T2104 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 615172 T2104 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 615177 T2104 oass.SolrIndexSearcher.<init> Opening Searcher@30337a19 main
[junit4:junit4] 2> 615178 T2104 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 615178 T2104 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 615181 T2105 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@30337a19 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 615183 T2104 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 615183 T2104 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56504/_ collection:collection1 shard:shard1
[junit4:junit4] 2> 615243 T2104 oasc.ZkController.register We are http://127.0.0.1:56504/_/collection1/ and leader is http://127.0.0.1:39343/_/collection1/
[junit4:junit4] 2> 615243 T2104 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56504/_
[junit4:junit4] 2> 615243 T2104 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 615243 T2104 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C553 name=collection1 org.apache.solr.core.SolrCore@4e7df1f2 url=http://127.0.0.1:56504/_/collection1 node=127.0.0.1:56504__ C553_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:56504__, base_url=http://127.0.0.1:56504/_}
[junit4:junit4] 2> 615244 T2106 C553 P56504 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 615244 T2104 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 615244 T2106 C553 P56504 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 615244 T2106 C553 P56504 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 615245 T2106 C553 P56504 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 615245 T2029 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 615246 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 615246 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 615289 T2106 C553 P56504 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 615298 T2061 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 615522 T2029 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 615525 T2029 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:43950
[junit4:junit4] 2> 615525 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 615526 T2029 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 615526 T2029 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372601004435
[junit4:junit4] 2> 615527 T2029 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372601004435/solr.xml
[junit4:junit4] 2> 615527 T2029 oasc.CoreContainer.<init> New CoreContainer 398831986
[junit4:junit4] 2> 615528 T2029 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372601004435/'
[junit4:junit4] 2> 615528 T2029 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372601004435/'
[junit4:junit4] 2> 615654 T2029 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 615655 T2029 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 615655 T2029 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 615656 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 615656 T2029 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 615657 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 615657 T2029 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 615658 T2029 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 615658 T2029 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 615659 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 615676 T2029 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 615676 T2029 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:58978/solr
[junit4:junit4] 2> 615677 T2029 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 615678 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 615685 T2118 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@503b715 name:ZooKeeperConnection Watcher:127.0.0.1:58978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 615686 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 615699 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 615707 T2029 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 615709 T2120 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@71a37b2b name:ZooKeeperConnection Watcher:127.0.0.1:58978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 615709 T2029 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 615720 T2029 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 616385 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 616386 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[junit4:junit4] 2> "numShards":"2",
[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:56504__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56504/_"}
[junit4:junit4] 2> 616425 T2103 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> 616425 T2058 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> 616426 T2071 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> 616426 T2087 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> 616426 T2120 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> 616425 T2051 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> 616723 T2029 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43950__
[junit4:junit4] 2> 616725 T2029 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:43950__
[junit4:junit4] 2> 616727 T2103 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> 616728 T2058 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 616728 T2071 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 616728 T2058 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> 616728 T2120 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 616728 T2051 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 616728 T2087 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 616729 T2051 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> 616729 T2103 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 616729 T2120 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> 616728 T2071 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> 616729 T2087 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> 616743 T2121 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 616743 T2121 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 616744 T2121 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 617300 T2061 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 617300 T2061 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node3&state=recovering&nodeName=127.0.0.1:56504__&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2002
[junit4:junit4] 2> 617931 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 617932 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[junit4:junit4] 2> "numShards":"2",
[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:43950__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43950/_"}
[junit4:junit4] 2> 617933 T2052 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 617933 T2052 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 617962 T2103 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> 617963 T2087 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> 617963 T2120 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> 617963 T2071 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> 617963 T2058 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> 617963 T2051 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> 618747 T2121 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 618747 T2121 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372601004435/collection1
[junit4:junit4] 2> 618747 T2121 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 618748 T2121 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 618748 T2121 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 618750 T2121 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372601004435/collection1/'
[junit4:junit4] 2> 618751 T2121 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372601004435/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 618752 T2121 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372601004435/collection1/lib/README' to classloader
[junit4:junit4] 2> 618809 T2121 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 618867 T2121 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 618969 T2121 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 618974 T2121 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C554 name=collection1 org.apache.solr.core.SolrCore@4e7df1f2 url=http://127.0.0.1:56504/_/collection1 node=127.0.0.1:56504__ C554_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:56504__, base_url=http://127.0.0.1:56504/_}
[junit4:junit4] 2> 619302 T2106 C554 P56504 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39343/_/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 619302 T2106 C554 P56504 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56504/_ START replicas=[http://127.0.0.1:39343/_/collection1/] nUpdates=100
[junit4:junit4] 2> 619303 T2106 C554 P56504 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 619303 T2106 C554 P56504 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 619304 T2106 C554 P56504 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 619304 T2106 C554 P56504 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 619304 T2106 C554 P56504 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 619304 T2106 C554 P56504 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39343/_/collection1/. core=collection1
[junit4:junit4] 2> 619305 T2106 C554 P56504 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C555 name=collection1 org.apache.solr.core.SolrCore@1bb93785 url=http://127.0.0.1:39343/_/collection1 node=127.0.0.1:39343__ C555_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:39343__, base_url=http://127.0.0.1:39343/_, leader=true}
[junit4:junit4] 2> 619312 T2062 C555 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 619318 T2063 C555 P39343 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 619321 T2063 C555 P39343 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 619322 T2063 C555 P39343 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 619322 T2063 C555 P39343 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 619323 T2063 C555 P39343 oass.SolrIndexSearcher.<init> Opening Searcher@5dc5614a realtime
[junit4:junit4] 2> 619323 T2063 C555 P39343 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 619324 T2063 C555 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 619324 T2106 C554 P56504 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 619325 T2106 C554 P56504 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 619327 T2064 C555 P39343 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 619327 T2064 C555 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 619328 T2106 C554 P56504 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 619328 T2106 C554 P56504 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 619329 T2106 C554 P56504 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 619329 T2106 C554 P56504 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 619330 T2106 C554 P56504 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 619467 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 619468 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[junit4:junit4] 2> "numShards":"2",
[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:56504__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56504/_"}
[junit4:junit4] 2> 619482 T2051 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> 619482 T2071 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> 619482 T2087 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> 619482 T2120 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> 619482 T2058 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> 619482 T2103 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> 619554 T2121 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 619566 T2121 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 619570 T2121 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 619585 T2121 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 619589 T2121 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 619593 T2121 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 619594 T2121 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 619595 T2121 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 619595 T2121 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 619596 T2121 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 619596 T2121 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 619597 T2121 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 619597 T2121 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1372601004435/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty4/
[junit4:junit4] 2> 619597 T2121 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3a6f5db5
[junit4:junit4] 2> 619598 T2121 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty4
[junit4:junit4] 2> 619598 T2121 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty4/index/
[junit4:junit4] 2> 619599 T2121 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 619599 T2121 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZkTest-1372600986377/jetty4/index
[junit4:junit4] 2> 619602 T2121 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@36b04dc6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@518fa913),segFN=segments_1,generation=1}
[junit4:junit4] 2> 619603 T2121 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 619605 T2121 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 619606 T2121 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 619606 T2121 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 619607 T2121 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 619608 T2121 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 619608 T2121 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 619609 T2121 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 619609 T2121 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 619610 T2121 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 619625 T2121 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 619631 T2121 oass.SolrIndexSearcher.<init> Opening Searcher@29c472f6 main
[junit4:junit4] 2> 619632 T2121 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 619633 T2121 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 619636 T2123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@29c472f6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 619638 T2121 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 619638 T2121 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:43950/_ collection:collection1 shard:shard2
[junit4:junit4] 2> 619646 T2121 oasc.ZkController.register We are http://127.0.0.1:43950/_/collection1/ and leader is http://127.0.0.1:22984/_/collection1/
[junit4:junit4] 2> 619646 T2121 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:43950/_
[junit4:junit4] 2> 619646 T2121 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 619646 T2121 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C556 name=collection1 org.apache.solr.core.SolrCore@2578c32a url=http://127.0.0.1:43950/_/collection1 node=127.0.0.1:43950__ C556_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:43950__, base_url=http://127.0.0.1:43950/_}
[junit4:junit4] 2> 619647 T2124 C556 P43950 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 619647 T2121 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 619647 T2124 C556 P43950 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 619648 T2124 C556 P43950 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 619648 T2124 C556 P43950 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 619648 T2029 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0
[junit4:junit4] 2> 619649 T2029 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 619650 T2124 C556 P43950 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 619650 T2029 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 619673 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 619674 T2077 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 619675 T2029 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):330
[junit4:junit4] 2> 619676 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 620677 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 620986 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 620987 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[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:43950__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43950/_"}
[junit4:junit4] 2> 621010 T2058 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> 621010 T2103 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> 621010 T2051 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> 621010 T2087 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> 621010 T2120 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> 621010 T2071 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> 621677 T2077 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 621677 T2077 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node4&state=recovering&nodeName=127.0.0.1:43950__&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 621679 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 622681 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C556_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:43950__, base_url=http://127.0.0.1:43950/_}
[junit4:junit4] 2> 623679 T2124 C556 P43950 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:22984/_/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 623679 T2124 C556 P43950 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:43950/_ START replicas=[http://127.0.0.1:22984/_/collection1/] nUpdates=100
[junit4:junit4] 2> 623680 T2124 C556 P43950 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 623680 T2124 C556 P43950 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 623680 T2124 C556 P43950 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 623680 T2124 C556 P43950 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 623680 T2124 C556 P43950 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 623681 T2124 C556 P43950 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:22984/_/collection1/. core=collection1
[junit4:junit4] 2> 623681 T2124 C556 P43950 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 623683 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C557 name=collection1 org.apache.solr.core.SolrCore@42380795 url=http://127.0.0.1:22984/_/collection1 node=127.0.0.1:22984__ C557_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:22984__, base_url=http://127.0.0.1:22984/_, leader=true}
[junit4:junit4] 2> 623688 T2078 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 623692 T2079 C557 P22984 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 623695 T2079 C557 P22984 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b78cae9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@56f299df),segFN=segments_1,generation=1}
[junit4:junit4] 2> 623696 T2079 C557 P22984 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 623696 T2079 C557 P22984 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 623696 T2079 C557 P22984 oass.SolrIndexSearcher.<init> Opening Searcher@8f90f87 realtime
[junit4:junit4] 2> 623697 T2079 C557 P22984 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 623697 T2079 C557 P22984 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 623698 T2124 C556 P43950 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 623698 T2124 C556 P43950 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 623700 T2080 C557 P22984 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 623701 T2080 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 623701 T2124 C556 P43950 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 623702 T2124 C556 P43950 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 623702 T2124 C556 P43950 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 623702 T2124 C556 P43950 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 623706 T2124 C556 P43950 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 624018 T2052 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624019 T2052 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[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:43950__",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:43950/_"}
[junit4:junit4] 2> 624033 T2103 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> 624033 T2087 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> 624033 T2071 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> 624033 T2058 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> 624033 T2120 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> 624033 T2051 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> 624685 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624686 T2029 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C558 name=collection1 org.apache.solr.core.SolrCore@1c694c5a url=http://127.0.0.1:44628/_/collection1 node=127.0.0.1:44628__ C558_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:44628__, base_url=http://127.0.0.1:44628/_, leader=true}
[junit4:junit4] 2> 624698 T2041 C558 P44628 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 624699 T2041 C558 P44628 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 624700 T2041 C558 P44628 oass.SolrIndexSearcher.<init> Opening Searcher@2e331fdd realtime
[junit4:junit4] 2> 624701 T2041 C558 P44628 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439276480716603392)} 0 6
[junit4:junit4] 2> C556_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:43950__, base_url=http://127.0.0.1:43950/_}
[junit4:junit4] 2> 624725 T2110 C556 P43950 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@36b04dc6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@518fa913),segFN=segments_1,generation=1}
[junit4:junit4] 2> 624726 T2110 C556 P43950 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 624728 T2110 C556 P43950 oass.SolrIndexSearcher.<init> Opening Searcher@c9df209 realtime
[junit4:junit4] 2> 624728 T2110 C556 P43950 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={update.distrib=FROMLEADER&_version_=-1439276480734429184&update.from=http://127.0.0.1:22984/_/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439276480734429184)} 0 5
[junit4:junit4] 2> ASYNC NEW_CORE C559 name=collection1 org.apache.solr.core.SolrCore@4e7df1f2 url=http://127.0.0.1:56504/_/collection1 node=127.0.0.1:56504__ C559_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:56504__, base_url=http://127.0.0.1:56504/_}
[junit4:junit4] 2> 624729 T2093 C559 P56504 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_1,generation=1}
[junit4:junit4] 2> 624729 T2093 C559 P56504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 624731 T2093 C559 P56504 oass.SolrIndexSearcher.<init> Opening Searcher@19e3167b realtime
[junit4:junit4] 2> 624731 T2093 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={update.distrib=FROMLEADER&_version_=-1439276480738623488&update.from=http://127.0.0.1:39343/_/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439276480738623488)} 0 4
[junit4:junit4] 2> ASYNC NEW_CORE C560 name=collection1 org.apache.solr.core.SolrCore@1bb93785 url=http://127.0.0.1:39343/_/collection1 node=127.0.0.1:39343__ C560_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:39343__, base_url=http://127.0.0.1:39343/_, leader=true}
[junit4:junit4] 2> 624732 T2065 C560 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1439276480738623488)} 0 16
[junit4:junit4] 2> 624733 T2081 C557 P22984 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439276480734429184)} 0 21
[junit4:junit4] 2> 624734 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624736 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624738 T2066 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624740 T2094 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624741 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624744 T2082 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=1
[junit4:junit4] 2> 624746 T2111 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=*:*&distrib=false&wt=javabin&version=2&sanity_check=is_empty} hits=0 status=0 QTime=1
[junit4:junit4] 2> 624750 T2041 C558 P44628 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624754 T2041 C558 P44628 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_2,generation=2}
[junit4:junit4] 2> 624755 T2041 C558 P44628 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 624756 T2041 C558 P44628 oass.SolrIndexSearcher.<init> Opening Searcher@8d956f9 main
[junit4:junit4] 2> 624757 T2041 C558 P44628 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624758 T2055 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8d956f9 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c1)}
[junit4:junit4] 2> 624758 T2041 C558 P44628 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439276480773226496)],commit=} 0 9
[junit4:junit4] 2> 624766 T2093 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:39343/_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439276480785809408)]} 0 1
[junit4:junit4] 2> 624767 T2066 C560 P39343 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:39343/_/collection1/, StdNode: http://127.0.0.1:56504/_/collection1/, StdNode: http://127.0.0.1:22984/_/collection1/, StdNode: http://127.0.0.1:43950/_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 624769 T2067 C560 P39343 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624769 T2083 C557 P22984 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624769 T2112 C556 P43950 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624770 T2083 C557 P22984 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 624771 T2093 C559 P56504 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624770 T2112 C556 P43950 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 624771 T2083 C557 P22984 oass.SolrIndexSearcher.<init> Opening Searcher@25649404 main
[junit4:junit4] 2> 624772 T2112 C556 P43950 oass.SolrIndexSearcher.<init> Opening Searcher@5419e015 main
[junit4:junit4] 2> 624772 T2083 C557 P22984 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624773 T2112 C556 P43950 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624773 T2067 C560 P39343 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 624773 T2123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5419e015 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 624773 T2089 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@25649404 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 624774 T2067 C560 P39343 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 624775 T2083 C557 P22984 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 624774 T2112 C556 P43950 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 624775 T2093 C559 P56504 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_2,generation=2}
[junit4:junit4] 2> 624776 T2093 C559 P56504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 624776 T2067 C560 P39343 oass.SolrIndexSearcher.<init> Opening Searcher@5b7f3837 main
[junit4:junit4] 2> 624777 T2067 C560 P39343 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624778 T2073 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5b7f3837 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c1)}
[junit4:junit4] 2> 624778 T2093 C559 P56504 oass.SolrIndexSearcher.<init> Opening Searcher@758e5f84 main
[junit4:junit4] 2> 624778 T2067 C560 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 624779 T2093 C559 P56504 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624779 T2105 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@758e5f84 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c1)}
[junit4:junit4] 2> 624780 T2093 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 624780 T2066 C560 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439276480785809408)],commit=} 0 19
[junit4:junit4] 2> 624781 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624783 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624787 T2066 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 624791 T2094 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 624792 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624795 T2082 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624798 T2111 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624800 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624801 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624808 T2113 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601013976&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 624808 T2061 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601013976&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 624811 T2061 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601013976&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 624812 T2066 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8
[junit4:junit4] 2> 624818 T2063 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601013987&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 624818 T2114 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601013987&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624821 T2063 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601013987&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 624822 T2094 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 624823 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624830 T2115 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601013999&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624830 T2139 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601013999&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 624833 T2139 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601013999&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 624834 T2082 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 624840 T2116 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014009&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624840 T2142 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014009&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 624843 T2142 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014009&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 624844 T2111 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 624849 T2041 C558 P44628 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624854 T2041 C558 P44628 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_3,generation=3}
[junit4:junit4] 2> 624854 T2041 C558 P44628 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 624856 T2041 C558 P44628 oass.SolrIndexSearcher.<init> Opening Searcher@2882d88 main
[junit4:junit4] 2> 624857 T2041 C558 P44628 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624857 T2055 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2882d88 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):c1)}
[junit4:junit4] 2> 624858 T2041 C558 P44628 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439276480875986944)],commit=} 0 11
[junit4:junit4] 2> 624871 T2093 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:39343/_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439276480894861312)]} 0 2
[junit4:junit4] 2> 624872 T2065 C560 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:22984/_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439276480894861312)]} 0 8
[junit4:junit4] 2> 624873 T2082 C557 P22984 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:39343/_/collection1/, StdNode: http://127.0.0.1:56504/_/collection1/, StdNode: http://127.0.0.1:22984/_/collection1/, StdNode: http://127.0.0.1:43950/_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 624875 T2095 C559 P56504 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624875 T2077 C557 P22984 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624877 T2077 C557 P22984 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 624877 T2110 C556 P43950 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624877 T2065 C560 P39343 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624878 T2110 C556 P43950 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 624877 T2077 C557 P22984 oass.SolrIndexSearcher.<init> Opening Searcher@146bc0b8 main
[junit4:junit4] 2> 624879 T2110 C556 P43950 oass.SolrIndexSearcher.<init> Opening Searcher@18f59994 main
[junit4:junit4] 2> 624879 T2077 C557 P22984 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624880 T2110 C556 P43950 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624881 T2089 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@146bc0b8 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 624881 T2095 C559 P56504 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_3,generation=3}
[junit4:junit4] 2> 624882 T2077 C557 P22984 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 624881 T2123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@18f59994 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 624882 T2095 C559 P56504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 624883 T2110 C556 P43950 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 624884 T2095 C559 P56504 oass.SolrIndexSearcher.<init> Opening Searcher@278eb611 main
[junit4:junit4] 2> 624885 T2095 C559 P56504 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624886 T2105 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@278eb611 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):c1)}
[junit4:junit4] 2> 624886 T2095 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 624893 T2065 C560 P39343 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_3,generation=3}
[junit4:junit4] 2> 624893 T2065 C560 P39343 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 624895 T2065 C560 P39343 oass.SolrIndexSearcher.<init> Opening Searcher@c71236 main
[junit4:junit4] 2> 624896 T2065 C560 P39343 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624896 T2073 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c71236 main{StandardDirectoryReader(segments_3:7:nrt _1(5.0):c1)}
[junit4:junit4] 2> 624897 T2065 C560 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4] 2> 624898 T2082 C557 P22984 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 37
[junit4:junit4] 2> 624899 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624900 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624905 T2066 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 624909 T2094 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 624910 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624913 T2082 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624916 T2111 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624917 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624919 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624924 T2096 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014094&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 624925 T2113 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014094&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624928 T2096 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014094&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 624929 T2066 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 624935 T2097 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014104&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 624936 T2114 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014104&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 624938 T2097 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014104&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 624939 T2094 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 624941 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624946 T2098 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014116&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 624947 T2115 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014116&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624950 T2098 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014116&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 624951 T2082 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 624956 T2099 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014126&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 624957 T2116 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014126&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 624960 T2099 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014126&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 624961 T2111 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 624966 T2041 C558 P44628 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 624991 T2041 C558 P44628 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_4,generation=4}
[junit4:junit4] 2> 624992 T2041 C558 P44628 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 624994 T2041 C558 P44628 oass.SolrIndexSearcher.<init> Opening Searcher@1d685ac4 main
[junit4:junit4] 2> 624994 T2041 C558 P44628 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 624995 T2055 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d685ac4 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):c1)}
[junit4:junit4] 2> 624996 T2041 C558 P44628 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439276480999718912)],commit=} 0 32
[junit4:junit4] 2> 625010 T2093 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:39343/_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439276481039564800)]} 0 2
[junit4:junit4] 2> 625011 T2146 C560 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:56504/_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439276481039564800)]} 0 9
[junit4:junit4] 2> 625012 T2094 C559 P56504 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:39343/_/collection1/, StdNode: http://127.0.0.1:56504/_/collection1/, StdNode: http://127.0.0.1:22984/_/collection1/, StdNode: http://127.0.0.1:43950/_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 625015 T2150 C559 P56504 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625015 T2079 C557 P22984 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625015 T2151 C556 P43950 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625016 T2079 C557 P22984 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 625015 T2146 C560 P39343 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625017 T2079 C557 P22984 oass.SolrIndexSearcher.<init> Opening Searcher@2cab8084 main
[junit4:junit4] 2> 625016 T2151 C556 P43950 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 625018 T2079 C557 P22984 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625018 T2151 C556 P43950 oass.SolrIndexSearcher.<init> Opening Searcher@2d20e555 main
[junit4:junit4] 2> 625018 T2089 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2cab8084 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 625019 T2151 C556 P43950 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625019 T2079 C557 P22984 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 625020 T2123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d20e555 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 625020 T2150 C559 P56504 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_4,generation=4}
[junit4:junit4] 2> 625020 T2151 C556 P43950 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 625021 T2150 C559 P56504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 625023 T2150 C559 P56504 oass.SolrIndexSearcher.<init> Opening Searcher@5c22166f main
[junit4:junit4] 2> 625024 T2150 C559 P56504 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625024 T2105 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5c22166f main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):c1)}
[junit4:junit4] 2> 625025 T2150 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 625031 T2146 C560 P39343 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_4,generation=4}
[junit4:junit4] 2> 625032 T2146 C560 P39343 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 625034 T2146 C560 P39343 oass.SolrIndexSearcher.<init> Opening Searcher@4d921333 main
[junit4:junit4] 2> 625034 T2146 C560 P39343 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625035 T2073 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4d921333 main{StandardDirectoryReader(segments_4:11:nrt _2(5.0):c1)}
[junit4:junit4] 2> 625035 T2146 C560 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4] 2> 625036 T2094 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 37
[junit4:junit4] 2> 625037 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625039 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625043 T2066 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 625046 T2094 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 625048 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625052 T2082 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 625054 T2111 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 625056 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625057 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625063 T2152 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014232&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 625064 T2061 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014232&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 625067 T2061 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014232&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 625069 T2066 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8
[junit4:junit4] 2> 625075 T2153 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014244&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 625075 T2063 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014244&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 625078 T2063 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014244&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 625079 T2094 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 625080 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625086 T2154 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014256&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 625087 T2139 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014256&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 625090 T2139 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014256&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 625091 T2082 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 625096 T2155 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014266&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 625097 T2142 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014266&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 625100 T2142 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014266&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 625101 T2111 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=7
[junit4:junit4] 2> 625106 T2041 C558 P44628 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625110 T2041 C558 P44628 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7ff48132 lockFactory=org.apache.lucene.store.NativeFSLockFactory@387c18a2),segFN=segments_5,generation=5}
[junit4:junit4] 2> 625111 T2041 C558 P44628 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 625113 T2041 C558 P44628 oass.SolrIndexSearcher.<init> Opening Searcher@17adb1b main
[junit4:junit4] 2> 625113 T2041 C558 P44628 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625114 T2055 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17adb1b main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):c1)}
[junit4:junit4] 2> 625114 T2041 C558 P44628 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={commit=true&wt=javabin&version=2} {add=[1 (1439276481145470976)],commit=} 0 10
[junit4:junit4] 2> 625127 T2093 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:39343/_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439276481162248192)]} 0 3
[junit4:junit4] 2> 625128 T2157 C560 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:43950/_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439276481162248192)]} 0 8
[junit4:junit4] 2> 625128 T2111 C556 P43950 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:39343/_/collection1/, StdNode: http://127.0.0.1:56504/_/collection1/, StdNode: http://127.0.0.1:22984/_/collection1/, StdNode: http://127.0.0.1:43950/_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 625131 T2161 C559 P56504 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625131 T2162 C557 P22984 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625131 T2157 C560 P39343 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625132 T2163 C556 P43950 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 625132 T2162 C557 P22984 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 625133 T2163 C556 P43950 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 625133 T2162 C557 P22984 oass.SolrIndexSearcher.<init> Opening Searcher@2fa60c69 main
[junit4:junit4] 2> 625134 T2163 C556 P43950 oass.SolrIndexSearcher.<init> Opening Searcher@54790d6 main
[junit4:junit4] 2> 625134 T2162 C557 P22984 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625134 T2163 C556 P43950 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625135 T2089 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2fa60c69 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 625135 T2123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54790d6 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 625136 T2162 C557 P22984 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 625136 T2163 C556 P43950 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 625136 T2161 C559 P56504 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d3aa21e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d556987),segFN=segments_5,generation=5}
[junit4:junit4] 2> 625136 T2157 C560 P39343 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f83cfca lockFactory=org.apache.lucene.store.NativeFSLockFactory@33ffbb1b),segFN=segments_5,generation=5}
[junit4:junit4] 2> 625137 T2161 C559 P56504 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 625137 T2157 C560 P39343 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 625139 T2161 C559 P56504 oass.SolrIndexSearcher.<init> Opening Searcher@353bf11 main
[junit4:junit4] 2> 625139 T2157 C560 P39343 oass.SolrIndexSearcher.<init> Opening Searcher@6421b648 main
[junit4:junit4] 2> 625140 T2161 C559 P56504 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625140 T2157 C560 P39343 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 625141 T2073 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6421b648 main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):c1)}
[junit4:junit4] 2> 625140 T2105 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@353bf11 main{StandardDirectoryReader(segments_5:15:nrt _3(5.0):c1)}
[junit4:junit4] 2> 625141 T2157 C560 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 625141 T2161 C559 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 625142 T2111 C556 P43950 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={commit=true&wt=javabin&version=2} {add=[1],commit=} 0 25
[junit4:junit4] 2> 625144 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625145 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625149 T2066 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 625152 T2094 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 625154 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625157 T2082 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 625160 T2111 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&distrib=false&wt=javabin&version=2&sanity_check=non_distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 625161 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625163 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625169 T2096 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014338&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 625169 T2113 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014338&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 625173 T2096 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014338&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 625174 T2066 C560 P39343 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8
[junit4:junit4] 2> 625180 T2114 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014349&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 625180 T2097 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014349&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=0
[junit4:junit4] 2> 625184 T2097 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014349&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 625185 T2094 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8
[junit4:junit4] 2> 625186 T2029 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 625194 T2098 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014362&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 625194 T2115 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014362&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=1
[junit4:junit4] 2> 625197 T2098 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014362&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 625199 T2082 C557 P22984 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=9
[junit4:junit4] 2> 625205 T2116 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014374&shard.url=127.0.0.1:22984/_/collection1/|127.0.0.1:43950/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=0 status=0 QTime=0
[junit4:junit4] 2> 625206 T2099 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014374&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&fl=id,score&start=0&q=id:1&distrib=false&wt=javabin&isShard=true&fsv=true&version=2&rows=10&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=1
[junit4:junit4] 2> 625209 T2099 C559 P56504 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={NOW=1372601014374&shard.url=127.0.0.1:39343/_/collection1/|127.0.0.1:56504/_/collection1/&ids=1&q=id:1&distrib=false&wt=javabin&isShard=true&version=2&sanity_check=distrib_id_1_lookup} status=0 QTime=0
[junit4:junit4] 2> 625210 T2111 C556 P43950 oasc.SolrCore.execute [collection1] webapp=/_ path=/select params={q=id:1&wt=javabin&version=2&sanity_check=distrib_id_1_lookup} hits=1 status=0 QTime=8
[junit4:junit4] 2> 625218 T2041 C558 P44628 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={wt=javabin&version=2} {add=[1 (1439276481261862912)]} 0 4
[junit4:junit4] 2> ASYNC NEW_CORE C561 name=collection1 org.apache.solr.core.SolrCore@4e7df1f2 url=http://127.0.0.1:56504/_/collection1 node=127.0.0.1:56504__ C561_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:56504__, base_url=http://127.0.0.1:56504/_}
[junit4:junit4] 2> 625241 T2093 C561 P56504 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:39343/_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439276481268154368)]} 0 15
[junit4:junit4] 2> ASYNC NEW_CORE C562 name=collection1 org.apache.solr.core.SolrCore@1bb93785 url=http://127.0.0.1:39343/_/collection1 node=127.0.0.1:39343__ C562_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:39343__, base_url=http://127.0.0.1:39343/_, leader=true}
[junit4:junit4] 2> 625242 T2164 C562 P39343 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={wt=javabin&version=2} {add=[1 (1439276481268154368)]} 0 21
[junit4:junit4] 2> ASYNC NEW_CORE C563 name=collection1 org.apache.solr.core.SolrCore@1c694c5a url=http://127.0.0.1:44628/_/collection1 node=127.0.0.1:44628__ C563_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:44628__, base_url=http://127.0.0.1:44628/_, leader=true}
[junit4:junit4] 2> 625247 T2041 C563 P44628 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={wt=javabin&version=2} {add=[2 (1439276481294368768)]} 0 2
[junit4:junit4] 2> ASYNC NEW_CORE C564 name=collection1 org.apache.solr.core.SolrCore@2578c32a url=http://127.0.0.1:43950/_/collection1 node=127.0.0.1:43950__ C564_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:43950__, base_url=http://127.0.0.1:43950/_}
[junit4:junit4] 2> 625262 T2110 C564 P43950 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:22984/_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1439276481300660224)]} 0 4
[junit4:junit4] 2> ASYNC NEW_CORE C565 name=collection1 org.apache.solr.core.SolrCore@42380795 url=http://127.0.0.1:22984/_/collection1 node=127.0.0.1:22984__ C565_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:22984__, base_url=http://127.0.0.1:22984/_, leader=true}
[junit4:junit4] 2> 625263 T2081 C565 P22984 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={wt=javabin&version=2} {add=[2 (1439276481300660224)]} 0 12
[junit4:junit4] 2> 625268 T2041 C563 P44628 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={wt=javabin&version=2} {add=[3 (1439276481316388864)]} 0 2
[junit4:junit4] 2> 625281 T2110 C564 P43950 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={distrib.from=http://127.0.0.1:22984/_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1439276481323728896)]} 0 2
[junit4:junit4] 2> 625282 T2081 C565 P22984 oasup.LogUpdateProcessor.finish [collection1] webapp=/_ path=/update params={wt=javabin&version=2} {add=[3 (1439276481323728896
[...truncated too long message...]
ame=MockRandom), genre_s=PostingsFormat(name=TestBloomFilteredLucene41Postings), author_t=PostingsFormat(name=MockRandom), range_facet_l=Lucene41(blocksize=128), n_ti1=PostingsFormat(name=TestBloomFilteredLucene41Postings), text=Pulsing41(freqCutoff=13 minBlockSize=62 maxBlockSize=203), _version_=PostingsFormat(name=MockRandom), val_i=PostingsFormat(name=TestBloomFilteredLucene41Postings), SubjectTerms_mfacet=PostingsFormat(name=MockRandom), series_t=PostingsFormat(name=MockRandom), a_t=Lucene41(blocksize=128), n_tdt1=PostingsFormat(name=MockRandom), regex_dup_A_s=Pulsing41(freqCutoff=13 minBlockSize=62 maxBlockSize=203), price=Pulsing41(freqCutoff=13 minBlockSize=62 maxBlockSize=203), other_tl1=PostingsFormat(name=MockRandom), n_l1=Lucene41(blocksize=128), a_si=PostingsFormat(name=MockRandom), inStock=Pulsing41(freqCutoff=13 minBlockSize=62 maxBlockSize=203)}, docValues:{timestamp=DocValuesFormat(name=Asserting)}, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=es_US, timezone=Etc/UCT
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=2,free=103674144,total=326696960
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestDynamicFieldCollectionResource, TestDynamicFieldResource, SliceStateUpdateTest, SimpleFacetsTest, SchemaVersionSpecificBehaviorTest, TestGroupingSearch, TermsComponentTest, DistributedTermsComponentTest, DocValuesTest, AlternateDirectoryTest, TestSerializedLuceneMatchVersion, TestCharFilters, TestStressVersions, TestLRUCache, IndexSchemaTest, BadComponentTest, FileBasedSpellCheckerTest, ZkCLITest, TestCopyFieldCollectionResource, ExternalFileFieldSortTest, ClusterStateUpdateTest, DistributedSpellCheckComponentTest, TestCoreContainer, TestPropInjectDefaults, WordBreakSolrSpellCheckerTest, TestSolrIndexConfig, SuggesterTest, TestSolrQueryParserDefaultOperatorResource, ShardRoutingTest, BasicHdfsTest, ScriptEngineTest, TestFieldTypeCollectionResource, TestPluginEnable, SolrInfoMBeanTest, TestFastWriter, TestSurroundQueryParser, FastVectorHighlighterTest, SuggesterFSTTest, AnalysisAfterCoreReloadTest, SOLR749Test, BasicFunctionalityTest, SearchHandlerTest, TestStressRecovery, TestSolrXml, CSVRequestHandlerTest, TestTrie, DateFieldTest, TestQuerySenderListener, TermVectorComponentTest, ResponseLogComponentTest, UpdateRequestProcessorFactoryTest, AliasIntegrationTest, RegexBoostProcessorTest, SynonymTokenizerTest, TestDocumentBuilder, PreAnalyzedFieldTest, PluginInfoTest, TestJoin, BlockDirectoryTest, TestQueryUtils, TestSolrDeletionPolicy2, TestPerFieldSimilarity, StatelessScriptUpdateProcessorFactoryTest, LeaderElectionTest, PeerSyncTest, TestSolrDeletionPolicy1, SoftAutoCommitTest, PreAnalyzedUpdateProcessorTest, LukeRequestHandlerTest, PolyFieldTest, RAMDirectoryFactoryTest, ZkControllerTest, TestPseudoReturnFields, UnloadDistributedZkTest, TestIBSimilarityFactory, TestExtendedDismaxParser, BasicDistributedZkTest]
[junit4:junit4] 2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory.
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=BasicDistributedZkTest -Dtests.seed=32DFD129DBAC725 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/hudson/lucene-data/enwiki.random.lines.txt -Dtests.locale=es_US -Dtests.timezone=Etc/UCT -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 0.00s J0 | BasicDistributedZkTest (suite) <<<
[junit4:junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.BasicDistributedZkTest:
[junit4:junit4] > 1) Thread[id=2512, name=recoveryCmdExecutor-1007-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] > at java.net.PlainSocketImpl.socketConnect(Native Method)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
[junit4:junit4] > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391)
[junit4:junit4] > at java.net.Socket.connect(Socket.java:579)
[junit4:junit4] > at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
[junit4:junit4] > at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
[junit4:junit4] > at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([32DFD129DBAC725]:0)Throwable #2: com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
[junit4:junit4] > 1) Thread[id=2512, name=recoveryCmdExecutor-1007-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] > at java.net.PlainSocketImpl.socketConnect(Native Method)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
[junit4:junit4] > at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
[junit4:junit4] > at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391)
[junit4:junit4] > at java.net.Socket.connect(Socket.java:579)
[junit4:junit4] > at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
[junit4:junit4] > at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
[junit4:junit4] > at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
[junit4:junit4] > at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4:junit4] > at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:297)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([32DFD129DBAC725]:0)
[junit4:junit4] Completed on J0 in 215.15s, 1 test, 2 errors <<< FAILURES!
[...truncated 517 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:393: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build.xml:190: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/common-build.xml:443: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:1245: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:889: There were test failures: 312 suites, 1316 tests, 2 suite-level errors, 710 ignored (1 assumption)
Total time: 87 minutes 31 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-NightlyTests-trunk - Build # 308 - Still
Failing
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-trunk/308/
2 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.BasicDistributedZkTest
Error Message:
1 thread leaked from SUITE scope at org.apache.solr.cloud.BasicDistributedZkTest: 1) Thread[id=2982, name=recoveryCmdExecutor-798-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest] at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391) at java.net.Socket.connect(Socket.java:579) at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127) at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180) at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294) at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645) at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180) at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:291) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:722)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.BasicDistributedZkTest:
1) Thread[id=2982, name=recoveryCmdExecutor-798-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391)
at java.net.Socket.connect(Socket.java:579)
at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:291)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:722)
at __randomizedtesting.SeedInfo.seed([2931CF2C25CF175A]:0)
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.BasicDistributedZkTest
Error Message:
There are still zombie threads that couldn't be terminated: 1) Thread[id=2982, name=recoveryCmdExecutor-798-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest] at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391) at java.net.Socket.connect(Socket.java:579) at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127) at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180) at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294) at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645) at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805) at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365) at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180) at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:291) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:722)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: There are still zombie threads that couldn't be terminated:
1) Thread[id=2982, name=recoveryCmdExecutor-798-thread-1, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:391)
at java.net.Socket.connect(Socket.java:579)
at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:365)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:291)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:722)
at __randomizedtesting.SeedInfo.seed([2931CF2C25CF175A]:0)
Build Log:
[...truncated 39782 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:393: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build.xml:190: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/common-build.xml:443: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:1246: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:890: There were test failures: 313 suites, 1323 tests, 2 suite-level errors, 641 ignored (2 assumptions)
Total time: 80 minutes 48 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
[JENKINS] Lucene-Solr-NightlyTests-trunk - Build # 307 - Still
Failing
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-trunk/307/
1 tests failed.
REGRESSION: org.apache.lucene.index.Test2BPostings.test
Error Message:
Java heap space
Stack Trace:
java.lang.OutOfMemoryError: Java heap space
at __randomizedtesting.SeedInfo.seed([9DBB80D29959B6D6:15EFBF0837A5DB2E]:0)
at org.apache.lucene.util.ByteBlockPool$DirectTrackingAllocator.getByteBlock(ByteBlockPool.java:103)
at org.apache.lucene.util.ByteBlockPool.nextBuffer(ByteBlockPool.java:202)
at org.apache.lucene.util.ByteBlockPool.allocSlice(ByteBlockPool.java:257)
at org.apache.lucene.index.TermsHashPerField.writeByte(TermsHashPerField.java:252)
at org.apache.lucene.index.TermsHashPerField.writeVInt(TermsHashPerField.java:273)
at org.apache.lucene.index.FreqProxTermsWriterPerField.addTerm(FreqProxTermsWriterPerField.java:199)
at org.apache.lucene.index.TermsHashPerField.add(TermsHashPerField.java:235)
at org.apache.lucene.index.DocInverterPerField.processFields(DocInverterPerField.java:165)
at org.apache.lucene.index.DocFieldProcessor.processDocument(DocFieldProcessor.java:210)
at org.apache.lucene.index.DocumentsWriterPerThread.updateDocument(DocumentsWriterPerThread.java:265)
at org.apache.lucene.index.DocumentsWriter.updateDocument(DocumentsWriter.java:432)
at org.apache.lucene.index.IndexWriter.updateDocument(IndexWriter.java:1511)
at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1186)
at org.apache.lucene.index.IndexWriter.addDocument(IndexWriter.java:1167)
at org.apache.lucene.index.Test2BPostings.test(Test2BPostings.java:76)
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:601)
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 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)
Build Log:
[...truncated 1403 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:393: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:366: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/build.xml:49: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:1246: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:890: There were test failures: 356 suites, 2250 tests, 1 error, 45 ignored (32 assumptions)
Total time: 30 minutes 36 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure