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/03/04 20:59:41 UTC
[JENKINS] Lucene-Solr-Tests-trunk-java7 - Build # 3783 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-java7/3783/
2 tests failed.
REGRESSION: org.apache.solr.cloud.BasicDistributedZkTest.testDistribSearch
Error Message:
Test abandoned because suite timeout was reached.
Stack Trace:
java.lang.Exception: Test abandoned because suite timeout was reached.
at __randomizedtesting.SeedInfo.seed([99E9FD5446A87955]:0)
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.BasicDistributedZkTest
Error Message:
Suite timeout exceeded (>= 7200000 msec).
Stack Trace:
java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
at __randomizedtesting.SeedInfo.seed([99E9FD5446A87955]:0)
Build Log:
[...truncated 9689 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZkTest
[junit4:junit4] 2> 0 T1590 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 4 T1590 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZkTest-1362419940665
[junit4:junit4] 2> 5 T1590 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 5 T1591 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 8 T1591 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 8 T1591 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 9 T1591 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 9 T1591 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 10 T1591 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 106 T1590 oasc.ZkTestServer.run start zk server on port:59686
[junit4:junit4] 2> 106 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@7b6dcd8d
[junit4:junit4] 2> 107 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 108 T1596 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 108 T1596 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 109 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59687
[junit4:junit4] 2> 109 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59687
[junit4:junit4] 2> 109 T1594 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 111 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400000 with negotiated timeout 10000 for client /140.211.11.196:59687
[junit4:junit4] 2> 111 T1596 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400000, negotiated timeout = 10000
[junit4:junit4] 2> 112 T1597 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7b6dcd8d name:ZooKeeperConnection Watcher:127.0.0.1:59686 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 112 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 113 T1590 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 116 T1595 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d368e7d400000
[junit4:junit4] 2> 125 T1597 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 125 T1590 oaz.ZooKeeper.close Session: 0x13d368e7d400000 closed
[junit4:junit4] 2> 125 T1592 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:59687 which had sessionid 0x13d368e7d400000
[junit4:junit4] 2> 125 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@3203c2c3
[junit4:junit4] 2> 126 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 127 T1598 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 127 T1598 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 127 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59688
[junit4:junit4] 2> 128 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59688
[junit4:junit4] 2> 129 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400001 with negotiated timeout 10000 for client /140.211.11.196:59688
[junit4:junit4] 2> 129 T1598 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400001, negotiated timeout = 10000
[junit4:junit4] 2> 129 T1599 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3203c2c3 name:ZooKeeperConnection Watcher:127.0.0.1:59686/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 130 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 130 T1590 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 133 T1590 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 142 T1590 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 144 T1590 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 147 T1590 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 148 T1590 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 153 T1590 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 154 T1590 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 257 T1590 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 258 T1590 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 261 T1590 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 261 T1590 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 272 T1590 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 272 T1590 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 275 T1590 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 276 T1590 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 279 T1590 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 280 T1590 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 282 T1590 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 283 T1590 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 290 T1590 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 291 T1590 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 294 T1595 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d368e7d400001
[junit4:junit4] 2> 295 T1599 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 295 T1592 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:59688 which had sessionid 0x13d368e7d400001
[junit4:junit4] 2> 295 T1590 oaz.ZooKeeper.close Session: 0x13d368e7d400001 closed
[junit4:junit4] 2> 482 T1590 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 488 T1590 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:59689
[junit4:junit4] 2> 489 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 489 T1590 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 490 T1590 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1362419940956
[junit4:junit4] 2> 490 T1590 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1362419940956/solr.xml
[junit4:junit4] 2> 491 T1590 oasc.CoreContainer.<init> New CoreContainer 1116044648
[junit4:junit4] 2> 492 T1590 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1362419940956/'
[junit4:junit4] 2> 492 T1590 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1362419940956/'
[junit4:junit4] 2> 555 T1590 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 556 T1590 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 556 T1590 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 556 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 557 T1590 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 557 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 558 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 558 T1590 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 559 T1590 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 559 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 582 T1590 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 602 T1590 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59686/solr
[junit4:junit4] 2> 603 T1590 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 603 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1f57c6e6
[junit4:junit4] 2> 604 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 605 T1609 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 605 T1609 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 606 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59690
[junit4:junit4] 2> 606 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59690
[junit4:junit4] 2> 608 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400002 with negotiated timeout 20000 for client /140.211.11.196:59690
[junit4:junit4] 2> 608 T1609 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400002, negotiated timeout = 20000
[junit4:junit4] 2> 608 T1610 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f57c6e6 name:ZooKeeperConnection Watcher:127.0.0.1:59686 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 609 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 610 T1595 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d368e7d400002
[junit4:junit4] 2> 621 T1610 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 621 T1592 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:59690 which had sessionid 0x13d368e7d400002
[junit4:junit4] 2> 621 T1590 oaz.ZooKeeper.close Session: 0x13d368e7d400002 closed
[junit4:junit4] 2> 621 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 635 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@63ffcb27
[junit4:junit4] 2> 636 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 636 T1611 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 637 T1611 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 637 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59691
[junit4:junit4] 2> 637 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59691
[junit4:junit4] 2> 639 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400003 with negotiated timeout 20000 for client /140.211.11.196:59691
[junit4:junit4] 2> 639 T1611 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400003, negotiated timeout = 20000
[junit4:junit4] 2> 639 T1612 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63ffcb27 name:ZooKeeperConnection Watcher:127.0.0.1:59686/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 639 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 641 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 650 T1590 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 652 T1590 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59689_
[junit4:junit4] 2> 652 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59689_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59689_
[junit4:junit4] 2> 653 T1590 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59689_
[junit4:junit4] 2> 662 T1590 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 675 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:delete cxid:0x16 zxid:0x21 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 676 T1590 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 679 T1590 oasc.Overseer.start Overseer (id=89287553231880195-127.0.0.1:59689_-n_0000000000) starting
[junit4:junit4] 2> 680 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 681 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 691 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 692 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 699 T1614 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 700 T1590 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 709 T1590 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 715 T1615 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1362419940956/collection1
[junit4:junit4] 2> 715 T1613 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 715 T1615 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 716 T1615 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 716 T1615 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 718 T1615 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1362419940956/collection1/'
[junit4:junit4] 2> 719 T1615 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1362419940956/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 719 T1615 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1362419940956/collection1/lib/README' to classloader
[junit4:junit4] 2> 768 T1615 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 827 T1615 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 928 T1615 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 934 T1615 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1570 T1615 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1581 T1615 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1585 T1615 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1601 T1615 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1606 T1615 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1611 T1615 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1612 T1615 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1612 T1615 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1613 T1615 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1614 T1615 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 1614 T1615 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 1614 T1615 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-controljetty-1362419940956/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data/
[junit4:junit4] 2> 1615 T1615 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2482448a
[junit4:junit4] 2> 1615 T1615 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1616 T1615 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data forceNew:false
[junit4:junit4] 2> 1616 T1615 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data
[junit4:junit4] 2> 1617 T1615 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data/index/
[junit4:junit4] 2> 1617 T1615 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1619 T1615 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data/index forceNew:false
[junit4:junit4] 2> 1624 T1615 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620995tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@42addb19),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1625 T1615 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1626 T1615 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data/index
[junit4:junit4] 2> 1628 T1615 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1628 T1615 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1629 T1615 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1629 T1615 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1630 T1615 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1630 T1615 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1631 T1615 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1631 T1615 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1632 T1615 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1644 T1615 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1650 T1615 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data
[junit4:junit4] 2> 1652 T1615 oass.SolrIndexSearcher.<init> Opening Searcher@79a10ada main
[junit4:junit4] 2> 1653 T1615 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data/tlog
[junit4:junit4] 2> 1654 T1615 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1654 T1615 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1658 T1616 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@79a10ada main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1660 T1615 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1660 T1615 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1661 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:create cxid:0x50 zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue Error:KeeperErrorCode = NoNode for /solr/overseer/queue
[junit4:junit4] 2> 2219 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2220 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:59689_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59689"}
[junit4:junit4] 2> 2220 T1613 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2220 T1613 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2221 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:create cxid:0x58 zxid:0x2c txntype:-1 reqpath:n/a Error Path:/solr/overseer/queue-work Error:KeeperErrorCode = NoNode for /solr/overseer/queue-work
[junit4:junit4] 2> 2237 T1612 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> 2676 T1615 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2676 T1615 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59689 collection:control_collection shard:shard1
[junit4:junit4] 2> 2677 T1615 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2692 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:delete cxid:0x72 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4] 2> 2693 T1615 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2694 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2703 T1615 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2704 T1615 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2704 T1615 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59689/collection1/
[junit4:junit4] 2> 2704 T1615 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2705 T1615 oasc.SyncStrategy.syncToMe http://127.0.0.1:59689/collection1/ has no replicas
[junit4:junit4] 2> 2705 T1615 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59689/collection1/
[junit4:junit4] 2> 2705 T1615 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2709 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3741 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3795 T1612 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> 3833 T1615 oasc.ZkController.register We are http://127.0.0.1:59689/collection1/ and leader is http://127.0.0.1:59689/collection1/
[junit4:junit4] 2> 3833 T1615 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59689
[junit4:junit4] 2> 3833 T1615 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3833 T1615 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3834 T1615 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3836 T1615 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3837 T1590 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3837 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3838 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3853 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3854 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@711910d6
[junit4:junit4] 2> 3855 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3855 T1618 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3856 T1618 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 3856 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59692
[junit4:junit4] 2> 3857 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59692
[junit4:junit4] 2> 3858 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400004 with negotiated timeout 10000 for client /140.211.11.196:59692
[junit4:junit4] 2> 3858 T1618 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400004, negotiated timeout = 10000
[junit4:junit4] 2> 3859 T1619 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@711910d6 name:ZooKeeperConnection Watcher:127.0.0.1:59686/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3859 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3860 T1590 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3861 T1590 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 4051 T1590 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 4054 T1590 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:59693
[junit4:junit4] 2> 4055 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 4056 T1590 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 4056 T1590 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1362419944523
[junit4:junit4] 2> 4057 T1590 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1362419944523/solr.xml
[junit4:junit4] 2> 4057 T1590 oasc.CoreContainer.<init> New CoreContainer 530888121
[junit4:junit4] 2> 4058 T1590 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1362419944523/'
[junit4:junit4] 2> 4059 T1590 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1362419944523/'
[junit4:junit4] 2> 4122 T1590 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 4123 T1590 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 4124 T1590 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 4124 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4125 T1590 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4125 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4126 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4126 T1590 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4127 T1590 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4127 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4148 T1590 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4168 T1590 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59686/solr
[junit4:junit4] 2> 4168 T1590 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4169 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@32ac31cf
[junit4:junit4] 2> 4170 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4170 T1629 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4171 T1629 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 4172 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59694
[junit4:junit4] 2> 4172 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59694
[junit4:junit4] 2> 4174 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400005 with negotiated timeout 20000 for client /140.211.11.196:59694
[junit4:junit4] 2> 4174 T1629 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400005, negotiated timeout = 20000
[junit4:junit4] 2> 4174 T1630 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32ac31cf name:ZooKeeperConnection Watcher:127.0.0.1:59686 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4174 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4175 T1595 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d368e7d400005
[junit4:junit4] 2> 4177 T1630 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4177 T1592 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:59694 which had sessionid 0x13d368e7d400005
[junit4:junit4] 2> 4177 T1590 oaz.ZooKeeper.close Session: 0x13d368e7d400005 closed
[junit4:junit4] 2> 4177 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 4189 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@4e0957fa
[junit4:junit4] 2> 4190 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4190 T1631 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4190 T1631 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 4191 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59695
[junit4:junit4] 2> 4191 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59695
[junit4:junit4] 2> 4192 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400006 with negotiated timeout 20000 for client /140.211.11.196:59695
[junit4:junit4] 2> 4192 T1631 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400006, negotiated timeout = 20000
[junit4:junit4] 2> 4193 T1632 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e0957fa name:ZooKeeperConnection Watcher:127.0.0.1:59686/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4193 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4194 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4195 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4203 T1590 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 5206 T1590 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59693_
[junit4:junit4] 2> 5207 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59693_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59693_
[junit4:junit4] 2> 5209 T1590 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59693_
[junit4:junit4] 2> 5211 T1612 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 5211 T1632 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5211 T1619 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5212 T1612 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5230 T1633 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1362419944523/collection1
[junit4:junit4] 2> 5231 T1633 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 5231 T1633 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 5231 T1633 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 5233 T1633 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1362419944523/collection1/'
[junit4:junit4] 2> 5234 T1633 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1362419944523/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 5235 T1633 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1362419944523/collection1/lib/README' to classloader
[junit4:junit4] 2> 5285 T1633 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 5308 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5309 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "node_name":"127.0.0.1:59689_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59689"}
[junit4:junit4] 2> 5322 T1612 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> 5322 T1632 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> 5322 T1619 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> 5346 T1633 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 5446 T1633 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 5452 T1633 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 6079 T1633 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 6091 T1633 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 6095 T1633 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 6115 T1633 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6120 T1633 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6125 T1633 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6126 T1633 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 6126 T1633 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 6126 T1633 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6127 T1633 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 6127 T1633 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 6128 T1633 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty1-1362419944523/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1/
[junit4:junit4] 2> 6128 T1633 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2482448a
[junit4:junit4] 2> 6129 T1633 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 6129 T1633 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1 forceNew:false
[junit4:junit4] 2> 6130 T1633 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1
[junit4:junit4] 2> 6130 T1633 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1/index/
[junit4:junit4] 2> 6131 T1633 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 6132 T1633 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1/index forceNew:false
[junit4:junit4] 2> 6177 T1633 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620996tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@58f99e45),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 6177 T1633 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 6178 T1633 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1/index
[junit4:junit4] 2> 6181 T1633 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 6181 T1633 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 6182 T1633 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 6182 T1633 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 6183 T1633 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 6183 T1633 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 6184 T1633 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 6184 T1633 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 6185 T1633 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 6197 T1633 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 6203 T1633 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1
[junit4:junit4] 2> 6205 T1633 oass.SolrIndexSearcher.<init> Opening Searcher@499e072f main
[junit4:junit4] 2> 6205 T1633 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1/tlog
[junit4:junit4] 2> 6206 T1633 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 6206 T1633 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 6212 T1634 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@499e072f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 6214 T1633 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 6215 T1633 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6826 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6827 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59693_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59693"}
[junit4:junit4] 2> 6827 T1613 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 6828 T1613 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6870 T1619 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> 6870 T1632 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> 6870 T1612 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> 7250 T1633 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7250 T1633 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59693 collection:collection1 shard:shard1
[junit4:junit4] 2> 7251 T1633 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7271 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400006 type:delete cxid:0x46 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7272 T1633 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7273 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400006 type:create cxid:0x47 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7274 T1633 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7275 T1633 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7275 T1633 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59693/collection1/
[junit4:junit4] 2> 7275 T1633 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7276 T1633 oasc.SyncStrategy.syncToMe http://127.0.0.1:59693/collection1/ has no replicas
[junit4:junit4] 2> 7276 T1633 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59693/collection1/
[junit4:junit4] 2> 7276 T1633 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7289 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400006 type:create cxid:0x51 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8374 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8397 T1632 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> 8397 T1612 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> 8397 T1619 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> 8420 T1633 oasc.ZkController.register We are http://127.0.0.1:59693/collection1/ and leader is http://127.0.0.1:59693/collection1/
[junit4:junit4] 2> 8420 T1633 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59693
[junit4:junit4] 2> 8420 T1633 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8420 T1633 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8421 T1633 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8423 T1633 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8424 T1590 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 8424 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8425 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8632 T1590 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8636 T1590 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:59698
[junit4:junit4] 2> 8636 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8637 T1590 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8637 T1590 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1362419949102
[junit4:junit4] 2> 8638 T1590 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1362419949102/solr.xml
[junit4:junit4] 2> 8638 T1590 oasc.CoreContainer.<init> New CoreContainer 298982835
[junit4:junit4] 2> 8639 T1590 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1362419949102/'
[junit4:junit4] 2> 8640 T1590 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1362419949102/'
[junit4:junit4] 2> 8703 T1590 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8703 T1590 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8704 T1590 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8704 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8705 T1590 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8705 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8706 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8706 T1590 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8707 T1590 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8707 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8730 T1590 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8750 T1590 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59686/solr
[junit4:junit4] 2> 8751 T1590 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8751 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@7d9787db
[junit4:junit4] 2> 8752 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8753 T1645 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8754 T1645 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 8754 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59699
[junit4:junit4] 2> 8754 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59699
[junit4:junit4] 2> 8756 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400007 with negotiated timeout 20000 for client /140.211.11.196:59699
[junit4:junit4] 2> 8756 T1645 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400007, negotiated timeout = 20000
[junit4:junit4] 2> 8756 T1646 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d9787db name:ZooKeeperConnection Watcher:127.0.0.1:59686 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8757 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8758 T1595 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d368e7d400007
[junit4:junit4] 2> 8768 T1646 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8768 T1592 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:59699 which had sessionid 0x13d368e7d400007
[junit4:junit4] 2> 8768 T1590 oaz.ZooKeeper.close Session: 0x13d368e7d400007 closed
[junit4:junit4] 2> 8769 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8782 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@529edfce
[junit4:junit4] 2> 8783 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8783 T1647 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8784 T1647 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 8784 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59700
[junit4:junit4] 2> 8784 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59700
[junit4:junit4] 2> 8786 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400008 with negotiated timeout 20000 for client /140.211.11.196:59700
[junit4:junit4] 2> 8786 T1647 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400008, negotiated timeout = 20000
[junit4:junit4] 2> 8786 T1648 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@529edfce name:ZooKeeperConnection Watcher:127.0.0.1:59686/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8786 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8787 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8789 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8797 T1590 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9799 T1590 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59698_
[junit4:junit4] 2> 9800 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400008 type:delete cxid:0x9 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59698_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59698_
[junit4:junit4] 2> 9801 T1590 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59698_
[junit4:junit4] 2> 9804 T1632 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> 9804 T1612 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> 9804 T1619 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9804 T1648 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9804 T1619 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> 9805 T1612 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9805 T1632 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9825 T1649 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1362419949102/collection1
[junit4:junit4] 2> 9825 T1649 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9826 T1649 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9826 T1649 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9827 T1649 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1362419949102/collection1/'
[junit4:junit4] 2> 9828 T1649 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1362419949102/collection1/lib/README' to classloader
[junit4:junit4] 2> 9829 T1649 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1362419949102/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9879 T1649 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 9903 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9904 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59693_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59693"}
[junit4:junit4] 2> 9917 T1632 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> 9917 T1612 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> 9917 T1648 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> 9917 T1619 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> 9940 T1649 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 10041 T1649 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 10047 T1649 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 10644 T1649 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 10651 T1649 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 10654 T1649 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 10667 T1649 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10671 T1649 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10674 T1649 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10675 T1649 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 10675 T1649 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 10675 T1649 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10676 T1649 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 10676 T1649 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 10676 T1649 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty2-1362419949102/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2/
[junit4:junit4] 2> 10676 T1649 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2482448a
[junit4:junit4] 2> 10677 T1649 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 10678 T1649 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2 forceNew:false
[junit4:junit4] 2> 10678 T1649 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2
[junit4:junit4] 2> 10678 T1649 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2/index/
[junit4:junit4] 2> 10678 T1649 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 10679 T1649 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2/index forceNew:false
[junit4:junit4] 2> 10683 T1649 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620997tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@3822f963),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 10683 T1649 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 10684 T1649 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2/index
[junit4:junit4] 2> 10686 T1649 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 10686 T1649 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 10687 T1649 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 10687 T1649 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 10688 T1649 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 10688 T1649 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 10688 T1649 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 10689 T1649 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 10689 T1649 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 10697 T1649 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 10701 T1649 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2
[junit4:junit4] 2> 10702 T1649 oass.SolrIndexSearcher.<init> Opening Searcher@504abe40 main
[junit4:junit4] 2> 10703 T1649 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2/tlog
[junit4:junit4] 2> 10703 T1649 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 10703 T1649 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 10707 T1650 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@504abe40 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 10709 T1649 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10709 T1649 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11421 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11422 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59698_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59698"}
[junit4:junit4] 2> 11422 T1613 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 11422 T1613 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 11430 T1612 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> 11430 T1619 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> 11430 T1648 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> 11430 T1632 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> 11711 T1649 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11711 T1649 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59698 collection:collection1 shard:shard2
[junit4:junit4] 2> 11712 T1649 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 11728 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400008 type:delete cxid:0x45 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4] 2> 11729 T1649 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 11730 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400008 type:create cxid:0x46 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11737 T1649 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 11737 T1649 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 11737 T1649 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59698/collection1/
[junit4:junit4] 2> 11738 T1649 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 11738 T1649 oasc.SyncStrategy.syncToMe http://127.0.0.1:59698/collection1/ has no replicas
[junit4:junit4] 2> 11738 T1649 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59698/collection1/
[junit4:junit4] 2> 11738 T1649 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 11741 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d400008 type:create cxid:0x4f zxid:0x82 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12948 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12966 T1619 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> 12966 T1612 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> 12966 T1632 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> 12966 T1648 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> 12976 T1649 oasc.ZkController.register We are http://127.0.0.1:59698/collection1/ and leader is http://127.0.0.1:59698/collection1/
[junit4:junit4] 2> 12976 T1649 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59698
[junit4:junit4] 2> 12976 T1649 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 12976 T1649 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 12977 T1649 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12979 T1649 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12980 T1590 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 12981 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 12981 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 13185 T1590 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 13189 T1590 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:59701
[junit4:junit4] 2> 13190 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 13190 T1590 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 13191 T1590 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1362419953657
[junit4:junit4] 2> 13191 T1590 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1362419953657/solr.xml
[junit4:junit4] 2> 13192 T1590 oasc.CoreContainer.<init> New CoreContainer 747283516
[junit4:junit4] 2> 13192 T1590 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1362419953657/'
[junit4:junit4] 2> 13193 T1590 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1362419953657/'
[junit4:junit4] 2> 13255 T1590 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 13256 T1590 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 13257 T1590 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 13257 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 13258 T1590 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 13258 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 13259 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 13259 T1590 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 13260 T1590 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 13260 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 13281 T1590 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 13301 T1590 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59686/solr
[junit4:junit4] 2> 13301 T1590 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 13302 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@18f3383b
[junit4:junit4] 2> 13303 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13303 T1661 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 13304 T1661 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 13304 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59702
[junit4:junit4] 2> 13305 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59702
[junit4:junit4] 2> 13342 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d400009 with negotiated timeout 20000 for client /140.211.11.196:59702
[junit4:junit4] 2> 13342 T1661 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d400009, negotiated timeout = 20000
[junit4:junit4] 2> 13343 T1662 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18f3383b name:ZooKeeperConnection Watcher:127.0.0.1:59686 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13343 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13344 T1595 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d368e7d400009
[junit4:junit4] 2> 13346 T1662 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 13346 T1592 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:59702 which had sessionid 0x13d368e7d400009
[junit4:junit4] 2> 13346 T1590 oaz.ZooKeeper.close Session: 0x13d368e7d400009 closed
[junit4:junit4] 2> 13346 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 13357 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@636fee1a
[junit4:junit4] 2> 13358 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 13359 T1663 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 13359 T1663 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 13359 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59703
[junit4:junit4] 2> 13360 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59703
[junit4:junit4] 2> 13361 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d40000a with negotiated timeout 20000 for client /140.211.11.196:59703
[junit4:junit4] 2> 13361 T1663 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d40000a, negotiated timeout = 20000
[junit4:junit4] 2> 13362 T1664 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@636fee1a name:ZooKeeperConnection Watcher:127.0.0.1:59686/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 13362 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 13363 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d40000a type:create cxid:0x1 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13364 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d40000a type:create cxid:0x2 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 13366 T1590 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 14369 T1590 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59701_
[junit4:junit4] 2> 14370 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d40000a type:delete cxid:0x9 zxid:0x91 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59701_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59701_
[junit4:junit4] 2> 14371 T1590 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59701_
[junit4:junit4] 2> 14374 T1612 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> 14374 T1632 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> 14374 T1664 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14374 T1648 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> 14374 T1619 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14375 T1619 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> 14375 T1612 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14389 T1632 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14389 T1648 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 14395 T1665 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1362419953657/collection1
[junit4:junit4] 2> 14395 T1665 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 14395 T1665 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 14396 T1665 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 14397 T1665 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1362419953657/collection1/'
[junit4:junit4] 2> 14398 T1665 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1362419953657/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 14399 T1665 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1362419953657/collection1/lib/README' to classloader
[junit4:junit4] 2> 14448 T1665 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 14480 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14481 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59698_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59698"}
[junit4:junit4] 2> 14495 T1612 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> 14495 T1632 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> 14495 T1664 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> 14495 T1648 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> 14495 T1619 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> 14507 T1665 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 14608 T1665 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 14614 T1665 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 15229 T1665 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 15239 T1665 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 15243 T1665 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 15258 T1665 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 15262 T1665 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 15267 T1665 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 15268 T1665 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 15268 T1665 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 15268 T1665 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 15269 T1665 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 15269 T1665 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 15270 T1665 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty3-1362419953657/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/
[junit4:junit4] 2> 15270 T1665 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2482448a
[junit4:junit4] 2> 15271 T1665 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 15272 T1665 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3 forceNew:false
[junit4:junit4] 2> 15272 T1665 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3
[junit4:junit4] 2> 15273 T1665 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/index/
[junit4:junit4] 2> 15273 T1665 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 15274 T1665 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/index forceNew:false
[junit4:junit4] 2> 15279 T1665 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620998tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@46c92c4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 15280 T1665 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 15280 T1665 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/index
[junit4:junit4] 2> 15283 T1665 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 15283 T1665 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 15284 T1665 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 15285 T1665 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 15285 T1665 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 15286 T1665 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 15286 T1665 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 15287 T1665 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 15287 T1665 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 15299 T1665 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 15304 T1665 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3
[junit4:junit4] 2> 15306 T1665 oass.SolrIndexSearcher.<init> Opening Searcher@62f0bcfa main
[junit4:junit4] 2> 15306 T1665 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/tlog
[junit4:junit4] 2> 15307 T1665 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 15308 T1665 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 15313 T1666 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@62f0bcfa main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 15315 T1665 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 15315 T1665 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15999 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16000 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59701_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59701"}
[junit4:junit4] 2> 16000 T1613 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 16000 T1613 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 16004 T1612 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> 16004 T1664 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> 16004 T1648 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> 16004 T1619 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> 16004 T1632 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> 16318 T1665 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 16318 T1665 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59701 collection:collection1 shard:shard1
[junit4:junit4] 2> 16322 T1665 oasc.ZkController.register We are http://127.0.0.1:59701/collection1/ and leader is http://127.0.0.1:59693/collection1/
[junit4:junit4] 2> 16322 T1665 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59701
[junit4:junit4] 2> 16322 T1665 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 16322 T1665 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C90 name=collection1 org.apache.solr.core.SolrCore@7d74af00 url=http://127.0.0.1:59701/collection1 node=127.0.0.1:59701_ C90_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:59701_, base_url=http://127.0.0.1:59701}
[junit4:junit4] 2> 16323 T1667 C90 P59701 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 16323 T1665 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16323 T1667 C90 P59701 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 16324 T1667 C90 P59701 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 16324 T1667 C90 P59701 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16324 T1590 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 16325 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 16326 T1667 C90 P59701 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16326 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16538 T1590 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 16541 T1590 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:59705
[junit4:junit4] 2> 16542 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 16542 T1590 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 16543 T1590 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1362419957004
[junit4:junit4] 2> 16543 T1590 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1362419957004/solr.xml
[junit4:junit4] 2> 16544 T1590 oasc.CoreContainer.<init> New CoreContainer 667436473
[junit4:junit4] 2> 16545 T1590 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1362419957004/'
[junit4:junit4] 2> 16545 T1590 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1362419957004/'
[junit4:junit4] 2> 16608 T1590 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 16608 T1590 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 16609 T1590 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 16609 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 16610 T1590 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 16610 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 16611 T1590 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 16611 T1590 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 16612 T1590 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 16612 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 16635 T1590 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 16655 T1590 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:59686/solr
[junit4:junit4] 2> 16655 T1590 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 16656 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@3220a131
[junit4:junit4] 2> 16657 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 16657 T1678 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 16659 T1678 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 16659 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59706
[junit4:junit4] 2> 16659 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59706
[junit4:junit4] 2> 16667 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d40000b with negotiated timeout 20000 for client /140.211.11.196:59706
[junit4:junit4] 2> 16667 T1678 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d40000b, negotiated timeout = 20000
[junit4:junit4] 2> 16668 T1679 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3220a131 name:ZooKeeperConnection Watcher:127.0.0.1:59686 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 16668 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 16669 T1595 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d368e7d40000b
[junit4:junit4] 2> 16682 T1679 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 16682 T1592 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:59706 which had sessionid 0x13d368e7d40000b
[junit4:junit4] 2> 16682 T1590 oaz.ZooKeeper.close Session: 0x13d368e7d40000b closed
[junit4:junit4] 2> 16683 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 16696 T1590 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:59686/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@7184242a
[junit4:junit4] 2> 16697 T1590 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 16697 T1680 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:59686. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 16698 T1680 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:59686, initiating session
[junit4:junit4] 2> 16698 T1592 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:59707
[junit4:junit4] 2> 16698 T1592 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:59707
[junit4:junit4] 2> 16725 T1594 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d368e7d40000c with negotiated timeout 20000 for client /140.211.11.196:59707
[junit4:junit4] 2> 16726 T1680 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:59686, sessionid = 0x13d368e7d40000c, negotiated timeout = 20000
[junit4:junit4] 2> 16726 T1681 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7184242a name:ZooKeeperConnection Watcher:127.0.0.1:59686/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 16726 T1590 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 16727 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d40000c type:create cxid:0x1 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 16753 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d40000c type:create cxid:0x2 zxid:0xa3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 16780 T1590 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 17521 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17522 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59701_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59701"}
[junit4:junit4] 2> 17563 T1632 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> 17563 T1664 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> 17563 T1648 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> 17563 T1681 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> 17563 T1619 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> 17563 T1612 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> 17783 T1590 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59705_
[junit4:junit4] 2> 17784 T1595 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d368e7d40000c type:delete cxid:0xb zxid:0xa8 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:59705_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:59705_
[junit4:junit4] 2> 17785 T1590 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59705_
[junit4:junit4] 2> 17787 T1632 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> 17788 T1612 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> 17788 T1619 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17787 T1664 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> 17787 T1648 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> 17787 T1681 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> 17788 T1619 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> 17789 T1632 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17799 T1612 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17800 T1664 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17800 T1648 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17800 T1681 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 17805 T1682 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1362419957004/collection1
[junit4:junit4] 2> 17805 T1682 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 17806 T1682 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 17806 T1682 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 17807 T1682 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1362419957004/collection1/'
[junit4:junit4] 2> 17809 T1682 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1362419957004/collection1/lib/README' to classloader
[junit4:junit4] 2> 17809 T1682 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1362419957004/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 17859 T1682 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 17918 T1682 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 18019 T1682 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 18025 T1682 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 18639 T1682 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 18647 T1682 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 18649 T1682 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 18662 T1682 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 18665 T1682 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 18669 T1682 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 18670 T1682 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 18670 T1682 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 18670 T1682 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 18671 T1682 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 18671 T1682 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 18671 T1682 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-jetty4-1362419957004/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/
[junit4:junit4] 2> 18672 T1682 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2482448a
[junit4:junit4] 2> 18672 T1682 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 18673 T1682 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4 forceNew:false
[junit4:junit4] 2> 18673 T1682 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4
[junit4:junit4] 2> 18673 T1682 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/index/
[junit4:junit4] 2> 18673 T1682 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 18674 T1682 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/index forceNew:false
[junit4:junit4] 2> 18678 T1682 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620999tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ef552b6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 18679 T1682 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 18679 T1682 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/index
[junit4:junit4] 2> 18681 T1682 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 18681 T1682 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 18682 T1682 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 18682 T1682 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 18683 T1682 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 18683 T1682 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 18683 T1682 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 18684 T1682 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 18684 T1682 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 18692 T1682 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 18696 T1682 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4
[junit4:junit4] 2> 18697 T1682 oass.SolrIndexSearcher.<init> Opening Searcher@38f3160a main
[junit4:junit4] 2> 18698 T1682 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/tlog
[junit4:junit4] 2> 18698 T1682 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 18699 T1682 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 18702 T1683 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@38f3160a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 18704 T1682 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 18704 T1682 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 19068 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19068 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59705_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59705"}
[junit4:junit4] 2> 19068 T1613 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 19069 T1613 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 19072 T1612 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> 19072 T1619 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> 19072 T1681 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> 19072 T1648 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> 19072 T1632 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> 19072 T1664 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> 19707 T1682 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 19707 T1682 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59705 collection:collection1 shard:shard2
[junit4:junit4] 2> 19710 T1682 oasc.ZkController.register We are http://127.0.0.1:59705/collection1/ and leader is http://127.0.0.1:59698/collection1/
[junit4:junit4] 2> 19711 T1682 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59705
[junit4:junit4] 2> 19711 T1682 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 19711 T1682 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C91 name=collection1 org.apache.solr.core.SolrCore@b1b0ff7 url=http://127.0.0.1:59705/collection1 node=127.0.0.1:59705_ C91_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:59705_, base_url=http://127.0.0.1:59705}
[junit4:junit4] 2> 19712 T1684 C91 P59705 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 19712 T1682 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19712 T1684 C91 P59705 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 19713 T1684 C91 P59705 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 19713 T1684 C91 P59705 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 19713 T1590 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 19714 T1590 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 19715 T1590 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 19731 T1684 C91 P59705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 19731 T1590 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19733 T1590 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 19733 T1590 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C90_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59701_, base_url=http://127.0.0.1:59701}
[junit4:junit4] 2> 20348 T1667 C90 P59701 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:59693/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 20348 T1667 C90 P59701 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59701 START replicas=[http://127.0.0.1:59693/collection1/] nUpdates=100
[junit4:junit4] 2> 20349 T1667 C90 P59701 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 20349 T1667 C90 P59701 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 20349 T1667 C90 P59701 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 20349 T1667 C90 P59701 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 20350 T1667 C90 P59701 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 20350 T1667 C90 P59701 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:59693/collection1/. core=collection1
[junit4:junit4] 2> 20350 T1667 C90 P59701 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C92 name=collection1 org.apache.solr.core.SolrCore@609af6c5 url=http://127.0.0.1:59693/collection1 node=127.0.0.1:59693_ C92_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:59693_, base_url=http://127.0.0.1:59693, leader=true}
[junit4:junit4] 2> 20357 T1623 C92 P59693 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 20363 T1624 C92 P59693 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 20363 T1624 C92 P59693 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1
[junit4:junit4] 2> 20368 T1624 C92 P59693 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620996tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@58f99e45),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 20368 T1624 C92 P59693 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 20371 T1624 C92 P59693 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620996tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@58f99e45),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620996tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@58f99e45),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 20372 T1624 C92 P59693 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 20373 T1624 C92 P59693 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1
[junit4:junit4] 2> 20373 T1624 C92 P59693 oass.SolrIndexSearcher.<init> Opening Searcher@7dcc779c realtime
[junit4:junit4] 2> 20374 T1624 C92 P59693 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 20374 T1624 C92 P59693 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 20375 T1667 C90 P59701 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 20375 T1667 C90 P59701 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 20378 T1625 C92 P59693 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 20378 T1625 C92 P59693 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 20379 T1667 C90 P59701 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 20379 T1667 C90 P59701 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 20380 T1667 C90 P59701 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 20382 T1625 C92 P59693 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1
[junit4:junit4] 2> 20383 T1625 C92 P59693 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1/index
[junit4:junit4] 2> 20383 T1625 C92 P59693 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 20384 T1667 C90 P59701 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 20385 T1667 C90 P59701 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/index.20130304135921045 forceNew:false
[junit4:junit4] 2> 20386 T1667 C90 P59701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3
[junit4:junit4] 2> 20386 T1667 C90 P59701 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d0152cf lockFactory=org.apache.lucene.store.NativeFSLockFactory@6c121f86) fullCopy=false
[junit4:junit4] 2> 20389 T1625 C92 P59693 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 20391 T1667 C90 P59701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/index
[junit4:junit4] 2> 20391 T1667 C90 P59701 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 20392 T1667 C90 P59701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3
[junit4:junit4] 2> 20393 T1667 C90 P59701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3
[junit4:junit4] 2> 20393 T1667 C90 P59701 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 20393 T1667 C90 P59701 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 20394 T1667 C90 P59701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3
[junit4:junit4] 2> 20397 T1667 C90 P59701 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620998tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@46c92c4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620998tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@46c92c4),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 20398 T1667 C90 P59701 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 20398 T1667 C90 P59701 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 20399 T1667 C90 P59701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3
[junit4:junit4] 2> 20399 T1667 C90 P59701 oass.SolrIndexSearcher.<init> Opening Searcher@36181632 main
[junit4:junit4] 2> 20400 T1666 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@36181632 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 20401 T1666 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/index
[junit4:junit4] 2> 20401 T1667 C90 P59701 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@3d0152cf lockFactory=org.apache.lucene.store.NativeFSLockFactory@6c121f86)
[junit4:junit4] 2> 20401 T1667 C90 P59701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/index.20130304135921045
[junit4:junit4] 2> 20402 T1667 C90 P59701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3/index
[junit4:junit4] 2> 20402 T1667 C90 P59701 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 20402 T1667 C90 P59701 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 20402 T1667 C90 P59701 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 20403 T1667 C90 P59701 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 20404 T1667 C90 P59701 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 20576 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20577 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59705_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59705"}
[junit4:junit4] 2> 20580 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59701_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59701"}
[junit4:junit4] 2> 20594 T1664 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> 20594 T1681 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> 20594 T1619 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> 20594 T1632 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> 20594 T1612 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> 20594 T1648 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> 20735 T1590 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21737 T1590 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22739 T1590 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C91_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:59705_, base_url=http://127.0.0.1:59705}
[junit4:junit4] 2> 22745 T1684 C91 P59705 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:59698/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 22745 T1684 C91 P59705 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:59705 START replicas=[http://127.0.0.1:59698/collection1/] nUpdates=100
[junit4:junit4] 2> 22746 T1684 C91 P59705 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 22746 T1684 C91 P59705 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 22746 T1684 C91 P59705 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 22746 T1684 C91 P59705 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 22747 T1684 C91 P59705 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 22747 T1684 C91 P59705 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:59698/collection1/. core=collection1
[junit4:junit4] 2> 22747 T1684 C91 P59705 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C93 name=collection1 org.apache.solr.core.SolrCore@3ab07463 url=http://127.0.0.1:59698/collection1 node=127.0.0.1:59698_ C93_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:59698_, base_url=http://127.0.0.1:59698, leader=true}
[junit4:junit4] 2> 22757 T1639 C93 P59698 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 22765 T1640 C93 P59698 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22766 T1640 C93 P59698 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2
[junit4:junit4] 2> 22770 T1640 C93 P59698 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620997tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@3822f963),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 22770 T1640 C93 P59698 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 22774 T1640 C93 P59698 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620997tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@3822f963),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620997tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@3822f963),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22774 T1640 C93 P59698 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22775 T1640 C93 P59698 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2
[junit4:junit4] 2> 22775 T1640 C93 P59698 oass.SolrIndexSearcher.<init> Opening Searcher@68de70f6 realtime
[junit4:junit4] 2> 22776 T1640 C93 P59698 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22776 T1640 C93 P59698 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 11
[junit4:junit4] 2> 22777 T1684 C91 P59705 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 22778 T1684 C91 P59705 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 22779 T1641 C93 P59698 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 22780 T1641 C93 P59698 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 22781 T1684 C91 P59705 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 22781 T1684 C91 P59705 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 22781 T1684 C91 P59705 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 22783 T1641 C93 P59698 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2
[junit4:junit4] 2> 22784 T1641 C93 P59698 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2/index
[junit4:junit4] 2> 22784 T1641 C93 P59698 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 22785 T1684 C91 P59705 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 22786 T1684 C91 P59705 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/index.20130304135923447 forceNew:false
[junit4:junit4] 2> 22787 T1684 C91 P59705 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4
[junit4:junit4] 2> 22787 T1684 C91 P59705 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c14be93 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6db36b4a) fullCopy=false
[junit4:junit4] 2> 22790 T1641 C93 P59698 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 22792 T1684 C91 P59705 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/index
[junit4:junit4] 2> 22792 T1684 C91 P59705 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 22793 T1684 C91 P59705 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4
[junit4:junit4] 2> 22794 T1684 C91 P59705 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4
[junit4:junit4] 2> 22794 T1684 C91 P59705 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 22794 T1684 C91 P59705 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 22795 T1684 C91 P59705 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4
[junit4:junit4] 2> 22798 T1684 C91 P59705 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620999tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ef552b6),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620999tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ef552b6),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22799 T1684 C91 P59705 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22799 T1684 C91 P59705 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 22800 T1684 C91 P59705 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4
[junit4:junit4] 2> 22800 T1684 C91 P59705 oass.SolrIndexSearcher.<init> Opening Searcher@2650af6e main
[junit4:junit4] 2> 22801 T1683 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2650af6e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22802 T1683 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/index
[junit4:junit4] 2> 22802 T1684 C91 P59705 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.RAMDirectory@5c14be93 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6db36b4a)
[junit4:junit4] 2> 22802 T1684 C91 P59705 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/index.20130304135923447
[junit4:junit4] 2> 22803 T1684 C91 P59705 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4/index
[junit4:junit4] 2> 22803 T1684 C91 P59705 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 22803 T1684 C91 P59705 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 22803 T1684 C91 P59705 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 22803 T1684 C91 P59705 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 22805 T1684 C91 P59705 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 23611 T1613 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 23612 T1613 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:59705_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59705"}
[junit4:junit4] 2> 23626 T1612 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> 23626 T1681 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> 23626 T1648 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> 23626 T1632 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> 23626 T1619 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> 23626 T1664 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> 23741 T1590 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 23742 T1590 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C94 name=collection1 org.apache.solr.core.SolrCore@2c5737e0 url=http://127.0.0.1:59689/collection1 node=127.0.0.1:59689_ C94_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:59689_, base_url=http://127.0.0.1:59689, leader=true}
[junit4:junit4] 2> 23757 T1602 C94 P59689 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data
[junit4:junit4] 2> 23762 T1602 C94 P59689 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.NIOFSDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/index2098620995tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@42addb19),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 23762 T1602 C94 P59689 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 23764 T1602 C94 P59689 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/control/data
[junit4:junit4] 2> 23764 T1602 C94 P59689 oass.SolrIndexSearcher.<init> Opening Searcher@b16d234 realtime
[junit4:junit4] 2> 23765 T1602 C94 P59689 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1428600876608520192)} 0 13
[junit4:junit4] 2> 23790 T1626 C92 P59693 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty1
[junit4:junit4] 2> 23795 T1642 C93 P59698 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty2
[junit4:junit4] 2> C90_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:59701_, base_url=http://127.0.0.1:59701}
[junit4:junit4] 2> 23801 T1654 C90 P59701 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty3
[junit4:junit4] 2> 23802 T1654 C90 P59701 /update {update.distrib=FROMLEADER&_version_=-1428600876642074624&update.from=http://127.0.0.1:59693/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1428600876642074624)} 0 2
[junit4:junit4] 2> C91_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:59705_, base_url=http://127.0.0.1:59705}
[junit4:junit4] 2> 23805 T1671 C91 P59705 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZkTest-1362419940665/jetty4
[junit4:junit4] 2> 23806 T1671 C91 P59705 /update {update.distrib=FROMLEADER&_version_=-1428600876648366080&update.from=http://127.0.0.1:59698/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1428600876648366080)} 0 3
[junit4:junit4] 2> 23807 T1642 C93 P59698 /update {update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1428600876648366080)} 0 13
[junit4:junit4] 2> 23808 T1626 C92 P59693 /update {wt=javabin&version=2} {deleteByQuery=*:* (-1428600876642074624)} 0 20
[junit4:junit4] 2> 23815 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[1 (1428600876667240448)]} 0 4
[junit4:junit4] 2> 23828 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1428600876673531904)]} 0 4
[junit4:junit4] 2> 23829 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[1 (1428600876673531904)]} 0 11
[junit4:junit4] 2> 23834 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[2 (1428600876688211968)]} 0 2
[junit4:junit4] 2> 23850 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1428600876696600576)]} 0 4
[junit4:junit4] 2> 23851 T1642 C93 P59698 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1428600876696600576)]} 0 11
[junit4:junit4] 2> 23851 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[2]} 0 14
[junit4:junit4] 2> 23856 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[3 (1428600876711280640)]} 0 2
[junit4:junit4] 2> 23865 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1428600876715474944)]} 0 2
[junit4:junit4] 2> 23866 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[3 (1428600876715474944)]} 0 8
[junit4:junit4] 2> 23871 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[4 (1428600876727009280)]} 0 2
[junit4:junit4] 2> 23882 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1428600876734349312)]} 0 2
[junit4:junit4] 2> 23883 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1428600876734349312)]} 0 7
[junit4:junit4] 2> 23884 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[4]} 0 10
[junit4:junit4] 2> 23889 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[5 (1428600876745883648)]} 0 2
[junit4:junit4] 2> 23898 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1428600876751126528)]} 0 2
[junit4:junit4] 2> 23899 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[5 (1428600876751126528)]} 0 7
[junit4:junit4] 2> 23904 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[6 (1428600876761612288)]} 0 2
[junit4:junit4] 2> 23913 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1428600876766855168)]} 0 2
[junit4:junit4] 2> 23914 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[6 (1428600876766855168)]} 0 7
[junit4:junit4] 2> 23919 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[7 (1428600876777340928)]} 0 2
[junit4:junit4] 2> 23928 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1428600876782583808)]} 0 2
[junit4:junit4] 2> 23929 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[7 (1428600876782583808)]} 0 7
[junit4:junit4] 2> 23934 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[8 (1428600876793069568)]} 0 2
[junit4:junit4] 2> 23946 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1428600876801458176)]} 0 2
[junit4:junit4] 2> 23947 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1428600876801458176)]} 0 7
[junit4:junit4] 2> 23948 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[8]} 0 11
[junit4:junit4] 2> 23953 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[9 (1428600876812992512)]} 0 2
[junit4:junit4] 2> 23962 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1428600876818235392)]} 0 2
[junit4:junit4] 2> 23963 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[9 (1428600876818235392)]} 0 7
[junit4:junit4] 2> 23968 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[10 (1428600876828721152)]} 0 2
[junit4:junit4] 2> 23977 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1428600876833964032)]} 0 2
[junit4:junit4] 2> 23978 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[10 (1428600876833964032)]} 0 7
[junit4:junit4] 2> 23983 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[11 (1428600876844449792)]} 0 2
[junit4:junit4] 2> 23992 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1428600876849692672)]} 0 2
[junit4:junit4] 2> 23993 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[11 (1428600876849692672)]} 0 7
[junit4:junit4] 2> 23998 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[12 (1428600876860178432)]} 0 2
[junit4:junit4] 2> 24007 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1428600876865421312)]} 0 2
[junit4:junit4] 2> 24008 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[12 (1428600876865421312)]} 0 7
[junit4:junit4] 2> 24013 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[13 (1428600876875907072)]} 0 2
[junit4:junit4] 2> 24026 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1428600876884295680)]} 0 2
[junit4:junit4] 2> 24027 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1428600876884295680)]} 0 8
[junit4:junit4] 2> 24028 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[13]} 0 12
[junit4:junit4] 2> 24033 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[14 (1428600876896878592)]} 0 2
[junit4:junit4] 2> 24042 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1428600876902121472)]} 0 2
[junit4:junit4] 2> 24043 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[14 (1428600876902121472)]} 0 7
[junit4:junit4] 2> 24048 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[15 (1428600876912607232)]} 0 2
[junit4:junit4] 2> 24057 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1428600876917850112)]} 0 2
[junit4:junit4] 2> 24057 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[15 (1428600876917850112)]} 0 6
[junit4:junit4] 2> 24062 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[16 (1428600876927287296)]} 0 2
[junit4:junit4] 2> 24072 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1428600876932530176)]} 0 2
[junit4:junit4] 2> 24073 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[16 (1428600876932530176)]} 0 8
[junit4:junit4] 2> 24080 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[17 (1428600876945113088)]} 0 4
[junit4:junit4] 2> 24102 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1428600876957696000)]} 0 5
[junit4:junit4] 2> 24102 T1642 C93 P59698 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[17 (1428600876957696000)]} 0 14
[junit4:junit4] 2> 24103 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[17]} 0 19
[junit4:junit4] 2> 24108 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[100 (1428600876975521792)]} 0 2
[junit4:junit4] 2> 24119 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[100 (1428600876982861824)]} 0 2
[junit4:junit4] 2> 24119 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[100 (1428600876982861824)]} 0 6
[junit4:junit4] 2> 24120 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[100]} 0 10
[junit4:junit4] 2> 24125 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[101 (1428600876993347584)]} 0 2
[junit4:junit4] 2> 24134 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[101 (1428600876998590464)]} 0 2
[junit4:junit4] 2> 24134 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[101 (1428600876998590464)]} 0 6
[junit4:junit4] 2> 24138 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[102 (1428600877008027648)]} 0 1
[junit4:junit4] 2> 24147 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[102 (1428600877012221952)]} 0 2
[junit4:junit4] 2> 24147 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[102 (1428600877012221952)]} 0 6
[junit4:junit4] 2> 24152 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[103 (1428600877021659136)]} 0 2
[junit4:junit4] 2> 24162 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[103 (1428600877026902016)]} 0 2
[junit4:junit4] 2> 24162 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[103 (1428600877026902016)]} 0 7
[junit4:junit4] 2> 24168 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[104 (1428600877038436352)]} 0 2
[junit4:junit4] 2> 24177 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[104 (1428600877042630656)]} 0 2
[junit4:junit4] 2> 24178 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[104 (1428600877042630656)]} 0 8
[junit4:junit4] 2> 24183 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[105 (1428600877054164992)]} 0 2
[junit4:junit4] 2> 24195 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[105 (1428600877062553600)]} 0 2
[junit4:junit4] 2> 24195 T1642 C93 P59698 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[105 (1428600877062553600)]} 0 6
[junit4:junit4] 2> 24196 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[105]} 0 10
[junit4:junit4] 2> 24200 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[106 (1428600877073039360)]} 0 1
[junit4:junit4] 2> 24209 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[106 (1428600877077233664)]} 0 2
[junit4:junit4] 2> 24209 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[106 (1428600877077233664)]} 0 6
[junit4:junit4] 2> 24214 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[107 (1428600877086670848)]} 0 2
[junit4:junit4] 2> 24222 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[107 (1428600877090865152)]} 0 2
[junit4:junit4] 2> 24222 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[107 (1428600877090865152)]} 0 6
[junit4:junit4] 2> 24227 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[108 (1428600877100302336)]} 0 2
[junit4:junit4] 2> 24236 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[108 (1428600877105545216)]} 0 2
[junit4:junit4] 2> 24236 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[108 (1428600877105545216)]} 0 6
[junit4:junit4] 2> 24241 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[109 (1428600877114982400)]} 0 2
[junit4:junit4] 2> 24253 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[109 (1428600877123371008)]} 0 2
[junit4:junit4] 2> 24253 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[109 (1428600877123371008)]} 0 6
[junit4:junit4] 2> 24254 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[109]} 0 10
[junit4:junit4] 2> 24259 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[110 (1428600877133856768)]} 0 2
[junit4:junit4] 2> 24268 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[110 (1428600877139099648)]} 0 2
[junit4:junit4] 2> 24268 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[110 (1428600877139099648)]} 0 6
[junit4:junit4] 2> 24273 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[111 (1428600877148536832)]} 0 2
[junit4:junit4] 2> 24282 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[111 (1428600877153779712)]} 0 2
[junit4:junit4] 2> 24282 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[111 (1428600877153779712)]} 0 6
[junit4:junit4] 2> 24287 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[112 (1428600877163216896)]} 0 2
[junit4:junit4] 2> 24299 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[112 (1428600877171605504)]} 0 2
[junit4:junit4] 2> 24299 T1642 C93 P59698 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[112 (1428600877171605504)]} 0 6
[junit4:junit4] 2> 24300 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[112]} 0 10
[junit4:junit4] 2> 24305 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[113 (1428600877182091264)]} 0 2
[junit4:junit4] 2> 24316 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[113 (1428600877189431296)]} 0 2
[junit4:junit4] 2> 24316 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[113 (1428600877189431296)]} 0 6
[junit4:junit4] 2> 24317 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[113]} 0 10
[junit4:junit4] 2> 24322 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[114 (1428600877199917056)]} 0 2
[junit4:junit4] 2> 24332 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[114 (1428600877207257088)]} 0 1
[junit4:junit4] 2> 24333 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[114 (1428600877207257088)]} 0 6
[junit4:junit4] 2> 24334 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[114]} 0 10
[junit4:junit4] 2> 24338 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[115 (1428600877217742848)]} 0 1
[junit4:junit4] 2> 24347 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[115 (1428600877221937152)]} 0 2
[junit4:junit4] 2> 24347 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[115 (1428600877221937152)]} 0 6
[junit4:junit4] 2> 24352 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[116 (1428600877231374336)]} 0 2
[junit4:junit4] 2> 24360 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[116 (1428600877235568640)]} 0 2
[junit4:junit4] 2> 24360 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[116 (1428600877235568640)]} 0 6
[junit4:junit4] 2> 24365 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[117 (1428600877245005824)]} 0 2
[junit4:junit4] 2> 24376 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[117 (1428600877252345856)]} 0 2
[junit4:junit4] 2> 24376 T1642 C93 P59698 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[117 (1428600877252345856)]} 0 6
[junit4:junit4] 2> 24377 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[117]} 0 10
[junit4:junit4] 2> 24382 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[118 (1428600877262831616)]} 0 2
[junit4:junit4] 2> 24390 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[118 (1428600877267025920)]} 0 2
[junit4:junit4] 2> 24390 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[118 (1428600877267025920)]} 0 6
[junit4:junit4] 2> 24395 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[119 (1428600877276463104)]} 0 1
[junit4:junit4] 2> 24406 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[119 (1428600877283803136)]} 0 2
[junit4:junit4] 2> 24406 T1642 C93 P59698 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[119 (1428600877283803136)]} 0 6
[junit4:junit4] 2> 24407 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[119]} 0 10
[junit4:junit4] 2> 24412 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[120 (1428600877294288896)]} 0 2
[junit4:junit4] 2> 24423 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[120 (1428600877301628928)]} 0 2
[junit4:junit4] 2> 24424 T1642 C93 P59698 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[120 (1428600877301628928)]} 0 7
[junit4:junit4] 2> 24424 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[120]} 0 10
[junit4:junit4] 2> 24429 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[121 (1428600877312114688)]} 0 2
[junit4:junit4] 2> 24437 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[121 (1428600877316308992)]} 0 2
[junit4:junit4] 2> 24437 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[121 (1428600877316308992)]} 0 6
[junit4:junit4] 2> 24442 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[122 (1428600877325746176)]} 0 2
[junit4:junit4] 2> 24454 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[122 (1428600877334134784)]} 0 2
[junit4:junit4] 2> 24454 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[122 (1428600877334134784)]} 0 6
[junit4:junit4] 2> 24455 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[122]} 0 10
[junit4:junit4] 2> 24460 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[123 (1428600877344620544)]} 0 2
[junit4:junit4] 2> 24471 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[123 (1428600877351960576)]} 0 2
[junit4:junit4] 2> 24471 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[123 (1428600877351960576)]} 0 6
[junit4:junit4] 2> 24472 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[123]} 0 10
[junit4:junit4] 2> 24477 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[124 (1428600877362446336)]} 0 2
[junit4:junit4] 2> 24487 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[124 (1428600877368737792)]} 0 2
[junit4:junit4] 2> 24487 T1627 C92 P59693 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[124 (1428600877368737792)]} 0 6
[junit4:junit4] 2> 24488 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[124]} 0 10
[junit4:junit4] 2> 24493 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[125 (1428600877379223552)]} 0 2
[junit4:junit4] 2> 24501 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[125 (1428600877383417856)]} 0 2
[junit4:junit4] 2> 24501 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[125 (1428600877383417856)]} 0 6
[junit4:junit4] 2> 24506 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[126 (1428600877392855040)]} 0 2
[junit4:junit4] 2> 24514 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[126 (1428600877397049344)]} 0 2
[junit4:junit4] 2> 24514 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[126 (1428600877397049344)]} 0 6
[junit4:junit4] 2> 24519 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[127 (1428600877406486528)]} 0 2
[junit4:junit4] 2> 24527 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[127 (1428600877410680832)]} 0 2
[junit4:junit4] 2> 24527 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[127 (1428600877410680832)]} 0 6
[junit4:junit4] 2> 24532 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[128 (1428600877420118016)]} 0 2
[junit4:junit4] 2> 24543 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[128 (1428600877427458048)]} 0 2
[junit4:junit4] 2> 24543 T1642 C93 P59698 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[128 (1428600877427458048)]} 0 6
[junit4:junit4] 2> 24544 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[128]} 0 10
[junit4:junit4] 2> 24549 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[129 (1428600877437943808)]} 0 2
[junit4:junit4] 2> 24557 T1654 C90 P59701 /update {distrib.from=http://127.0.0.1:59693/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[129 (1428600877442138112)]} 0 2
[junit4:junit4] 2> 24557 T1626 C92 P59693 /update {wt=javabin&version=2} {add=[129 (1428600877442138112)]} 0 6
[junit4:junit4] 2> 24562 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[130 (1428600877451575296)]} 0 2
[junit4:junit4] 2> 24570 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[130 (1428600877455769600)]} 0 2
[junit4:junit4] 2> 24570 T1643 C93 P59698 /update {wt=javabin&version=2} {add=[130 (1428600877455769600)]} 0 6
[junit4:junit4] 2> 24574 T1602 C94 P59689 /update {wt=javabin&version=2} {add=[131 (1428600877465206784)]} 0 1
[junit4:junit4] 2> 24583 T1671 C91 P59705 /update {distrib.from=http://127.0.0.1:59698/collection1/&update.distrib=
[...truncated too long message...]
e$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 10) Thread[id=1652, name=HashSessionScavenger-52, state=TIMED_WAITING, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] 2> at java.lang.Object.wait(Native Method)
[junit4:junit4] 2> at java.util.TimerThread.mainLoop(Timer.java:552)
[junit4:junit4] 2> at java.util.TimerThread.run(Timer.java:505)
[junit4:junit4] 2> 11) Thread[id=1653, name=qtp1168228197-1653 Acceptor0 SocketConnector@127.0.0.1:59701, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] 2> at java.net.PlainSocketImpl.socketAccept(Native Method)
[junit4:junit4] 2> at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:398)
[junit4:junit4] 2> at java.net.ServerSocket.implAccept(ServerSocket.java:522)
[junit4:junit4] 2> at java.net.ServerSocket.accept(ServerSocket.java:490)
[junit4:junit4] 2> at org.eclipse.jetty.server.bio.SocketConnector.accept(SocketConnector.java:117)
[junit4:junit4] 2> at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:938)
[junit4:junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 12) Thread[id=1745, name=qtp2117968044-1745, state=RUNNABLE, group=TGRP-BasicDistributedZkTest]
[junit4:junit4] 2> at java.net.SocketInputStream.socketRead0(Native Method)
[junit4:junit4] 2> at java.net.SocketInputStream.read(SocketInputStream.java:150)
[junit4:junit4] 2> at java.net.SocketInputStream.read(SocketInputStream.java:121)
[junit4:junit4] 2> at org.eclipse.jetty.io.ByteArrayBuffer.readFrom(ByteArrayBuffer.java:375)
[junit4:junit4] 2> at org.eclipse.jetty.io.bio.StreamEndPoint.fill(StreamEndPoint.java:141)
[junit4:junit4] 2> at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.fill(SocketConnector.java:227)
[junit4:junit4] 2> at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:1035)
[junit4:junit4] 2> at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:280)
[junit4:junit4] 2> at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
[junit4:junit4] 2> at org.eclipse.jetty.server.BlockingHttpConnection.handle(BlockingHttpConnection.java:72)
[junit4:junit4] 2> at org.eclipse.jetty.server.bio.SocketConnector$ConnectorEndPoint.run(SocketConnector.java:264)
[junit4:junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
[junit4:junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {foo_b=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80), n_f1=PostingsFormat(name=NestedPulsing), cat=PostingsFormat(name=SimpleText), foo_d=PostingsFormat(name=TestBloomFilteredLucene41Postings), foo_f=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80), n_tl1=PostingsFormat(name=NestedPulsing), n_d1=PostingsFormat(name=SimpleText), rnd_b=PostingsFormat(name=TestBloomFilteredLucene41Postings), intDefault=PostingsFormat(name=SimpleText), n_td1=PostingsFormat(name=NestedPulsing), timestamp=PostingsFormat(name=SimpleText), id=PostingsFormat(name=TestBloomFilteredLucene41Postings), range_facet_sl=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80), range_facet_si=PostingsFormat(name=NestedPulsing), oddField_s=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80), sequence_i=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80), name=PostingsFormat(name=TestBloomFilteredLucene41Postings), foo_i=PostingsFormat(name=NestedPulsing), regex_dup_B_s=PostingsFormat(name=SimpleText), multiDefault=PostingsFormat(name=NestedPulsing), n_tf1=PostingsFormat(name=SimpleText), n_dt1=PostingsFormat(name=NestedPulsing), genre_s=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80), author_t=PostingsFormat(name=NestedPulsing), n_ti1=PostingsFormat(name=TestBloomFilteredLucene41Postings), range_facet_l=PostingsFormat(name=SimpleText), text=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80), _version_=PostingsFormat(name=SimpleText), val_i=PostingsFormat(name=TestBloomFilteredLucene41Postings), SubjectTerms_mfacet=PostingsFormat(name=SimpleText), series_t=PostingsFormat(name=NestedPulsing), a_t=PostingsFormat(name=SimpleText), n_tdt1=PostingsFormat(name=SimpleText), regex_dup_A_s=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80), price=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80), other_tl1=PostingsFormat(name=SimpleText), n_l1=PostingsFormat(name=SimpleText), a_si=PostingsFormat(name=NestedPulsing), inStock=Pulsing41(freqCutoff=5 minBlockSize=18 maxBlockSize=80)}, docValues:{timestamp=DocValuesFormat(name=SimpleText)}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=de_LU, timezone=America/Port_of_Spain
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_09 (64-bit)/cpus=16,threads=16,free=277666712,total=536870912
[junit4:junit4] 2> NOTE: All tests run in this JVM: [DocValuesTest, TestFaceting, TestSearchPerf, OverseerTest, LegacyHTMLStripCharFilterTest, TestPseudoReturnFields, TestReplicationHandler, TestSolrQueryParser, QueryParsingTest, SolrIndexSplitterTest, TestPerFieldSimilarity, TestPluginEnable, MBeansHandlerTest, TestReversedWildcardFilterFactory, SpellingQueryConverterTest, WordBreakSolrSpellCheckerTest, DocumentBuilderTest, TestFunctionQuery, SuggesterTest, SoftAutoCommitTest, SystemInfoHandlerTest, TestPhraseSuggestions, TestDocSet, SliceStateUpdateTest, SimpleFacetsTest, UnloadDistributedZkTest, RAMDirectoryFactoryTest, SpatialFilterTest, TestConfig, TestSort, TestSolrDeletionPolicy1, ReturnFieldsTest, TestPHPSerializedResponseWriter, BadComponentTest, CSVRequestHandlerTest, BinaryUpdateRequestHandlerTest, ChaosMonkeyNothingIsSafeTest, LoggingHandlerTest, DirectSolrConnectionTest, OverseerCollectionProcessorTest, SynonymTokenizerTest, ShowFileRequestHandlerTest, QueryElevationComponentTest, PolyFieldTest, TestFastLRUCache, SliceStateTest, ExternalFileFieldSortTest, FileBasedSpellCheckerTest, PeerSyncTest, AutoCommitTest, MoreLikeThisHandlerTest, SchemaVersionSpecificBehaviorTest, TestIBSimilarityFactory, BasicDistributedZkTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=BasicDistributedZkTest -Dtests.seed=99E9FD5446A87955 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=de_LU -Dtests.timezone=America/Port_of_Spain -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 0.00s J0 | BasicDistributedZkTest (suite) <<<
[junit4:junit4] > Throwable #1: java.lang.Exception: Suite timeout exceeded (>= 7200000 msec).
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([99E9FD5446A87955]:0)
[junit4:junit4] Completed on J0 in 7223.39s, 1 test, 2 errors <<< FAILURES!
[...truncated 41 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:381: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:361: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build.xml:183: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/common-build.xml:449: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:1213: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:877: There were test failures: 261 suites, 1101 tests, 1 suite-level error, 1 error, 58 ignored (8 assumptions)
Total time: 156 minutes 11 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure